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/rand438.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand438.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand438.cudf.user-upgrades.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.08 1.06 1.01 4/35 20125
/proc/meminfo: memFree=482840/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=3712 CPUtime=0.01
/proc/20125/stat : 20125 (packup) R 20124 20124 1511 34817 1511 4202496 405 0 0 0 1 0 0 0 25 0 1 0 4589377 3801088 334 1283457024 134512640 134752139 4288764944 18446744073709551615 134681608 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20125/statm: 928 334 286 59 0 92 0

[startup+0.153697 s]
/proc/loadavg: 1.08 1.06 1.01 4/35 20125
/proc/meminfo: memFree=482840/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=8480 CPUtime=0.15
/proc/20125/stat : 20125 (packup) R 20124 20124 1511 34817 1511 4202496 1614 0 0 0 14 1 0 0 25 0 1 0 4589377 8683520 1543 1283457024 134512640 134752139 4288764944 18446744073709551615 4157819986 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20125/statm: 2120 1543 286 59 0 1284 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 11048

[startup+0.203701 s]
/proc/loadavg: 1.08 1.06 1.01 4/35 20125
/proc/meminfo: memFree=482840/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=9932 CPUtime=0.21
/proc/20125/stat : 20125 (packup) R 20124 20124 1511 34817 1511 4202496 1969 0 0 0 20 1 0 0 25 0 1 0 4589377 10170368 1898 1283457024 134512640 134752139 4288764944 18446744073709551615 4157832780 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20125/statm: 2483 1898 286 59 0 1647 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12500

[startup+0.313718 s]
/proc/loadavg: 1.08 1.06 1.01 4/35 20125
/proc/meminfo: memFree=482840/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=12860 CPUtime=0.31
/proc/20125/stat : 20125 (packup) R 20124 20124 1511 34817 1511 4202496 2696 0 0 0 28 3 0 0 25 0 1 0 4589377 13168640 2625 1283457024 134512640 134752139 4288764944 18446744073709551615 134706007 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20125/statm: 3215 2625 286 59 0 2379 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15428

[startup+0.713763 s]
/proc/loadavg: 1.08 1.06 1.01 4/35 20125
/proc/meminfo: memFree=482840/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=22048 CPUtime=0.71
/proc/20125/stat : 20125 (packup) R 20124 20124 1511 34817 1511 4202496 4989 0 0 0 68 3 0 0 25 0 1 0 4589377 22577152 4918 1283457024 134512640 134752139 4288764944 18446744073709551615 134681753 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20125/statm: 5512 4918 286 59 0 4676 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 24616

[startup+1.51385 s]
/proc/loadavg: 1.08 1.06 1.01 2/36 20126
/proc/meminfo: memFree=456044/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=46088 CPUtime=1.51
/proc/20125/stat : 20125 (packup) R 20124 20124 1511 34817 1511 4202496 11091 0 0 0 143 8 0 0 25 0 1 0 4589377 47194112 10828 1283457024 134512640 134752139 4288764944 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20125/statm: 11522 10828 322 59 0 10686 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 48656

[startup+3.10406 s]
/proc/loadavg: 1.08 1.06 1.01 2/38 20128
/proc/meminfo: memFree=428484/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=46092 CPUtime=3.02
/proc/20125/stat : 20125 (packup) S 20124 20124 1511 34817 1511 4202496 11165 8188 0 0 168 24 98 12 18 0 1 0 4589377 47198208 10846 1283457024 134512640 134752139 4288764944 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20125/statm: 11523 10846 333 59 0 10687 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 48660

[startup+6.30452 s]
/proc/loadavg: 1.08 1.06 1.01 2/38 20132
/proc/meminfo: memFree=428856/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=46096 CPUtime=5.05
/proc/20125/stat : 20125 (packup) S 20124 20124 1511 34817 1511 4202496 11239 23550 0 0 178 34 267 26 18 0 1 0 4589377 47202304 10852 1283457024 134512640 134752139 4288764944 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20125/statm: 11524 10852 333 59 0 10688 0
[pid=20131] ppid=20125 vsize=1672 CPUtime=0
/proc/20131/stat : 20131 (sh) S 20125 20124 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4589885 1712128 124 1283457024 134512640 134593992 4290713232 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20131/statm: 418 124 108 20 0 45 0
[pid=20132] ppid=20131 vsize=45100 CPUtime=1.23
/proc/20132/stat : 20132 (minisatp_32) R 20131 20124 1511 34817 1511 4202496 12623 0 0 0 111 12 0 0 24 0 1 0 4589886 46182400 9934 1283457024 134512640 135413687 4287333248 18446744073709551615 134686593 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20132/statm: 11275 9934 94 220 0 11053 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 95436

[startup+12.7064 s]
/proc/loadavg: 1.07 1.05 1.01 2/38 20134
/proc/meminfo: memFree=333632/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=46100 CPUtime=8
/proc/20125/stat : 20125 (packup) S 20124 20124 1511 34817 1511 4202496 11303 47612 0 0 190 46 517 47 18 0 1 0 4589377 47206400 10853 1283457024 134512640 134752139 4288764944 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20125/statm: 11525 10853 333 59 0 10689 0
[pid=20133] ppid=20125 vsize=1668 CPUtime=0
/proc/20133/stat : 20133 (sh) S 20125 20124 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4590179 1708032 123 1283457024 134512640 134593992 4293826960 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20133/statm: 417 123 108 20 0 44 0
[pid=20134] ppid=20133 vsize=122068 CPUtime=4.68
/proc/20134/stat : 20134 (minisatp_32) R 20133 20124 1511 34817 1511 4202496 39961 0 0 0 428 40 0 0 25 0 1 0 4590179 124997632 26344 1283457024 134512640 135413687 4287277936 18446744073709551615 134653643 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20134/statm: 30517 26344 107 220 0 30295 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 172404

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

[startup+12.8064 s]
/proc/loadavg: 1.07 1.05 1.01 2/38 20134
/proc/meminfo: memFree=333632/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=46100 CPUtime=8
/proc/20125/stat : 20125 (packup) S 20124 20124 1511 34817 1511 4202496 11303 47612 0 0 190 46 517 47 18 0 1 0 4589377 47206400 10853 1283457024 134512640 134752139 4288764944 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20125/statm: 11525 10853 333 59 0 10689 0
[pid=20133] ppid=20125 vsize=1668 CPUtime=0
/proc/20133/stat : 20133 (sh) S 20125 20124 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4590179 1708032 123 1283457024 134512640 134593992 4293826960 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20133/statm: 417 123 108 20 0 44 0
[pid=20134] ppid=20133 vsize=122068 CPUtime=4.78
/proc/20134/stat : 20134 (minisatp_32) R 20133 20124 1511 34817 1511 4202496 39961 0 0 0 438 40 0 0 25 0 1 0 4590179 124997632 26344 1283457024 134512640 135413687 4287277936 18446744073709551615 134961351 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20134/statm: 30517 26344 107 220 0 30295 0
Current children cumulated CPU time (s) 12.78
Current children cumulated vsize (KiB) 172404

[startup+13.2065 s]
/proc/loadavg: 1.07 1.05 1.01 2/38 20134
/proc/meminfo: memFree=332640/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=46100 CPUtime=8
/proc/20125/stat : 20125 (packup) S 20124 20124 1511 34817 1511 4202496 11303 47612 0 0 190 46 517 47 18 0 1 0 4589377 47206400 10853 1283457024 134512640 134752139 4288764944 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20125/statm: 11525 10853 333 59 0 10689 0
[pid=20133] ppid=20125 vsize=1668 CPUtime=0
/proc/20133/stat : 20133 (sh) S 20125 20124 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4590179 1708032 123 1283457024 134512640 134593992 4293826960 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20133/statm: 417 123 108 20 0 44 0
[pid=20134] ppid=20133 vsize=122808 CPUtime=5.18
/proc/20134/stat : 20134 (minisatp_32) R 20133 20124 1511 34817 1511 4202496 40074 0 0 0 478 40 0 0 25 0 1 0 4590179 125755392 26454 1283457024 134512640 135413687 4287277936 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20134/statm: 30702 26454 107 220 0 30480 0
Current children cumulated CPU time (s) 13.18
Current children cumulated vsize (KiB) 173144

[startup+13.6066 s]
/proc/loadavg: 1.07 1.05 1.01 2/38 20134
/proc/meminfo: memFree=332640/1048576 swapFree=0/0
[pid=20124] ppid=20123 vsize=2568 CPUtime=0
/proc/20124/stat : 20124 (packup2mp4tr-0.) S 20123 20124 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 18 0 1 0 4589377 2629632 274 1283457024 134512640 135304128 4294048080 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20124/statm: 642 274 233 194 0 29 0
[pid=20125] ppid=20124 vsize=45328 CPUtime=13.58
/proc/20125/stat : 20125 (packup) R 20124 20124 1511 34817 1511 4202496 18312 87905 0 0 194 47 1029 88 18 0 1 0 4589377 46415872 10673 1283457024 134512640 134752139 4288764944 18446744073709551615 4157801783 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20125/statm: 11332 10673 346 59 0 10496 0
Current children cumulated CPU time (s) 13.58
Current children cumulated vsize (KiB) 47896

Child status: 0
Real time (s): 13.6651
CPU time (s): 13.6489
CPU user time (s): 12.2688
CPU system time (s): 1.38009
CPU usage (%): 99.881
Max. virtual memory (cumulated for all children) (KiB): 183152

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.2688
system time used= 1.38009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 109702
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= 20
involuntary context switches= 228

runsolver used 0 second user time and 0 second system time

The end