runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf.dudf-real.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.47 1.25 1.14 4/34 935
/proc/meminfo: memFree=284336/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=3712 CPUtime=0.01
/proc/935/stat : 935 (packup) R 934 934 1511 34817 1511 4202496 404 0 0 0 1 0 0 0 25 0 1 0 5139536 3801088 333 1283457024 134512640 134752139 4291587728 18446744073709551615 134681676 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/935/statm: 928 333 286 59 0 92 0

[startup+0.153615 s]
/proc/loadavg: 1.47 1.25 1.14 4/34 935
/proc/meminfo: memFree=284336/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=8820 CPUtime=0.15
/proc/935/stat : 935 (packup) R 934 934 1511 34817 1511 4202496 1694 0 0 0 14 1 0 0 25 0 1 0 5139536 9031680 1623 1283457024 134512640 134752139 4291587728 18446744073709551615 134708546 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/935/statm: 2205 1623 286 59 0 1369 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 11392

[startup+0.203621 s]
/proc/loadavg: 1.47 1.25 1.14 4/34 935
/proc/meminfo: memFree=284336/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=10272 CPUtime=0.21
/proc/935/stat : 935 (packup) R 934 934 1511 34817 1511 4202496 2064 0 0 0 20 1 0 0 25 0 1 0 5139536 10518528 1993 1283457024 134512640 134752139 4291587728 18446744073709551615 4157860943 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/935/statm: 2568 1993 286 59 0 1732 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12844

[startup+0.313637 s]
/proc/loadavg: 1.47 1.25 1.14 4/34 935
/proc/meminfo: memFree=284336/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=13372 CPUtime=0.31
/proc/935/stat : 935 (packup) R 934 934 1511 34817 1511 4202496 2821 0 0 0 30 1 0 0 25 0 1 0 5139536 13692928 2750 1283457024 134512640 134752139 4291587728 18446744073709551615 134681839 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/935/statm: 3343 2750 286 59 0 2507 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15944

[startup+0.713708 s]
/proc/loadavg: 1.47 1.25 1.14 4/34 935
/proc/meminfo: memFree=284336/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=23480 CPUtime=0.71
/proc/935/stat : 935 (packup) R 934 934 1511 34817 1511 4202496 5370 0 0 0 70 1 0 0 25 0 1 0 5139536 24043520 5299 1283457024 134512640 134752139 4291587728 18446744073709551615 134681751 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/935/statm: 5870 5299 286 59 0 5034 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 26052

[startup+1.514 s]
/proc/loadavg: 1.47 1.25 1.14 2/35 936
/proc/meminfo: memFree=251960/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=35372 CPUtime=1.14
/proc/935/stat : 935 (packup) S 934 934 1511 34817 1511 4202496 8374 0 0 0 103 11 0 0 25 0 1 0 5139536 36220928 8184 1283457024 134512640 134752139 4291587728 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/935/statm: 8843 8184 324 59 0 8007 0
Current children cumulated CPU time (s) 1.14
Current children cumulated vsize (KiB) 37944

[startup+3.10434 s]
/proc/loadavg: 1.47 1.25 1.14 2/37 938
/proc/meminfo: memFree=210884/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=35376 CPUtime=3.09
/proc/935/stat : 935 (packup) R 934 934 1511 34817 1511 4202496 8439 18689 0 0 114 16 165 14 18 0 1 0 5139536 36225024 8196 1283457024 134512640 134752139 4291587728 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/935/statm: 8844 8196 332 59 0 8008 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 37948

[startup+6.30539 s]
/proc/loadavg: 1.51 1.27 1.15 2/39 944
/proc/meminfo: memFree=223012/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=35384 CPUtime=6.12
/proc/935/stat : 935 (packup) S 934 934 1511 34817 1511 4202496 8568 41618 0 0 127 43 406 36 18 0 1 0 5139536 36233216 8204 1283457024 134512640 134752139 4291587728 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/935/statm: 8846 8204 332 59 0 8010 0
Current children cumulated CPU time (s) 6.12
Current children cumulated vsize (KiB) 37956

Solver just ended. Dumping a history of the last processes samples

[startup+6.40541 s]
/proc/loadavg: 1.51 1.27 1.15 2/39 944
/proc/meminfo: memFree=223012/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=35384 CPUtime=6.12
/proc/935/stat : 935 (packup) S 934 934 1511 34817 1511 4202496 8568 41618 0 0 127 43 406 36 18 0 1 0 5139536 36233216 8204 1283457024 134512640 134752139 4291587728 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/935/statm: 8846 8204 332 59 0 8010 0
Current children cumulated CPU time (s) 6.12
Current children cumulated vsize (KiB) 37956

[startup+7.2056 s]
/proc/loadavg: 1.51 1.27 1.15 2/39 946
/proc/meminfo: memFree=240868/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=35384 CPUtime=6.12
/proc/935/stat : 935 (packup) S 934 934 1511 34817 1511 4202496 8568 41618 0 0 127 43 406 36 18 0 1 0 5139536 36233216 8204 1283457024 134512640 134752139 4291587728 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/935/statm: 8846 8204 332 59 0 8010 0
[pid=945] ppid=935 vsize=1668 CPUtime=0
/proc/945/stat : 945 (sh) S 935 934 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 5140148 1708032 123 1283457024 134512640 134593992 4289121552 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/945/statm: 417 123 108 20 0 44 0
[pid=946] ppid=945 vsize=33508 CPUtime=1.07
/proc/946/stat : 946 (minisatp_32) R 945 934 1511 34817 1511 4202496 10081 0 0 0 96 11 0 0 24 0 1 0 5140149 34312192 7395 1283457024 134512640 135413687 4288185424 18446744073709551615 134688878 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/946/statm: 8377 7395 94 220 0 8155 0
Current children cumulated CPU time (s) 7.19
Current children cumulated vsize (KiB) 73132

[startup+7.60572 s]
/proc/loadavg: 1.51 1.27 1.15 2/39 946
/proc/meminfo: memFree=240868/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=35384 CPUtime=6.12
/proc/935/stat : 935 (packup) S 934 934 1511 34817 1511 4202496 8568 41618 0 0 127 43 406 36 18 0 1 0 5139536 36233216 8204 1283457024 134512640 134752139 4291587728 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/935/statm: 8846 8204 332 59 0 8010 0
[pid=945] ppid=935 vsize=1668 CPUtime=0
/proc/945/stat : 945 (sh) S 935 934 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 5140148 1708032 123 1283457024 134512640 134593992 4289121552 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/945/statm: 417 123 108 20 0 44 0
[pid=946] ppid=945 vsize=42020 CPUtime=1.47
/proc/946/stat : 946 (minisatp_32) R 945 934 1511 34817 1511 4202496 13969 0 0 0 131 16 0 0 25 0 1 0 5140149 43028480 9593 1283457024 134512640 135413687 4288185424 18446744073709551615 134691800 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/946/statm: 10505 9593 107 220 0 10283 0
Current children cumulated CPU time (s) 7.59
Current children cumulated vsize (KiB) 81644

[startup+7.70574 s]
/proc/loadavg: 1.51 1.27 1.15 2/37 946
/proc/meminfo: memFree=251812/1048576 swapFree=0/0
[pid=934] ppid=933 vsize=2572 CPUtime=0
/proc/934/stat : 934 (packup2mp4tr-0.) S 933 934 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 5139536 2633728 275 1283457024 134512640 135304128 4291094080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/934/statm: 643 275 233 194 0 30 0
[pid=935] ppid=934 vsize=34996 CPUtime=7.69
/proc/935/stat : 935 (packup) R 934 934 1511 34817 1511 4202496 15535 56046 0 0 131 46 540 52 18 0 1 0 5139536 35835904 8120 1283457024 134512640 134752139 4291587728 18446744073709551615 134622887 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/935/statm: 8749 8120 345 59 0 7913 0
Current children cumulated CPU time (s) 7.69
Current children cumulated vsize (KiB) 37568

Child status: 0
Real time (s): 7.75455
CPU time (s): 7.74848
CPU user time (s): 6.76042
CPU system time (s): 0.988061
CPU usage (%): 99.9218
Max. virtual memory (cumulated for all children) (KiB): 100128

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.76042
system time used= 0.988061
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 72528
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 19
involuntary context switches= 152

runsolver used 0 second user time and 0 second system time

The end