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/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/dd08e73e-d489-11df-b9cf-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: 1.06 1.03 0.85 2/60 21248
/proc/meminfo: memFree=178424/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=3152 CPUtime=0
/proc/21248/stat : 21248 (runsolver) R 21247 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115312638 3227648 32 18446744073709551615 134512640 134586868 4288175296 4288173344 4151944240 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 788 32 0 19 0 73 0

[startup+0.191944 s]
/proc/loadavg: 1.06 1.03 0.85 2/60 21248
/proc/meminfo: memFree=178424/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=0.04
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 729 3613 0 0 0 0 4 0 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768229568 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200316 s]
/proc/loadavg: 1.06 1.03 0.85 2/60 21248
/proc/meminfo: memFree=178424/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=0.04
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 729 3613 0 0 0 0 4 0 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768229568 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300258 s]
/proc/loadavg: 1.06 1.03 0.85 2/60 21248
/proc/meminfo: memFree=178424/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=0.04
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 729 3613 0 0 0 0 4 0 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768229568 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700227 s]
/proc/loadavg: 1.06 1.03 0.85 2/60 21248
/proc/meminfo: memFree=178424/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=0.04
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 729 3613 0 0 0 0 4 0 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768229568 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.06 1.03 0.85 2/62 21264
/proc/meminfo: memFree=143184/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=0.04
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 729 3613 0 0 0 0 4 0 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768229568 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21264] ppid=21248 vsize=51796 CPUtime=1.4
/proc/21264/stat : 21264 (cudf2lp) R 21248 21248 1733 0 -1 4202496 14443 0 0 0 132 8 0 0 20 0 1 0 115312642 53039104 11045 18446744073709551615 4194304 5690517 140736166625248 140736166622904 4329232 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/21264/statm: 12949 11045 160 366 0 12580 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 61008

[startup+3.10023 s]
/proc/loadavg: 1.06 1.03 0.85 2/62 21264
/proc/meminfo: memFree=90484/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=2.75
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 754 27026 0 0 0 0 257 18 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768229568 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.75
Current children cumulated vsize (KiB) 9212

[startup+6.30031 s]
/proc/loadavg: 1.05 1.03 0.85 2/62 21265
/proc/meminfo: memFree=29476/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=2.75
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 754 27026 0 0 0 0 257 18 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768229568 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21265] ppid=21248 vsize=226820 CPUtime=3.41
/proc/21265/stat : 21265 (gringo) R 21248 21248 1733 0 -1 4202496 54586 0 0 0 319 22 0 0 20 0 1 0 115312918 232263680 45820 18446744073709551615 4194304 6531320 140735446328304 140735446324712 4596999 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21265/statm: 56705 45820 283 571 0 56126 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 236032

[startup+12.7004 s]
/proc/loadavg: 1.05 1.03 0.85 2/63 21267
/proc/meminfo: memFree=209556/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=8.21
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 793 112335 0 0 0 0 760 61 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768228976 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21266] ppid=21248 vsize=104676 CPUtime=4.18
/proc/21266/stat : 21266 (clasp) R 21248 21248 1733 0 -1 4202496 31471 0 0 0 404 14 0 0 20 0 1 0 115313483 107188224 25812 18446744073709551615 4194304 6238623 140733867153616 140733867150640 4356222 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/21266/statm: 26169 25812 264 500 0 25666 0
[pid=21267] ppid=21248 vsize=22040 CPUtime=0.01
/proc/21267/stat : 21267 (parse.py) S 21248 21248 1733 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 115313483 22568960 1127 18446744073709551615 4194304 6642060 140737036096592 140737036094952 140160913684256 0 0 16777220 20994 0 0 0 17 0 0 0 11 0 0
/proc/21267/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.4
Current children cumulated vsize (KiB) 135928

[startup+25.5004 s]
/proc/loadavg: 1.04 1.03 0.85 2/63 21267
/proc/meminfo: memFree=209556/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=8.21
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 793 112335 0 0 0 0 760 61 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768228976 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21266] ppid=21248 vsize=104676 CPUtime=16.85
/proc/21266/stat : 21266 (clasp) R 21248 21248 1733 0 -1 4202496 31476 0 0 0 1671 14 0 0 20 0 1 0 115313483 107188224 25817 18446744073709551615 4194304 6238623 140733867153616 140733867150640 4687659 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/21266/statm: 26169 25817 264 500 0 25666 0
[pid=21267] ppid=21248 vsize=22040 CPUtime=0.01
/proc/21267/stat : 21267 (parse.py) S 21248 21248 1733 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 115313483 22568960 1127 18446744073709551615 4194304 6642060 140737036096592 140737036094952 140160913684256 0 0 16777220 20994 0 0 0 17 0 0 0 11 0 0
/proc/21267/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.07
Current children cumulated vsize (KiB) 135928

[startup+51.1003 s]
/proc/loadavg: 1.02 1.02 0.86 2/63 21267
/proc/meminfo: memFree=86920/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=8.21
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 793 112335 0 0 0 0 760 61 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768228976 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21266] ppid=21248 vsize=227288 CPUtime=42.25
/proc/21266/stat : 21266 (clasp) R 21248 21248 1733 0 -1 4202496 62172 0 0 0 4198 27 0 0 20 0 1 0 115313483 232742912 56513 18446744073709551615 4194304 6238623 140733867153616 140733867150168 4687697 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/21266/statm: 56822 56513 264 500 0 56319 0
[pid=21267] ppid=21248 vsize=22040 CPUtime=0.01
/proc/21267/stat : 21267 (parse.py) S 21248 21248 1733 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 115313483 22568960 1127 18446744073709551615 4194304 6642060 140737036096592 140737036094952 140160913684256 0 0 16777220 20994 0 0 0 17 0 0 0 11 0 0
/proc/21267/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.47
Current children cumulated vsize (KiB) 258540

[startup+102.3 s]
/proc/loadavg: 1.01 1.02 0.86 2/63 21267
/proc/meminfo: memFree=19836/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=8.21
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 793 112335 0 0 0 0 760 61 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768228976 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21266] ppid=21248 vsize=294168 CPUtime=93.09
/proc/21266/stat : 21266 (clasp) R 21248 21248 1733 0 -1 4202496 78872 0 0 0 9279 30 0 0 20 0 1 0 115313483 301228032 73213 18446744073709551615 4194304 6238623 140733867153616 140733867150168 4696928 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/21266/statm: 73542 73213 264 500 0 73039 0
[pid=21267] ppid=21248 vsize=22040 CPUtime=0.01
/proc/21267/stat : 21267 (parse.py) S 21248 21248 1733 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 115313483 22568960 1127 18446744073709551615 4194304 6642060 140737036096592 140737036094952 140160913684256 0 0 16777220 20994 0 0 0 17 0 0 0 11 0 0
/proc/21267/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.31
Current children cumulated vsize (KiB) 325420



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.4 s]
/proc/loadavg: 1.00 1.02 0.87 2/63 21267
/proc/meminfo: memFree=13612/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=8.21
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 793 112335 0 0 0 0 760 61 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768228976 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21266] ppid=21248 vsize=300352 CPUtime=141.86
/proc/21266/stat : 21266 (clasp) R 21248 21248 1733 0 -1 4202496 80398 0 0 0 14155 31 0 0 20 0 1 0 115313483 307560448 74739 18446744073709551615 4194304 6238623 140733867153616 140733867150168 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/21266/statm: 75088 74739 264 500 0 74585 0
[pid=21267] ppid=21248 vsize=22040 CPUtime=0.01
/proc/21267/stat : 21267 (parse.py) S 21248 21248 1733 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 115313483 22568960 1127 18446744073709551615 4194304 6642060 140737036096592 140737036094952 140160913684256 0 0 16777220 20994 0 0 0 17 0 0 0 11 0 0
/proc/21267/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 331604

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

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

[startup+151.4 s]
/proc/loadavg: 1.00 1.02 0.87 2/63 21267
/proc/meminfo: memFree=13612/1022884 swapFree=0/0
[pid=21248] ppid=21247 vsize=9212 CPUtime=8.21
/proc/21248/stat : 21248 (aspcud-basic) S 21247 21248 1733 0 -1 4202496 793 112335 0 0 0 0 760 61 20 0 1 0 115312638 9433088 364 18446744073709551615 4194304 5129932 140734768230912 140734768228976 140090330846302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21248/statm: 2303 364 303 229 0 63 0
[pid=21266] ppid=21248 vsize=300352 CPUtime=141.86
/proc/21266/stat : 21266 (clasp) R 21248 21248 1733 0 -1 4202496 80398 0 0 0 14155 31 0 0 20 0 1 0 115313483 307560448 74739 18446744073709551615 4194304 6238623 140733867153616 140733867150168 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/21266/statm: 75088 74739 264 500 0 74585 0
[pid=21267] ppid=21248 vsize=22040 CPUtime=0.01
/proc/21267/stat : 21267 (parse.py) S 21248 21248 1733 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 115313483 22568960 1127 18446744073709551615 4194304 6642060 140737036096592 140737036094952 140160913684256 0 0 16777220 20994 0 0 0 17 0 0 0 11 0 0
/proc/21267/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 331604

Child status: 0
Real time (s): 151.456
CPU time (s): 150.169
CPU user time (s): 149.205
CPU system time (s): 0.96406
CPU usage (%): 99.1507
Max. virtual memory (cumulated for all children) (KiB): 377424

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.205
system time used= 0.96406
maximum resident set size= 306156
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 195184
page faults= 14
swaps= 0
block input operations= 41048
block output operations= 36632
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 102
involuntary context switches= 17324

runsolver used 0.32402 second user time and 0.552034 second system time

The end