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/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.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: 0.88 0.92 0.92 2/59 5345
/proc/meminfo: memFree=396276/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=3152 CPUtime=0
/proc/5345/stat : 5345 (runsolver) R 5344 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115784564 3227648 32 18446744073709551615 134512640 134586868 4288825920 4288823968 4151563312 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.109304 s]
/proc/loadavg: 0.88 0.92 0.92 2/59 5345
/proc/meminfo: memFree=396276/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=0.03
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 730 3610 0 0 0 0 3 0 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415840 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200262 s]
/proc/loadavg: 0.88 0.92 0.92 2/59 5345
/proc/meminfo: memFree=396276/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=0.03
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 730 3610 0 0 0 0 3 0 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415840 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300285 s]
/proc/loadavg: 0.88 0.92 0.92 2/59 5345
/proc/meminfo: memFree=396276/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=0.03
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 730 3610 0 0 0 0 3 0 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415840 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700211 s]
/proc/loadavg: 0.88 0.92 0.92 2/59 5345
/proc/meminfo: memFree=396276/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=0.03
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 730 3610 0 0 0 0 3 0 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415840 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.88 0.92 0.92 2/61 5361
/proc/meminfo: memFree=335988/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=0.03
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 730 3610 0 0 0 0 3 0 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415840 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5361] ppid=5345 vsize=80696 CPUtime=1.44
/proc/5361/stat : 5361 (cudf2lp) R 5345 5345 1750 0 -1 4202496 22473 0 0 0 137 7 0 0 20 0 1 0 115784566 82632704 19074 18446744073709551615 4194304 5690517 140736290289344 140736290286472 5007832 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/5361/statm: 20174 19074 168 366 0 19805 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 89908

[startup+3.10026 s]
/proc/loadavg: 0.88 0.92 0.92 2/61 5362
/proc/meminfo: memFree=352604/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=1.82
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 755 27025 0 0 0 0 170 12 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415840 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5362] ppid=5345 vsize=95088 CPUtime=1.24
/proc/5362/stat : 5362 (gringo) R 5345 5345 1750 0 -1 4202496 24319 0 0 0 116 8 0 0 20 0 1 0 115784748 97370112 19651 18446744073709551615 4194304 6531320 140735470286112 140735470282536 4596029 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/5362/statm: 23772 19651 281 571 0 23193 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 104300

[startup+6.30032 s]
/proc/loadavg: 0.97 0.93 0.93 2/62 5364
/proc/meminfo: memFree=279560/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=5.2
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 793 106845 0 0 0 0 479 41 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415248 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5363] ppid=5345 vsize=97956 CPUtime=1.01
/proc/5363/stat : 5363 (clasp) R 5345 5345 1750 0 -1 4202496 28253 0 0 0 92 9 0 0 20 0 1 0 115785089 100306944 24070 18446744073709551615 4194304 6238623 140736542382480 140736542379504 4355607 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5363/statm: 24489 24070 263 500 0 23986 0
[pid=5364] ppid=5345 vsize=22040 CPUtime=0.01
/proc/5364/stat : 5364 (parse.py) S 5345 5345 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 115785089 22568960 1127 18446744073709551615 4194304 6642060 140736257992768 140736257991128 140133679093536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5364/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 129208

[startup+12.7003 s]
/proc/loadavg: 1.05 0.95 0.94 2/62 5364
/proc/meminfo: memFree=260216/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=5.2
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 793 106845 0 0 0 0 479 41 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415248 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5363] ppid=5345 vsize=97956 CPUtime=7.37
/proc/5363/stat : 5363 (clasp) R 5345 5345 1750 0 -1 4202496 28255 0 0 0 727 10 0 0 20 0 1 0 115785089 100306944 24072 18446744073709551615 4194304 6238623 140736542382480 140736542379504 4409904 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5363/statm: 24489 24072 263 500 0 23986 0
[pid=5364] ppid=5345 vsize=22040 CPUtime=0.01
/proc/5364/stat : 5364 (parse.py) S 5345 5345 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 115785089 22568960 1127 18446744073709551615 4194304 6642060 140736257992768 140736257991128 140133679093536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5364/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 129208

[startup+25.5003 s]
/proc/loadavg: 1.04 0.95 0.94 2/62 5364
/proc/meminfo: memFree=260216/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=5.2
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 793 106845 0 0 0 0 479 41 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415248 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5363] ppid=5345 vsize=97956 CPUtime=20.07
/proc/5363/stat : 5363 (clasp) R 5345 5345 1750 0 -1 4202496 28255 0 0 0 1997 10 0 0 20 0 1 0 115785089 100306944 24072 18446744073709551615 4194304 6238623 140736542382480 140736542379504 4687675 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5363/statm: 24489 24072 263 500 0 23986 0
[pid=5364] ppid=5345 vsize=22040 CPUtime=0.01
/proc/5364/stat : 5364 (parse.py) S 5345 5345 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 115785089 22568960 1127 18446744073709551615 4194304 6642060 140736257992768 140736257991128 140133679093536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5364/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.28
Current children cumulated vsize (KiB) 129208

[startup+51.1004 s]
/proc/loadavg: 1.03 0.96 0.94 2/62 5364
/proc/meminfo: memFree=235788/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=5.2
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 793 106845 0 0 0 0 479 41 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415248 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5363] ppid=5345 vsize=122212 CPUtime=45.48
/proc/5363/stat : 5363 (clasp) R 5345 5345 1750 0 -1 4202496 34423 0 0 0 4535 13 0 0 20 0 1 0 115785089 125145088 30240 18446744073709551615 4194304 6238623 140736542382480 140736542379504 4332793 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5363/statm: 30553 30240 263 500 0 30050 0
[pid=5364] ppid=5345 vsize=22040 CPUtime=0.01
/proc/5364/stat : 5364 (parse.py) S 5345 5345 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 115785089 22568960 1127 18446744073709551615 4194304 6642060 140736257992768 140736257991128 140133679093536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5364/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.69
Current children cumulated vsize (KiB) 153464

[startup+102.3 s]
/proc/loadavg: 1.01 0.96 0.94 2/62 5364
/proc/meminfo: memFree=192016/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=5.2
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 793 106845 0 0 0 0 479 41 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415248 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5363] ppid=5345 vsize=165744 CPUtime=96.32
/proc/5363/stat : 5363 (clasp) R 5345 5345 1750 0 -1 4202496 45305 0 0 0 9612 20 0 0 20 0 1 0 115785089 169721856 41122 18446744073709551615 4194304 6238623 140736542382480 140736542379504 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5363/statm: 41436 41122 263 500 0 40933 0
[pid=5364] ppid=5345 vsize=22040 CPUtime=0.01
/proc/5364/stat : 5364 (parse.py) S 5345 5345 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 115785089 22568960 1127 18446744073709551615 4194304 6642060 140736257992768 140736257991128 140133679093536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5364/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.53
Current children cumulated vsize (KiB) 196996



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.3 s]
/proc/loadavg: 1.00 0.97 0.94 2/62 5364
/proc/meminfo: memFree=181724/1022884 swapFree=0/0
[pid=5345] ppid=5344 vsize=9212 CPUtime=5.2
/proc/5345/stat : 5345 (aspcud-basic) S 5344 5345 1750 0 -1 4202496 793 106845 0 0 0 0 479 41 20 0 1 0 115784564 9433088 365 18446744073709551615 4194304 5129932 140735795417184 140735795415248 140207251215454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5345/statm: 2303 365 303 229 0 63 0
[pid=5363] ppid=5345 vsize=175860 CPUtime=144.84
/proc/5363/stat : 5363 (clasp) R 5345 5345 1750 0 -1 4202496 47858 0 0 0 14462 22 0 0 20 0 1 0 115785089 180080640 43675 18446744073709551615 4194304 6238623 140736542382480 140736542379504 4306765 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5363/statm: 43965 43675 263 500 0 43462 0
[pid=5364] ppid=5345 vsize=22040 CPUtime=0.01
/proc/5364/stat : 5364 (parse.py) S 5345 5345 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 115785089 22568960 1127 18446744073709551615 4194304 6642060 140736257992768 140736257991128 140133679093536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5364/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 207112

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.341
CPU time (s): 150.129
CPU user time (s): 149.445
CPU system time (s): 0.684042
CPU usage (%): 99.1991
Max. virtual memory (cumulated for all children) (KiB): 348932

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.445
system time used= 0.684042
maximum resident set size= 284204
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 157113
page faults= 0
swaps= 0
block input operations= 39640
block output operations= 34720
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 64
involuntary context switches= 17208

runsolver used 0.352022 second user time and 0.548034 second system time

The end