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: runsolver -s SIGUSR1 -M 1124 -C 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/install/rand954.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand954.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/install/rand954.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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

[startup+0 s]
/proc/loadavg: 1.14 1.05 0.96 2/56 23744
/proc/meminfo: memFree=699864/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=3152 CPUtime=0
/proc/23744/stat : 23744 (runsolver) R 23743 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41408256 3227648 33 18446744073709551615 134512640 134586868 4292071280 4292069328 4152050736 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23744/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.128928 s]
/proc/loadavg: 1.14 1.05 0.96 2/56 23744
/proc/meminfo: memFree=699864/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=0.04
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 694 2803 2 5 0 0 2 2 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200319 s]
/proc/loadavg: 1.14 1.05 0.96 2/56 23744
/proc/meminfo: memFree=699864/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=0.04
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 694 2803 2 5 0 0 2 2 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300313 s]
/proc/loadavg: 1.14 1.05 0.96 2/56 23744
/proc/meminfo: memFree=699864/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=0.04
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 694 2803 2 5 0 0 2 2 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700224 s]
/proc/loadavg: 1.14 1.05 0.96 2/56 23744
/proc/meminfo: memFree=699864/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=0.04
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 694 2803 2 5 0 0 2 2 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.14 1.05 0.96 2/58 23757
/proc/meminfo: memFree=666236/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=0.04
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 694 2803 2 5 0 0 2 2 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23757] ppid=23744 vsize=30672 CPUtime=1.33
/proc/23757/stat : 23757 (cudf2lp) R 23744 23744 32685 0 -1 4202496 9070 0 1 0 128 5 0 0 20 0 1 0 41408265 31408128 7338 18446744073709551615 4194304 5690517 140734891504272 140734891500760 4293680 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/23757/statm: 7668 7338 160 366 0 7299 0
Current children cumulated CPU time (s) 1.37
Current children cumulated vsize (KiB) 39884

[startup+3.10031 s]
/proc/loadavg: 1.14 1.05 0.96 2/58 23757
/proc/meminfo: memFree=633872/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=0.04
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 694 2803 2 5 0 0 2 2 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23757] ppid=23744 vsize=93028 CPUtime=2.9
/proc/23757/stat : 23757 (cudf2lp) R 23744 23744 32685 0 -1 4202496 26613 0 1 0 277 13 0 0 20 0 1 0 41408265 95260672 19887 18446744073709551615 4194304 5690517 140734891504272 140734891501912 4951979 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/23757/statm: 23257 19887 160 366 0 22888 0
Current children cumulated CPU time (s) 2.94
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 1.12 1.05 0.96 2/58 23758
/proc/meminfo: memFree=637716/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=4.91
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 722 42123 2 6 0 0 463 28 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23758] ppid=23744 vsize=38968 CPUtime=1.18
/proc/23758/stat : 23758 (gringo) R 23744 23744 32685 0 -1 4202496 9894 0 0 0 114 4 0 0 20 0 1 0 41408766 39903232 7758 18446744073709551615 4194304 6531320 140735931523920 140735931520536 5184895 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23758/statm: 9742 7758 259 571 0 9163 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 48180

[startup+12.7003 s]
/proc/loadavg: 1.11 1.05 0.96 2/58 23758
/proc/meminfo: memFree=319532/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=4.91
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 722 42123 2 6 0 0 463 28 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155996272 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23758] ppid=23744 vsize=449136 CPUtime=7.54
/proc/23758/stat : 23758 (gringo) R 23744 23744 32685 0 -1 4202496 106646 0 0 0 707 47 0 0 20 0 1 0 41408766 459915264 90171 18446744073709551615 4194304 6531320 140735931523920 140735931519912 5520704 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23758/statm: 112284 90171 282 571 0 111705 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 458348

[startup+25.5005 s]
/proc/loadavg: 1.09 1.04 0.96 2/59 23760
/proc/meminfo: memFree=430876/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=17.97
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 763 221019 2 6 0 0 1667 130 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995680 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23759] ppid=23744 vsize=228452 CPUtime=7.06
/proc/23759/stat : 23759 (unclasp) R 23744 23744 32685 0 -1 4202496 69222 0 0 0 681 25 0 0 20 0 1 0 41410091 233934848 56623 18446744073709551615 4194304 6012874 140737200068848 140737200068168 4855840 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23759/statm: 57113 56623 226 444 0 56661 0
[pid=23760] ppid=23744 vsize=22324 CPUtime=0.02
/proc/23760/stat : 23760 (parse.py) S 23744 23744 32685 0 -1 4202496 1384 0 0 0 2 0 0 0 20 0 1 0 41410091 22859776 1193 18446744073709551615 4194304 6642060 140736025162480 140736025160360 140526221514528 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23760/statm: 5581 1193 508 598 0 667 0
Current children cumulated CPU time (s) 25.05
Current children cumulated vsize (KiB) 259988

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

[startup+25.6005 s]
/proc/loadavg: 1.09 1.04 0.96 2/59 23760
/proc/meminfo: memFree=430876/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=17.97
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 763 221019 2 6 0 0 1667 130 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995680 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23759] ppid=23744 vsize=228452 CPUtime=7.16
/proc/23759/stat : 23759 (unclasp) R 23744 23744 32685 0 -1 4202496 69222 0 0 0 691 25 0 0 20 0 1 0 41410091 233934848 56623 18446744073709551615 4194304 6012874 140737200068848 140737200068168 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23759/statm: 57113 56623 226 444 0 56661 0
[pid=23760] ppid=23744 vsize=22324 CPUtime=0.02
/proc/23760/stat : 23760 (parse.py) S 23744 23744 32685 0 -1 4202496 1384 0 0 0 2 0 0 0 20 0 1 0 41410091 22859776 1193 18446744073709551615 4194304 6642060 140736025162480 140736025160360 140526221514528 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23760/statm: 5581 1193 508 598 0 667 0
Current children cumulated CPU time (s) 25.15
Current children cumulated vsize (KiB) 259988

[startup+32.0047 s]
/proc/loadavg: 1.08 1.04 0.96 2/59 23760
/proc/meminfo: memFree=430752/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=17.97
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 763 221019 2 6 0 0 1667 130 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995680 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23759] ppid=23744 vsize=228452 CPUtime=13.52
/proc/23759/stat : 23759 (unclasp) R 23744 23744 32685 0 -1 4202496 69222 0 0 0 1326 26 0 0 20 0 1 0 41410091 233934848 56623 18446744073709551615 4194304 6012874 140737200068848 140737200068168 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23759/statm: 57113 56623 226 444 0 56661 0
[pid=23760] ppid=23744 vsize=22468 CPUtime=0.02
/proc/23760/stat : 23760 (parse.py) S 23744 23744 32685 0 -1 4202496 1420 0 0 0 2 0 0 0 20 0 1 0 41410091 23007232 1229 18446744073709551615 4194304 6642060 140736025162480 140736025160728 140526221514528 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23760/statm: 5617 1229 508 598 0 703 0
Current children cumulated CPU time (s) 31.51
Current children cumulated vsize (KiB) 260132

[startup+38.4004 s]
/proc/loadavg: 1.07 1.04 0.96 2/59 23760
/proc/meminfo: memFree=430752/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=17.97
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 763 221019 2 6 0 0 1667 130 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995680 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23759] ppid=23744 vsize=228452 CPUtime=19.86
/proc/23759/stat : 23759 (unclasp) R 23744 23744 32685 0 -1 4202496 69222 0 0 0 1958 28 0 0 20 0 1 0 41410091 233934848 56623 18446744073709551615 4194304 6012874 140737200068848 140737200068168 4548194 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23759/statm: 57113 56623 226 444 0 56661 0
[pid=23760] ppid=23744 vsize=22468 CPUtime=0.02
/proc/23760/stat : 23760 (parse.py) S 23744 23744 32685 0 -1 4202496 1420 0 0 0 2 0 0 0 20 0 1 0 41410091 23007232 1229 18446744073709551615 4194304 6642060 140736025162480 140736025160728 140526221514528 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23760/statm: 5617 1229 508 598 0 703 0
Current children cumulated CPU time (s) 37.85
Current children cumulated vsize (KiB) 260132

[startup+41.6004 s]
/proc/loadavg: 1.07 1.04 0.96 2/59 23760
/proc/meminfo: memFree=430752/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=17.97
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 763 221019 2 6 0 0 1667 130 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995680 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23759] ppid=23744 vsize=228452 CPUtime=23.05
/proc/23759/stat : 23759 (unclasp) R 23744 23744 32685 0 -1 4202496 69222 0 0 0 2276 29 0 0 20 0 1 0 41410091 233934848 56623 18446744073709551615 4194304 6012874 140737200068848 140737200068168 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23759/statm: 57113 56623 226 444 0 56661 0
[pid=23760] ppid=23744 vsize=22468 CPUtime=0.02
/proc/23760/stat : 23760 (parse.py) S 23744 23744 32685 0 -1 4202496 1420 0 0 0 2 0 0 0 20 0 1 0 41410091 23007232 1229 18446744073709551615 4194304 6642060 140736025162480 140736025160728 140526221514528 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23760/statm: 5617 1229 508 598 0 703 0
Current children cumulated CPU time (s) 41.04
Current children cumulated vsize (KiB) 260132

[startup+43.2004 s]
/proc/loadavg: 1.07 1.04 0.96 2/59 23760
/proc/meminfo: memFree=430752/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=17.97
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 763 221019 2 6 0 0 1667 130 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995680 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23759] ppid=23744 vsize=228452 CPUtime=24.63
/proc/23759/stat : 23759 (unclasp) R 23744 23744 32685 0 -1 4202496 69222 0 0 0 2434 29 0 0 20 0 1 0 41410091 233934848 56623 18446744073709551615 4194304 6012874 140737200068848 140737200068168 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23759/statm: 57113 56623 226 444 0 56661 0
[pid=23760] ppid=23744 vsize=22468 CPUtime=0.02
/proc/23760/stat : 23760 (parse.py) S 23744 23744 32685 0 -1 4202496 1420 0 0 0 2 0 0 0 20 0 1 0 41410091 23007232 1229 18446744073709551615 4194304 6642060 140736025162480 140736025160728 140526221514528 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23760/statm: 5617 1229 508 598 0 703 0
Current children cumulated CPU time (s) 42.62
Current children cumulated vsize (KiB) 260132

[startup+43.6004 s]
/proc/loadavg: 1.07 1.04 0.96 2/59 23760
/proc/meminfo: memFree=430752/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=17.97
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 763 221019 2 6 0 0 1667 130 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995680 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23759] ppid=23744 vsize=228452 CPUtime=25.03
/proc/23759/stat : 23759 (unclasp) R 23744 23744 32685 0 -1 4202496 69222 0 0 0 2474 29 0 0 20 0 1 0 41410091 233934848 56623 18446744073709551615 4194304 6012874 140737200068848 140737200068168 4548848 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23759/statm: 57113 56623 226 444 0 56661 0
[pid=23760] ppid=23744 vsize=22468 CPUtime=0.02
/proc/23760/stat : 23760 (parse.py) S 23744 23744 32685 0 -1 4202496 1420 0 0 0 2 0 0 0 20 0 1 0 41410091 23007232 1229 18446744073709551615 4194304 6642060 140736025162480 140736025160728 140526221514528 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23760/statm: 5617 1229 508 598 0 703 0
Current children cumulated CPU time (s) 43.02
Current children cumulated vsize (KiB) 260132

[startup+44.0004 s]
/proc/loadavg: 1.06 1.04 0.96 1/58 23761
/proc/meminfo: memFree=659284/1022884 swapFree=0/0
[pid=23744] ppid=23743 vsize=9212 CPUtime=43.42
/proc/23744/stat : 23744 (aspuncud-full) S 23743 23744 32685 0 -1 4202496 796 291687 2 6 0 0 4174 168 20 0 1 0 41408256 9433088 365 18446744073709551615 4194304 5129932 140734155997616 140734155995168 139700800910430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23744/statm: 2303 365 303 229 0 63 0
[pid=23761] ppid=23744 vsize=152 CPUtime=0
/proc/23761/stat : 23761 (rm) R 23744 23744 32685 0 -1 4194304 59 0 0 0 0 0 0 0 20 0 1 0 41412655 155648 1 18446744073709551615 0 0 140733419654308 140734155995272 139700800912423 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/23761/statm: 38 1 0 0 0 22 0
Current children cumulated CPU time (s) 43.42
Current children cumulated vsize (KiB) 9364

Child status: 0
Real time (s): 44.0219
CPU time (s): 43.4507
CPU user time (s): 41.7506
CPU system time (s): 1.70011
CPU usage (%): 98.7026
Max. virtual memory (cumulated for all children) (KiB): 784188

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 41.7506
system time used= 1.70011
maximum resident set size= 649668
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 292716
page faults= 9
swaps= 0
block input operations= 69032
block output operations= 81880
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 194
involuntary context switches= 841

runsolver used 0.108006 second user time and 0.196012 second system time

The end