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 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/1aabfc32-d491-11df-9a24-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/1aabfc32-d491-11df-9a24-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/1aabfc32-d491-11df-9a24-00163e3d3b7c.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 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: 0.85 0.91 0.67 2/60 20745
/proc/meminfo: memFree=431144/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9204 CPUtime=0
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 115231037 9424896 331 18446744073709551615 4194304 5129932 140733493821488 140733493818952 139984631187232 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2301 331 272 229 0 61 0

[startup+0.132315 s]
/proc/loadavg: 0.85 0.91 0.67 2/60 20745
/proc/meminfo: memFree=431144/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=0.05
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 729 3615 0 0 1 0 3 1 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493820144 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200317 s]
/proc/loadavg: 0.85 0.91 0.67 2/60 20745
/proc/meminfo: memFree=431144/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=0.05
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 729 3615 0 0 1 0 3 1 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493820144 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300303 s]
/proc/loadavg: 0.85 0.91 0.67 2/60 20745
/proc/meminfo: memFree=431144/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=0.05
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 729 3615 0 0 1 0 3 1 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493820144 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700229 s]
/proc/loadavg: 0.85 0.91 0.67 2/60 20745
/proc/meminfo: memFree=431144/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=0.05
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 729 3615 0 0 1 0 3 1 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493820144 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.87 0.91 0.67 2/62 20761
/proc/meminfo: memFree=395284/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=0.05
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 729 3615 0 0 1 0 3 1 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493820144 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
[pid=20761] ppid=20745 vsize=51240 CPUtime=1.4
/proc/20761/stat : 20761 (cudf2lp) R 20745 20745 1733 0 -1 4202496 14346 0 0 0 134 6 0 0 20 0 1 0 115231040 52469760 10948 18446744073709551615 4194304 5690517 140736881645824 140736881643464 4359402 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/20761/statm: 12810 10948 160 366 0 12441 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 60452

[startup+3.10024 s]
/proc/loadavg: 0.87 0.91 0.67 2/62 20761
/proc/meminfo: memFree=362176/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=2.92
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 754 28562 0 0 1 0 274 17 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493820144 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 9212

[startup+6.30033 s]
/proc/loadavg: 0.87 0.91 0.67 2/62 20762
/proc/meminfo: memFree=283808/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=2.92
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 754 28562 0 0 1 0 274 17 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493820144 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
[pid=20762] ppid=20745 vsize=189004 CPUtime=3.28
/proc/20762/stat : 20762 (gringo) R 20745 20745 1733 0 -1 4202496 45948 0 0 0 310 18 0 0 20 0 1 0 115231335 193540096 41279 18446744073709551615 4194304 6531320 140734346271680 140734346268296 4363222 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20762/statm: 47251 41279 283 571 0 46672 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 198216

[startup+12.7004 s]
/proc/loadavg: 0.89 0.91 0.67 2/63 20764
/proc/meminfo: memFree=274376/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=8.82
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 793 120290 0 0 1 0 815 66 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493819552 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
[pid=20763] ppid=20745 vsize=115324 CPUtime=3.7
/proc/20763/stat : 20763 (clasp) R 20745 20745 1733 0 -1 4202496 33997 0 0 0 355 15 0 0 20 0 1 0 115231930 118091776 28199 18446744073709551615 4194304 6238623 140735562477632 140735562474656 4586315 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20763/statm: 28831 28199 263 500 0 28328 0
[pid=20764] ppid=20745 vsize=22040 CPUtime=0.01
/proc/20764/stat : 20764 (parse.py) S 20745 20745 1733 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 115231930 22568960 1128 18446744073709551615 4194304 6642060 140735539714736 140735539713096 140293719332640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20764/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 146576

[startup+25.5004 s]
/proc/loadavg: 0.90 0.91 0.68 2/63 20764
/proc/meminfo: memFree=274376/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=8.82
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 793 120290 0 0 1 0 815 66 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493819552 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
[pid=20763] ppid=20745 vsize=115324 CPUtime=16.38
/proc/20763/stat : 20763 (clasp) R 20745 20745 1733 0 -1 4202496 34020 0 0 0 1623 15 0 0 20 0 1 0 115231930 118091776 28222 18446744073709551615 4194304 6238623 140735562477632 140735562474656 4332548 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20763/statm: 28831 28222 264 500 0 28328 0
[pid=20764] ppid=20745 vsize=22040 CPUtime=0.01
/proc/20764/stat : 20764 (parse.py) S 20745 20745 1733 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 115231930 22568960 1128 18446744073709551615 4194304 6642060 140735539714736 140735539713096 140293719332640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20764/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.21
Current children cumulated vsize (KiB) 146576

[startup+51.1004 s]
/proc/loadavg: 0.93 0.92 0.68 2/63 20764
/proc/meminfo: memFree=203448/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=8.82
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 793 120290 0 0 1 0 815 66 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493819552 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
[pid=20763] ppid=20745 vsize=185164 CPUtime=41.73
/proc/20763/stat : 20763 (clasp) R 20745 20745 1733 0 -1 4202496 51799 0 0 0 4150 23 0 0 20 0 1 0 115231930 189607936 46001 18446744073709551615 4194304 6238623 140735562477632 140735562474184 4331882 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20763/statm: 46291 46001 264 500 0 45788 0
[pid=20764] ppid=20745 vsize=22040 CPUtime=0.01
/proc/20764/stat : 20764 (parse.py) S 20745 20745 1733 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 115231930 22568960 1128 18446744073709551615 4194304 6642060 140735539714736 140735539713096 140293719332640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20764/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.56
Current children cumulated vsize (KiB) 216416

[startup+102.3 s]
/proc/loadavg: 0.97 0.93 0.70 2/63 20764
/proc/meminfo: memFree=88872/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=8.82
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 793 120290 0 0 1 0 815 66 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493819552 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
[pid=20763] ppid=20745 vsize=299552 CPUtime=92.54
/proc/20763/stat : 20763 (clasp) R 20745 20745 1733 0 -1 4202496 80344 0 0 0 9219 35 0 0 20 0 1 0 115231930 306741248 74546 18446744073709551615 4194304 6238623 140735562477632 140735562474184 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20763/statm: 74888 74546 264 500 0 74385 0
[pid=20764] ppid=20745 vsize=22040 CPUtime=0.01
/proc/20764/stat : 20764 (parse.py) S 20745 20745 1733 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 115231930 22568960 1128 18446744073709551615 4194304 6642060 140735539714736 140735539713096 140293719332640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20764/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.37
Current children cumulated vsize (KiB) 330804



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.3 s]
/proc/loadavg: 0.99 0.94 0.71 2/63 20764
/proc/meminfo: memFree=83788/1022884 swapFree=0/0
[pid=20745] ppid=20744 vsize=9212 CPUtime=8.82
/proc/20745/stat : 20745 (aspcud-basic) S 20744 20745 1733 0 -1 4202496 793 120290 0 0 1 0 815 66 20 0 1 0 115231037 9433088 364 18446744073709551615 4194304 5129932 140733493821488 140733493819552 139984631043166 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20745/statm: 2303 364 303 229 0 63 0
[pid=20763] ppid=20745 vsize=304512 CPUtime=141.2
/proc/20763/stat : 20763 (clasp) R 20745 20745 1733 0 -1 4202496 81600 0 0 0 14084 36 0 0 20 0 1 0 115231930 311820288 75802 18446744073709551615 4194304 6238623 140735562477632 140735562474184 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20763/statm: 76128 75802 264 500 0 75625 0
[pid=20764] ppid=20745 vsize=22040 CPUtime=0.01
/proc/20764/stat : 20764 (parse.py) S 20745 20745 1733 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 115231930 22568960 1128 18446744073709551615 4194304 6642060 140735539714736 140735539713096 140293719332640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20764/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.03
Current children cumulated vsize (KiB) 335764

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 151.352
CPU time (s): 150.097
CPU user time (s): 149.041
CPU system time (s): 1.05607
CPU usage (%): 99.1711
Max. virtual memory (cumulated for all children) (KiB): 400620

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.041
system time used= 1.05607
maximum resident set size= 331832
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 204355
page faults= 0
swaps= 0
block input operations= 43040
block output operations= 39760
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 93
involuntary context switches= 17219

runsolver used 0.288018 second user time and 0.64404 second system time

The end