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/rand172.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand172.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand172.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.07 1.03 1.00 4/34 7074
/proc/meminfo: memFree=654228/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=3712 CPUtime=0
/proc/7074/stat : 7074 (packup) R 7073 7073 1511 34817 1511 4202496 402 0 0 0 0 0 0 0 25 0 1 0 1746870 3801088 331 1283457024 134512640 134752139 4292814832 18446744073709551615 134681499 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/7074/statm: 928 331 286 59 0 92 0

[startup+0.113472 s]
/proc/loadavg: 1.07 1.03 1.00 4/34 7074
/proc/meminfo: memFree=654228/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=7292 CPUtime=0.12
/proc/7074/stat : 7074 (packup) R 7073 7073 1511 34817 1511 4202496 1318 0 0 0 12 0 0 0 25 0 1 0 1746870 7467008 1247 1283457024 134512640 134752139 4292814832 18446744073709551615 134681798 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/7074/statm: 1823 1247 286 59 0 987 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 9864

[startup+0.203488 s]
/proc/loadavg: 1.07 1.03 1.00 4/34 7074
/proc/meminfo: memFree=654228/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=9932 CPUtime=0.2
/proc/7074/stat : 7074 (packup) R 7073 7073 1511 34817 1511 4202496 1965 0 0 0 19 1 0 0 25 0 1 0 1746870 10170368 1894 1283457024 134512640 134752139 4292814832 18446744073709551615 134681645 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/7074/statm: 2483 1894 286 59 0 1647 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12504

[startup+0.313513 s]
/proc/loadavg: 1.07 1.03 1.00 4/34 7074
/proc/meminfo: memFree=654228/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=12860 CPUtime=0.31
/proc/7074/stat : 7074 (packup) R 7073 7073 1511 34817 1511 4202496 2689 0 0 0 30 1 0 0 25 0 1 0 1746870 13168640 2618 1283457024 134512640 134752139 4292814832 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/7074/statm: 3215 2618 286 59 0 2379 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15432

[startup+0.713599 s]
/proc/loadavg: 1.07 1.03 1.00 4/34 7074
/proc/meminfo: memFree=654228/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=21916 CPUtime=0.71
/proc/7074/stat : 7074 (packup) R 7073 7073 1511 34817 1511 4202496 4974 0 0 0 69 2 0 0 25 0 1 0 1746870 22441984 4903 1283457024 134512640 134752139 4292814832 18446744073709551615 134681833 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/7074/statm: 5479 4903 286 59 0 4643 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 24488

[startup+1.51378 s]
/proc/loadavg: 1.07 1.03 1.00 2/35 7075
/proc/meminfo: memFree=627556/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46264 CPUtime=1.51
/proc/7074/stat : 7074 (packup) R 7073 7073 1511 34817 1511 4202496 10961 0 0 0 147 4 0 0 25 0 1 0 1746870 47374336 10841 1283457024 134512640 134752139 4292814832 18446744073709551615 134664374 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/7074/statm: 11566 10841 320 59 0 10730 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 48836

[startup+3.10477 s]
/proc/loadavg: 1.07 1.03 1.00 2/37 7077
/proc/meminfo: memFree=599996/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46092 CPUtime=3.01
/proc/7074/stat : 7074 (packup) S 7073 7073 1511 34817 1511 4202496 11167 8073 0 0 166 26 95 14 18 0 1 0 1746870 47198208 10846 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/7074/statm: 11523 10846 333 59 0 10687 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 48664

[startup+6.3055 s]
/proc/loadavg: 1.07 1.03 1.00 2/37 7081
/proc/meminfo: memFree=591316/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46096 CPUtime=4.57
/proc/7074/stat : 7074 (packup) S 7073 7073 1511 34817 1511 4202496 11245 20361 0 0 178 36 215 28 18 0 1 0 1746870 47202304 10852 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/7074/statm: 11524 10852 333 59 0 10688 0
[pid=7080] ppid=7074 vsize=1672 CPUtime=0
/proc/7080/stat : 7080 (sh) S 7074 7073 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 1747329 1712128 123 1283457024 134512640 134593992 4288162848 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/7080/statm: 418 123 108 20 0 45 0
[pid=7081] ppid=7080 vsize=45796 CPUtime=1.71
/proc/7081/stat : 7081 (minisatp_32) R 7080 7073 1511 34817 1511 4202496 14784 0 0 0 157 14 0 0 25 0 1 0 1747329 46895104 10051 1283457024 134512640 135413687 4288404608 18446744073709551615 134696821 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/7081/statm: 11449 10051 94 220 0 11227 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 96136

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

[startup+6.40553 s]
/proc/loadavg: 1.07 1.03 1.00 2/37 7081
/proc/meminfo: memFree=591316/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46096 CPUtime=4.57
/proc/7074/stat : 7074 (packup) S 7073 7073 1511 34817 1511 4202496 11245 20361 0 0 178 36 215 28 18 0 1 0 1746870 47202304 10852 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/7074/statm: 11524 10852 333 59 0 10688 0
[pid=7080] ppid=7074 vsize=1672 CPUtime=0
/proc/7080/stat : 7080 (sh) S 7074 7073 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 1747329 1712128 123 1283457024 134512640 134593992 4288162848 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/7080/statm: 418 123 108 20 0 45 0
[pid=7081] ppid=7080 vsize=44768 CPUtime=1.81
/proc/7081/stat : 7081 (minisatp_32) R 7080 7073 1511 34817 1511 4202496 15171 0 0 0 167 14 0 0 25 0 1 0 1747329 45842432 9950 1283457024 134512640 135413687 4288404608 18446744073709551615 134696800 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/7081/statm: 11192 9950 94 220 0 10970 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 95108

[startup+9.60655 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 7083
/proc/meminfo: memFree=556604/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46100 CPUtime=7.52
/proc/7074/stat : 7074 (packup) S 7073 7073 1511 34817 1511 4202496 11307 43522 0 0 189 48 467 48 18 0 1 0 1746870 47206400 10853 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/7074/statm: 11525 10853 333 59 0 10689 0
[pid=7082] ppid=7074 vsize=1668 CPUtime=0
/proc/7082/stat : 7082 (sh) S 7074 7073 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 1747623 1708032 123 1283457024 134512640 134593992 4294058432 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/7082/statm: 417 123 108 20 0 44 0
[pid=7083] ppid=7082 vsize=66760 CPUtime=2.08
/proc/7083/stat : 7083 (minisatp_32) R 7082 7073 1511 34817 1511 4202496 21874 0 0 0 192 16 0 0 25 0 1 0 1747623 68362240 15173 1283457024 134512640 135413687 4290473584 18446744073709551615 134649212 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/7083/statm: 16690 15173 94 220 0 16468 0
Current children cumulated CPU time (s) 9.6
Current children cumulated vsize (KiB) 117100

[startup+11.2086 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 7083
/proc/meminfo: memFree=507500/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46100 CPUtime=7.52
/proc/7074/stat : 7074 (packup) S 7073 7073 1511 34817 1511 4202496 11307 43522 0 0 189 48 467 48 18 0 1 0 1746870 47206400 10853 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/7074/statm: 11525 10853 333 59 0 10689 0
[pid=7082] ppid=7074 vsize=1668 CPUtime=0
/proc/7082/stat : 7082 (sh) S 7074 7073 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 1747623 1708032 123 1283457024 134512640 134593992 4294058432 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/7082/statm: 417 123 108 20 0 44 0
[pid=7083] ppid=7082 vsize=124336 CPUtime=3.67
/proc/7083/stat : 7083 (minisatp_32) R 7082 7073 1511 34817 1511 4202496 37658 0 0 0 347 20 0 0 25 0 1 0 1747623 127320064 26899 1283457024 134512640 135413687 4290473584 18446744073709551615 134971471 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/7083/statm: 31084 26899 107 220 0 30862 0
Current children cumulated CPU time (s) 11.19
Current children cumulated vsize (KiB) 174676

[startup+12.0088 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 7083
/proc/meminfo: memFree=507500/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46100 CPUtime=7.52
/proc/7074/stat : 7074 (packup) S 7073 7073 1511 34817 1511 4202496 11307 43522 0 0 189 48 467 48 18 0 1 0 1746870 47206400 10853 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/7074/statm: 11525 10853 333 59 0 10689 0
[pid=7082] ppid=7074 vsize=1668 CPUtime=0
/proc/7082/stat : 7082 (sh) S 7074 7073 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 1747623 1708032 123 1283457024 134512640 134593992 4294058432 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/7082/statm: 417 123 108 20 0 44 0
[pid=7083] ppid=7082 vsize=121856 CPUtime=4.46
/proc/7083/stat : 7083 (minisatp_32) R 7082 7073 1511 34817 1511 4202496 39568 0 0 0 426 20 0 0 25 0 1 0 1747623 124780544 26236 1283457024 134512640 135413687 4290473584 18446744073709551615 134628267 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/7083/statm: 30464 26236 109 220 0 30242 0
Current children cumulated CPU time (s) 11.98
Current children cumulated vsize (KiB) 172196

[startup+12.4088 s]
/proc/loadavg: 1.06 1.03 1.00 3/37 7083
/proc/meminfo: memFree=504896/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46100 CPUtime=7.52
/proc/7074/stat : 7074 (packup) S 7073 7073 1511 34817 1511 4202496 11307 43522 0 0 189 48 467 48 18 0 1 0 1746870 47206400 10853 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/7074/statm: 11525 10853 333 59 0 10689 0
[pid=7082] ppid=7074 vsize=1668 CPUtime=0
/proc/7082/stat : 7082 (sh) S 7074 7073 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 1747623 1708032 123 1283457024 134512640 134593992 4294058432 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/7082/statm: 417 123 108 20 0 44 0
[pid=7083] ppid=7082 vsize=122320 CPUtime=4.86
/proc/7083/stat : 7083 (minisatp_32) R 7082 7073 1511 34817 1511 4202496 39929 0 0 0 466 20 0 0 25 0 1 0 1747623 125255680 26342 1283457024 134512640 135413687 4290473584 18446744073709551615 134653572 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/7083/statm: 30580 26342 109 220 0 30358 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 172660

[startup+12.6041 s]
/proc/loadavg: 1.06 1.03 1.00 3/37 7083
/proc/meminfo: memFree=504896/1048576 swapFree=0/0
[pid=7073] ppid=7072 vsize=2572 CPUtime=0
/proc/7073/stat : 7073 (packup2mp4tr-0.) S 7072 7073 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 1746870 2633728 274 1283457024 134512640 135304128 4292542432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/7073/statm: 643 274 233 194 0 30 0
[pid=7074] ppid=7073 vsize=46104 CPUtime=12.48
/proc/7074/stat : 7074 (packup) R 7073 7073 1511 34817 1511 4202496 11392 83610 0 0 189 49 940 70 18 0 1 0 1746870 47210496 10867 1283457024 134512640 134752139 4292814832 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/7074/statm: 11526 10867 346 59 0 10690 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 48676

Child status: 0
Real time (s): 12.7002
CPU time (s): 12.5808
CPU user time (s): 11.3727
CPU system time (s): 1.20807
CPU usage (%): 99.0595
Max. virtual memory (cumulated for all children) (KiB): 183216

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.3727
system time used= 1.20808
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 105413
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= 24
involuntary context switches= 211

runsolver used 0 second user time and 0 second system time

The end