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/embedded/real/80e3fda2-9501-11e0-8001-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/80e3fda2-9501-11e0-8001-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/80e3fda2-9501-11e0-8001-00163e1e087d.cudf.result -sum(solution,installedsize),-count(removed) 

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

[startup+0 s]
/proc/loadavg: 1.00 0.98 0.95 2/56 9780
/proc/meminfo: memFree=227892/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=3152 CPUtime=0
/proc/9780/stat : 9780 (runsolver) R 9779 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 37610483 3227648 32 18446744073709551615 134512640 134586868 4291481504 4291479552 4151493680 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.151502 s]
/proc/loadavg: 1.00 0.98 0.95 2/56 9780
/proc/meminfo: memFree=227892/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=0.04
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 737 3614 0 0 0 0 3 1 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921888 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.20031 s]
/proc/loadavg: 1.00 0.98 0.95 2/56 9780
/proc/meminfo: memFree=227892/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=0.04
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 737 3614 0 0 0 0 3 1 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921888 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300297 s]
/proc/loadavg: 1.00 0.98 0.95 2/56 9780
/proc/meminfo: memFree=227892/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=0.04
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 737 3614 0 0 0 0 3 1 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921888 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700218 s]
/proc/loadavg: 1.00 0.98 0.95 2/56 9780
/proc/meminfo: memFree=227892/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=0.04
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 737 3614 0 0 0 0 3 1 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921888 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50029 s]
/proc/loadavg: 1.00 0.98 0.95 2/58 9796
/proc/meminfo: memFree=190900/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=0.04
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 737 3614 0 0 0 0 3 1 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921888 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
[pid=9796] ppid=9780 vsize=50184 CPUtime=1.42
/proc/9796/stat : 9796 (cudf2lp) R 9780 9780 32685 0 -1 4202496 14232 0 0 0 136 6 0 0 20 0 1 0 37610486 51388416 10832 18446744073709551615 4194304 5690517 140734178373024 140734178370664 4970528 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/9796/statm: 12546 10832 160 366 0 12177 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 59396

[startup+3.10021 s]
/proc/loadavg: 1.00 0.98 0.95 2/58 9796
/proc/meminfo: memFree=130760/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=2.54
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 763 27620 0 0 0 0 242 12 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921888 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.54
Current children cumulated vsize (KiB) 9212

[startup+6.30038 s]
/proc/loadavg: 1.00 0.98 0.95 2/59 9799
/proc/meminfo: memFree=156916/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=4.85
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 802 64352 0 0 0 0 453 32 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921296 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
[pid=9798] ppid=9780 vsize=42032 CPUtime=1.35
/proc/9798/stat : 9798 (clasp) R 9780 9780 32685 0 -1 4202496 12090 0 0 0 131 4 0 0 20 0 1 0 37610974 43040768 10168 18446744073709551615 4194304 6238623 140734678800000 140734678797024 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9798/statm: 10508 10168 263 500 0 10005 0
[pid=9799] ppid=9780 vsize=22040 CPUtime=0.02
/proc/9799/stat : 9799 (parse.py) S 9780 9780 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37610974 22568960 1128 18446744073709551615 4194304 6642060 140737098164672 140737098163032 140438093502240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9799/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 73284

[startup+12.7004 s]
/proc/loadavg: 1.00 0.98 0.95 2/59 9799
/proc/meminfo: memFree=157040/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=4.85
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 802 64352 0 0 0 0 453 32 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921296 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
[pid=9798] ppid=9780 vsize=42032 CPUtime=7.7
/proc/9798/stat : 9798 (clasp) R 9780 9780 32685 0 -1 4202496 12090 0 0 0 766 4 0 0 20 0 1 0 37610974 43040768 10168 18446744073709551615 4194304 6238623 140734678800000 140734678797024 4407065 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9798/statm: 10508 10168 263 500 0 10005 0
[pid=9799] ppid=9780 vsize=22040 CPUtime=0.02
/proc/9799/stat : 9799 (parse.py) S 9780 9780 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37610974 22568960 1128 18446744073709551615 4194304 6642060 140737098164672 140737098163032 140438093502240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9799/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.57
Current children cumulated vsize (KiB) 73284

[startup+25.5004 s]
/proc/loadavg: 1.00 0.98 0.95 2/59 9799
/proc/meminfo: memFree=157040/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=4.85
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 802 64352 0 0 0 0 453 32 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921296 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
[pid=9798] ppid=9780 vsize=42032 CPUtime=20.41
/proc/9798/stat : 9798 (clasp) R 9780 9780 32685 0 -1 4202496 12090 0 0 0 2037 4 0 0 20 0 1 0 37610974 43040768 10168 18446744073709551615 4194304 6238623 140734678800000 140734678797024 4586419 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9798/statm: 10508 10168 263 500 0 10005 0
[pid=9799] ppid=9780 vsize=22040 CPUtime=0.02
/proc/9799/stat : 9799 (parse.py) S 9780 9780 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37610974 22568960 1128 18446744073709551615 4194304 6642060 140737098164672 140737098163032 140438093502240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9799/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.28
Current children cumulated vsize (KiB) 73284

[startup+51.1004 s]
/proc/loadavg: 1.00 0.98 0.95 2/59 9799
/proc/meminfo: memFree=155676/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=4.85
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 802 64352 0 0 0 0 453 32 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921296 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
[pid=9798] ppid=9780 vsize=43352 CPUtime=45.84
/proc/9798/stat : 9798 (clasp) R 9780 9780 32685 0 -1 4202496 12468 0 0 0 4579 5 0 0 20 0 1 0 37610974 44392448 10546 18446744073709551615 4194304 6238623 140734678800000 140734678797024 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9798/statm: 10838 10546 263 500 0 10335 0
[pid=9799] ppid=9780 vsize=22040 CPUtime=0.02
/proc/9799/stat : 9799 (parse.py) S 9780 9780 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37610974 22568960 1128 18446744073709551615 4194304 6642060 140737098164672 140737098163032 140438093502240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9799/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.71
Current children cumulated vsize (KiB) 74604

[startup+102.3 s]
/proc/loadavg: 1.00 0.98 0.95 2/59 9799
/proc/meminfo: memFree=123312/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=4.85
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 802 64352 0 0 0 0 453 32 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921296 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
[pid=9798] ppid=9780 vsize=75856 CPUtime=96.68
/proc/9798/stat : 9798 (clasp) R 9780 9780 32685 0 -1 4202496 20531 0 0 0 9657 11 0 0 20 0 1 0 37610974 77676544 18609 18446744073709551615 4194304 6238623 140734678800000 140734678797024 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9798/statm: 18964 18609 263 500 0 18461 0
[pid=9799] ppid=9780 vsize=22040 CPUtime=0.02
/proc/9799/stat : 9799 (parse.py) S 9780 9780 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37610974 22568960 1128 18446744073709551615 4194304 6642060 140737098164672 140737098163032 140438093502240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9799/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.55
Current children cumulated vsize (KiB) 107108



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.1 s]
/proc/loadavg: 1.00 0.98 0.95 2/59 9799
/proc/meminfo: memFree=123064/1022884 swapFree=0/0
[pid=9780] ppid=9779 vsize=9212 CPUtime=4.85
/proc/9780/stat : 9780 (aspcud-basic) S 9779 9780 32685 0 -1 4202496 802 64352 0 0 0 0 453 32 20 0 1 0 37610483 9433088 364 18446744073709551615 4194304 5129932 140733994923232 140733994921296 139910872290398 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9780/statm: 2303 364 303 229 0 63 0
[pid=9798] ppid=9780 vsize=75856 CPUtime=145.18
/proc/9798/stat : 9798 (clasp) R 9780 9780 32685 0 -1 4202496 20573 0 0 0 14503 15 0 0 20 0 1 0 37610974 77676544 18651 18446744073709551615 4194304 6238623 140734678800000 140734678797024 4663111 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9798/statm: 18964 18651 263 500 0 18461 0
[pid=9799] ppid=9780 vsize=22040 CPUtime=0.02
/proc/9799/stat : 9799 (parse.py) S 9780 9780 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37610974 22568960 1128 18446744073709551615 4194304 6642060 140737098164672 140737098163032 140438093502240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9799/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 107108

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.119
CPU time (s): 150.097
CPU user time (s): 149.589
CPU system time (s): 0.508031
CPU usage (%): 99.3237
Max. virtual memory (cumulated for all children) (KiB): 161092

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.589
system time used= 0.508031
maximum resident set size= 132544
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 87350
page faults= 0
swaps= 0
block input operations= 37048
block output operations= 18624
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 70
involuntary context switches= 2251

runsolver used 0.32802 second user time and 0.676042 second system time

The end