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/aspuncud-basic-1.7/embedded/install/rand7.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand7.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/embedded/install/rand7.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.87 0.93 0.90 2/59 23666
/proc/meminfo: memFree=403144/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=3152 CPUtime=0
/proc/23666/stat : 23666 (runsolver) R 23665 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115938598 3227648 33 18446744073709551615 134512640 134586868 4288209120 4288207168 4152054832 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.180057 s]
/proc/loadavg: 0.87 0.93 0.90 2/59 23666
/proc/meminfo: memFree=403144/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=0.03
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 694 2807 0 0 0 0 3 0 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909999168 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200337 s]
/proc/loadavg: 0.87 0.93 0.90 2/59 23666
/proc/meminfo: memFree=403144/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=0.03
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 694 2807 0 0 0 0 3 0 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909999168 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300305 s]
/proc/loadavg: 0.87 0.93 0.90 2/59 23666
/proc/meminfo: memFree=403144/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=0.03
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 694 2807 0 0 0 0 3 0 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909999168 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700238 s]
/proc/loadavg: 0.87 0.93 0.90 2/59 23666
/proc/meminfo: memFree=403144/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=0.03
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 694 2807 0 0 0 0 3 0 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909999168 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 0.88 0.93 0.90 2/61 23679
/proc/meminfo: memFree=369144/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=0.03
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 694 2807 0 0 0 0 3 0 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909999168 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
[pid=23679] ppid=23666 vsize=33064 CPUtime=1.4
/proc/23679/stat : 23679 (cudf2lp) R 23666 23666 1733 0 -1 4202496 9696 0 0 0 134 6 0 0 20 0 1 0 115938601 33857536 7963 18446744073709551615 4194304 5690517 140733216552480 140733216550120 4357520 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/23679/statm: 8266 7963 160 366 0 7897 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 42276

[startup+3.10031 s]
/proc/loadavg: 0.88 0.93 0.90 2/61 23679
/proc/meminfo: memFree=332440/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=0.03
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 694 2807 0 0 0 0 3 0 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909999168 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
[pid=23679] ppid=23666 vsize=93028 CPUtime=2.98
/proc/23679/stat : 23679 (cudf2lp) R 23666 23666 1733 0 -1 4202496 26939 0 0 0 285 13 0 0 20 0 1 0 115938601 95260672 20212 18446744073709551615 4194304 5690517 140733216552480 140733216550120 4367140 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/23679/statm: 23257 20212 160 366 0 22888 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.88 0.93 0.90 2/61 23680
/proc/meminfo: memFree=337524/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=4.61
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 722 42127 0 0 0 1 436 24 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909999168 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
[pid=23680] ppid=23666 vsize=45084 CPUtime=1.57
/proc/23680/stat : 23680 (gringo) R 23666 23666 1733 0 -1 4202496 12512 0 0 0 149 8 0 0 20 0 1 0 115939069 46166016 9379 18446744073709551615 4194304 6531320 140737170619648 140737170615464 5514265 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23680/statm: 11271 9379 259 571 0 10692 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 54296

[startup+12.7003 s]
/proc/loadavg: 0.89 0.93 0.90 2/61 23680
/proc/meminfo: memFree=37408/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=12
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 762 142551 0 0 0 1 1119 80 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909998576 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 12
Current children cumulated vsize (KiB) 9212

[startup+25.5004 s]
/proc/loadavg: 0.91 0.94 0.90 2/62 23682
/proc/meminfo: memFree=247460/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=12
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 762 142551 0 0 0 1 1119 80 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909998576 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
[pid=23681] ppid=23666 vsize=126556 CPUtime=13.1
/proc/23681/stat : 23681 (unclasp) R 23666 23666 1733 0 -1 4202496 36919 0 0 0 1296 14 0 0 20 0 1 0 115939822 129593344 30971 18446744073709551615 4194304 6012874 140736994543680 140736994543000 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23681/statm: 31639 30971 226 444 0 31187 0
[pid=23682] ppid=23666 vsize=22040 CPUtime=0.02
/proc/23682/stat : 23682 (parse.py) S 23666 23666 1733 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 115939822 22568960 1129 18446744073709551615 4194304 6642060 140736114412896 140736114411224 140651885184800 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23682/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.12
Current children cumulated vsize (KiB) 157808

[startup+51.1005 s]
/proc/loadavg: 1.00 0.96 0.91 2/62 23682
/proc/meminfo: memFree=246468/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=12
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 762 142551 0 0 0 1 1119 80 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909998576 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
[pid=23681] ppid=23666 vsize=126556 CPUtime=38.43
/proc/23681/stat : 23681 (unclasp) R 23666 23666 1733 0 -1 4202496 37243 0 0 0 3827 16 0 0 20 0 1 0 115939822 129593344 31295 18446744073709551615 4194304 6012874 140736994543680 140736994543000 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23681/statm: 31639 31295 226 444 0 31187 0
[pid=23682] ppid=23666 vsize=22040 CPUtime=0.02
/proc/23682/stat : 23682 (parse.py) S 23666 23666 1733 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 115939822 22568960 1129 18446744073709551615 4194304 6642060 140736114412896 140736114411224 140651885184800 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23682/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.45
Current children cumulated vsize (KiB) 157808

[startup+102.3 s]
/proc/loadavg: 1.00 0.96 0.91 2/62 23682
/proc/meminfo: memFree=223404/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=12
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 762 142551 0 0 0 1 1119 80 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909998576 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
[pid=23681] ppid=23666 vsize=151084 CPUtime=89.23
/proc/23681/stat : 23681 (unclasp) R 23666 23666 1733 0 -1 4202496 43006 0 0 0 8903 20 0 0 20 0 1 0 115939822 154710016 37058 18446744073709551615 4194304 6012874 140736994543680 140736994543000 4532853 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23681/statm: 37771 37058 227 444 0 37319 0
[pid=23682] ppid=23666 vsize=22040 CPUtime=0.02
/proc/23682/stat : 23682 (parse.py) S 23666 23666 1733 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 115939822 22568960 1129 18446744073709551615 4194304 6642060 140736114412896 140736114411224 140651885184800 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23682/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.25
Current children cumulated vsize (KiB) 182336



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.5 s]
/proc/loadavg: 1.05 0.98 0.91 2/62 23690
/proc/meminfo: memFree=168224/1022884 swapFree=0/0
[pid=23666] ppid=23665 vsize=9212 CPUtime=12
/proc/23666/stat : 23666 (aspuncud-basic) S 23665 23666 1733 0 -1 4202496 762 142551 0 0 0 1 1119 80 20 0 1 0 115938598 9433088 364 18446744073709551615 4194304 5129932 140734910000512 140734909998576 140163842479198 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23666/statm: 2303 364 303 229 0 63 0
[pid=23681] ppid=23666 vsize=207564 CPUtime=138.03
/proc/23681/stat : 23681 (unclasp) R 23666 23666 1733 0 -1 4202496 56643 0 0 0 13775 28 0 0 20 0 1 0 115939822 212545536 50695 18446744073709551615 4194304 6012874 140736994543680 140736994543000 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23681/statm: 51891 50695 227 444 0 51439 0
[pid=23682] ppid=23666 vsize=22040 CPUtime=0.02
/proc/23682/stat : 23682 (parse.py) S 23666 23666 1733 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 115939822 22568960 1129 18446744073709551615 4194304 6642060 140736114412896 140736114411224 140651885184800 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23682/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 238816

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.533
CPU time (s): 150.109
CPU user time (s): 148.973
CPU system time (s): 1.13607
CPU usage (%): 99.0608
Max. virtual memory (cumulated for all children) (KiB): 430348

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.973
system time used= 1.13607
maximum resident set size= 364564
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 201563
page faults= 0
swaps= 0
block input operations= 68440
block output operations= 48328
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 73
involuntary context switches= 17170

runsolver used 0.348021 second user time and 0.568035 second system time

The end