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/201108251442/packup2mp4pa-0.6/rand285.cudf.s-e-l.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/incremental/s-e-l/rand285.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand285.cudf.s-e-l.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.18 1.07 1.04 4/34 9952
/proc/meminfo: memFree=372772/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=3716 CPUtime=0.01
/proc/9952/stat : 9952 (packup) R 9951 9951 4778 34817 4778 4202496 406 0 0 0 1 0 0 0 25 0 1 0 10431372 3805184 335 1283457024 134512640 134752139 4293277792 18446744073709551615 134681812 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9952/statm: 929 335 286 59 0 93 0

[startup+0.193703 s]
/proc/loadavg: 1.18 1.07 1.04 4/34 9952
/proc/meminfo: memFree=372772/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=10844 CPUtime=0.2
/proc/9952/stat : 9952 (packup) R 9951 9951 4778 34817 4778 4202496 2196 0 0 0 20 0 0 0 25 0 1 0 10431372 11104256 2125 1283457024 134512640 134752139 4293277792 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9952/statm: 2711 2125 286 59 0 1875 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13416

[startup+0.203699 s]
/proc/loadavg: 1.18 1.07 1.04 4/34 9952
/proc/meminfo: memFree=372772/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=11108 CPUtime=0.21
/proc/9952/stat : 9952 (packup) R 9951 9951 4778 34817 4778 4202496 2273 0 0 0 21 0 0 0 25 0 1 0 10431372 11374592 2202 1283457024 134512640 134752139 4293277792 18446744073709551615 134681765 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9952/statm: 2777 2202 286 59 0 1941 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13680

[startup+0.313734 s]
/proc/loadavg: 1.18 1.07 1.04 4/34 9952
/proc/meminfo: memFree=372772/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=14540 CPUtime=0.32
/proc/9952/stat : 9952 (packup) R 9951 9951 4778 34817 4778 4202496 3140 0 0 0 32 0 0 0 25 0 1 0 10431372 14888960 3069 1283457024 134512640 134752139 4293277792 18446744073709551615 134681798 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9952/statm: 3635 3069 286 59 0 2799 0
Current children cumulated CPU time (s) 0.32
Current children cumulated vsize (KiB) 17112

[startup+0.713795 s]
/proc/loadavg: 1.18 1.07 1.04 4/34 9952
/proc/meminfo: memFree=372772/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=25428 CPUtime=0.71
/proc/9952/stat : 9952 (packup) R 9951 9951 4778 34817 4778 4202496 5839 0 0 0 71 0 0 0 25 0 1 0 10431372 26038272 5768 1283457024 134512640 134752139 4293277792 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9952/statm: 6357 5768 286 59 0 5521 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 28000

[startup+1.50404 s]
/proc/loadavg: 1.18 1.07 1.04 2/35 9953
/proc/meminfo: memFree=336552/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=39560 CPUtime=1.22
/proc/9952/stat : 9952 (packup) S 9951 9951 4778 34817 4778 4202496 9531 0 0 0 106 16 0 0 25 0 1 0 10431372 40509440 9212 1283457024 134512640 134752139 4293277792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9952/statm: 9890 9212 324 59 0 9054 0
Current children cumulated CPU time (s) 1.22
Current children cumulated vsize (KiB) 42132

[startup+3.10446 s]
/proc/loadavg: 1.18 1.07 1.04 2/37 9955
/proc/meminfo: memFree=315688/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=39564 CPUtime=2.99
/proc/9952/stat : 9952 (packup) S 9951 9951 4778 34817 4778 4202496 9586 11107 0 0 120 24 140 15 18 0 1 0 10431372 40513536 9221 1283457024 134512640 134752139 4293277792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9952/statm: 9891 9221 332 59 0 9055 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 42136

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

[startup+3.20448 s]
/proc/loadavg: 1.18 1.07 1.04 2/37 9955
/proc/meminfo: memFree=315688/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=39564 CPUtime=2.99
/proc/9952/stat : 9952 (packup) S 9951 9951 4778 34817 4778 4202496 9586 11107 0 0 120 24 140 15 18 0 1 0 10431372 40513536 9221 1283457024 134512640 134752139 4293277792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9952/statm: 9891 9221 332 59 0 9055 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 42136

[startup+4.80486 s]
/proc/loadavg: 1.17 1.07 1.04 2/37 9957
/proc/meminfo: memFree=300312/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=39564 CPUtime=2.99
/proc/9952/stat : 9952 (packup) S 9951 9951 4778 34817 4778 4202496 9586 11107 0 0 120 24 140 15 18 0 1 0 10431372 40513536 9221 1283457024 134512640 134752139 4293277792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9952/statm: 9891 9221 332 59 0 9055 0
[pid=9956] ppid=9952 vsize=1672 CPUtime=0
/proc/9956/stat : 9956 (sh) S 9952 9951 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10431673 1712128 124 1283457024 134512640 134593992 4292532304 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9956/statm: 418 124 108 20 0 45 0
[pid=9957] ppid=9956 vsize=67216 CPUtime=1.78
/proc/9957/stat : 9957 (minisatp_32) R 9956 9951 4778 34817 4778 4202496 19982 0 0 0 153 25 0 0 25 0 1 0 10431673 68829184 15370 1283457024 134512640 135413687 4290098720 18446744073709551615 134686203 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9957/statm: 16804 15370 107 220 0 16582 0
Current children cumulated CPU time (s) 4.77
Current children cumulated vsize (KiB) 111024

[startup+5.60505 s]
/proc/loadavg: 1.17 1.07 1.04 2/37 9957
/proc/meminfo: memFree=271180/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=39564 CPUtime=2.99
/proc/9952/stat : 9952 (packup) S 9951 9951 4778 34817 4778 4202496 9586 11107 0 0 120 24 140 15 18 0 1 0 10431372 40513536 9221 1283457024 134512640 134752139 4293277792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9952/statm: 9891 9221 332 59 0 9055 0
[pid=9956] ppid=9952 vsize=1672 CPUtime=0
/proc/9956/stat : 9956 (sh) S 9952 9951 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10431673 1712128 124 1283457024 134512640 134593992 4292532304 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9956/statm: 418 124 108 20 0 45 0
[pid=9957] ppid=9956 vsize=71548 CPUtime=2.58
/proc/9957/stat : 9957 (minisatp_32) R 9956 9951 4778 34817 4778 4202496 22707 0 0 0 232 26 0 0 25 0 1 0 10431673 73265152 16074 1283457024 134512640 135413687 4290098720 18446744073709551615 134628616 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9957/statm: 17887 16074 107 220 0 17665 0
Current children cumulated CPU time (s) 5.57
Current children cumulated vsize (KiB) 115356

[startup+5.80528 s]
/proc/loadavg: 1.17 1.07 1.04 2/37 9957
/proc/meminfo: memFree=271180/1048576 swapFree=0/0
[pid=9951] ppid=9950 vsize=2572 CPUtime=0
/proc/9951/stat : 9951 (packup2mp4pa-0.) S 9950 9951 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10431372 2633728 273 1283457024 134512640 135304128 4290125200 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9951/statm: 643 273 233 194 0 30 0
[pid=9952] ppid=9951 vsize=36284 CPUtime=5.78
/proc/9952/stat : 9952 (packup) R 9951 9951 4778 34817 4778 4202496 17580 34067 0 0 126 26 384 42 18 0 1 0 10431372 37154816 8564 1283457024 134512640 134752139 4293277792 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9952/statm: 9071 8564 345 59 0 8235 0
Current children cumulated CPU time (s) 5.78
Current children cumulated vsize (KiB) 38856

Child status: 0
Real time (s): 5.81907
CPU time (s): 5.81236
CPU user time (s): 5.10832
CPU system time (s): 0.704044
CPU usage (%): 99.8848
Max. virtual memory (cumulated for all children) (KiB): 123212

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.10832
system time used= 0.704044
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 52431
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= 12
involuntary context switches= 109

runsolver used 0 second user time and 0 second system time

The end