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/upgrade/real/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/upgrade/real/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf.result -count(down),-notuptodate(solution),-aligned(solution,source,sourceversion),-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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.00 0.97 0.62 2/65 9390
/proc/meminfo: memFree=425760/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9204 CPUtime=0
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 117130062 9424896 332 18446744073709551615 4194304 5129932 140737337703056 140737337700520 140331810010912 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2301 332 272 229 0 61 0

[startup+0.189145 s]
/proc/loadavg: 1.00 0.97 0.62 2/65 9390
/proc/meminfo: memFree=425760/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=0.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 697 2816 0 0 0 0 3 0 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200374 s]
/proc/loadavg: 1.00 0.97 0.62 2/65 9390
/proc/meminfo: memFree=425760/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=0.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 697 2816 0 0 0 0 3 0 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300374 s]
/proc/loadavg: 1.00 0.97 0.62 2/65 9390
/proc/meminfo: memFree=425760/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=0.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 697 2816 0 0 0 0 3 0 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700277 s]
/proc/loadavg: 1.00 0.97 0.62 2/65 9390
/proc/meminfo: memFree=425760/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=0.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 697 2816 0 0 0 0 3 0 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50037 s]
/proc/loadavg: 1.00 0.97 0.62 2/67 9403
/proc/meminfo: memFree=388660/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=0.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 697 2816 0 0 0 0 3 0 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
[pid=9403] ppid=9390 vsize=55948 CPUtime=1.43
/proc/9403/stat : 9403 (cudf2lp) R 9390 9390 1745 0 -1 4202496 15462 0 0 0 135 8 0 0 20 0 1 0 117130066 57290752 12062 18446744073709551615 4194304 5690517 140737032625136 140737032622776 4293615 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/9403/statm: 13987 12062 160 366 0 13618 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 65160

[startup+3.10037 s]
/proc/loadavg: 1.00 0.97 0.62 2/67 9403
/proc/meminfo: memFree=338812/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=3.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 724 27979 0 0 0 0 283 20 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 9212

[startup+6.30027 s]
/proc/loadavg: 1.00 0.97 0.62 2/67 9404
/proc/meminfo: memFree=257716/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=3.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 724 27979 0 0 0 0 283 20 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
[pid=9404] ppid=9390 vsize=277268 CPUtime=3.19
/proc/9404/stat : 9404 (gringo) R 9390 9390 1745 0 -1 4202496 65030 0 0 0 295 24 0 0 20 0 1 0 117130370 283922432 55849 18446744073709551615 4194304 6531320 140737381191728 140737381188712 4452639 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9404/statm: 69317 55849 282 571 0 68738 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 286480

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

[startup+6.40037 s]
/proc/loadavg: 1.00 0.97 0.62 2/67 9404
/proc/meminfo: memFree=257716/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=3.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 724 27979 0 0 0 0 283 20 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
[pid=9404] ppid=9390 vsize=296584 CPUtime=3.29
/proc/9404/stat : 9404 (gringo) R 9390 9390 1745 0 -1 4202496 69091 0 0 0 305 24 0 0 20 0 1 0 117130370 303702016 59910 18446744073709551615 4194304 6531320 140737381191728 140737381188152 4597961 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9404/statm: 74146 59910 282 571 0 73567 0
Current children cumulated CPU time (s) 6.32
Current children cumulated vsize (KiB) 305796

[startup+7.2008 s]
/proc/loadavg: 1.00 0.97 0.62 2/67 9404
/proc/meminfo: memFree=117100/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=3.03
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 724 27979 0 0 0 0 283 20 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701712 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
[pid=9404] ppid=9390 vsize=360520 CPUtime=4.08
/proc/9404/stat : 9404 (gringo) R 9390 9390 1745 0 -1 4202496 84049 0 0 0 380 28 0 0 20 0 1 0 117130370 369172480 69221 18446744073709551615 4194304 6531320 140737381191728 140737381189416 5641063 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9404/statm: 90130 69221 283 571 0 89551 0
Current children cumulated CPU time (s) 7.11
Current children cumulated vsize (KiB) 369732

[startup+8.00035 s]
/proc/loadavg: 1.00 0.97 0.62 2/68 9406
/proc/meminfo: memFree=286104/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=7.28
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 763 112032 0 0 0 0 673 55 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701120 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
[pid=9405] ppid=9390 vsize=113456 CPUtime=0.6
/proc/9405/stat : 9405 (unclasp) R 9390 9390 1745 0 -1 4202496 31362 0 0 0 50 10 0 0 20 0 1 0 117130799 116178944 27178 18446744073709551615 4194304 6012874 140733720476048 140733720475368 4532684 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9405/statm: 28364 27178 220 444 0 27912 0
[pid=9406] ppid=9390 vsize=22040 CPUtime=0.01
/proc/9406/stat : 9406 (parse.py) S 9390 9390 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 117130799 22568960 1127 18446744073709551615 4194304 6642060 140735279331456 140735279329816 140507849443104 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9406/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 7.89
Current children cumulated vsize (KiB) 144708

[startup+8.20037 s]
/proc/loadavg: 1.00 0.97 0.62 2/68 9406
/proc/meminfo: memFree=286104/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=7.28
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 763 112032 0 0 0 0 673 55 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337701120 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
[pid=9405] ppid=9390 vsize=105252 CPUtime=0.79
/proc/9405/stat : 9405 (unclasp) R 9390 9390 1745 0 -1 4202496 31374 0 0 0 69 10 0 0 20 0 1 0 117130799 107778048 25679 18446744073709551615 4194304 6012874 140733720476048 140733720475368 4535463 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9405/statm: 26313 25679 226 444 0 25861 0
[pid=9406] ppid=9390 vsize=22364 CPUtime=0.02
/proc/9406/stat : 9406 (parse.py) S 9390 9390 1745 0 -1 4202496 1395 0 0 0 0 2 0 0 20 0 1 0 117130799 22900736 1203 18446744073709551615 4194304 6642060 140735279331456 140735279329416 140507849443104 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9406/statm: 5591 1203 508 598 0 677 0
Current children cumulated CPU time (s) 8.09
Current children cumulated vsize (KiB) 136828

[startup+8.30037 s]
/proc/loadavg: 1.00 0.97 0.62 2/68 9406
/proc/meminfo: memFree=286104/1022884 swapFree=0/0
[pid=9390] ppid=9389 vsize=9212 CPUtime=8.2
/proc/9390/stat : 9390 (aspuncud-full) S 9389 9390 1745 0 -1 4202496 798 144876 0 0 0 0 750 70 20 0 1 0 117130062 9433088 365 18446744073709551615 4194304 5129932 140737337703056 140737337700608 140331809866846 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9390/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 8.2
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 8.30343
CPU time (s): 8.23251
CPU user time (s): 7.51247
CPU system time (s): 0.720045
CPU usage (%): 99.146
Max. virtual memory (cumulated for all children) (KiB): 373832

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.51247
system time used= 0.720045
maximum resident set size= 299472
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 145907
page faults= 0
swaps= 0
block input operations= 40776
block output operations= 41464
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 248
involuntary context switches= 1150

runsolver used 0.024001 second user time and 0.036002 second system time

The end