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/install/rand547.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand547.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/install/rand547.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

[startup+0 s]
/proc/loadavg: 0.81 0.40 0.24 2/65 3095
/proc/meminfo: memFree=386996/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=3152 CPUtime=0
/proc/3095/stat : 3095 (runsolver) R 3094 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115134113 3227648 33 18446744073709551615 134512640 134586868 4288100624 4288098672 4151886896 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/3095/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.167051 s]
/proc/loadavg: 0.81 0.40 0.24 2/65 3095
/proc/meminfo: memFree=386996/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=0.03
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 710 3385 2 6 0 0 2 1 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650420144 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200379 s]
/proc/loadavg: 0.81 0.40 0.24 2/65 3095
/proc/meminfo: memFree=386996/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=0.03
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 737 3607 2 7 0 0 2 1 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650420144 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300303 s]
/proc/loadavg: 0.81 0.40 0.24 2/65 3095
/proc/meminfo: memFree=386996/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=0.03
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 737 3607 2 7 0 0 2 1 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650420144 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700189 s]
/proc/loadavg: 0.81 0.40 0.24 2/65 3095
/proc/meminfo: memFree=386996/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=0.03
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 737 3607 2 7 0 0 2 1 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650420144 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/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.81 0.40 0.24 1/67 3111
/proc/meminfo: memFree=353500/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=0.03
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 737 3607 2 7 0 0 2 1 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650420144 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3111] ppid=3095 vsize=33064 CPUtime=1.03
/proc/3111/stat : 3111 (cudf2lp) R 3095 3095 1745 0 -1 4202496 9498 0 1 0 97 6 0 0 20 0 1 0 115134130 33857536 7765 18446744073709551615 4194304 5690517 140736477672112 140736477669480 4293200 0 0 16781316 0 0 0 0 17 0 0 0 28 0 0
/proc/3111/statm: 8266 7765 160 366 0 7897 0
Current children cumulated CPU time (s) 1.06
Current children cumulated vsize (KiB) 42276

[startup+3.1003 s]
/proc/loadavg: 0.81 0.40 0.24 2/67 3111
/proc/meminfo: memFree=319772/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=0.03
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 737 3607 2 7 0 0 2 1 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650420144 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3111] ppid=3095 vsize=93028 CPUtime=2.53
/proc/3111/stat : 3111 (cudf2lp) R 3095 3095 1745 0 -1 4202496 26484 0 1 0 237 16 0 0 20 0 1 0 115134130 95260672 19757 18446744073709551615 4194304 5690517 140736477672112 140736477669752 4357157 0 0 16781316 0 0 0 0 17 0 0 0 37 0 0
/proc/3111/statm: 23257 19757 160 366 0 22888 0
Current children cumulated CPU time (s) 2.56
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.82 0.41 0.24 2/67 3112
/proc/meminfo: memFree=328824/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=4.48
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 763 42926 2 8 0 0 418 30 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650420144 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3112] ppid=3095 vsize=38672 CPUtime=1.24
/proc/3112/stat : 3112 (gringo) R 3095 3095 1745 0 -1 4202496 10684 0 0 0 118 6 0 0 20 0 1 0 115134617 39600128 7550 18446744073709551615 4194304 6531320 140736131186960 140736131183144 4403660 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3112/statm: 9668 7550 259 571 0 9089 0
Current children cumulated CPU time (s) 5.72
Current children cumulated vsize (KiB) 47884

[startup+12.7003 s]
/proc/loadavg: 0.84 0.42 0.24 2/68 3114
/proc/meminfo: memFree=265364/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=10.57
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 804 152411 2 8 0 0 974 83 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650419552 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3113] ppid=3095 vsize=141104 CPUtime=1.37
/proc/3113/stat : 3113 (clasp) R 3095 3095 1745 0 -1 4202496 40954 0 0 0 123 14 0 0 20 0 1 0 115135243 144490496 34749 18446744073709551615 4194304 6238623 140734409546272 140734409543568 4611489 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3113/statm: 35276 34749 253 500 0 34773 0
[pid=3114] ppid=3095 vsize=22040 CPUtime=0
/proc/3114/stat : 3114 (parse.py) S 3095 3095 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115135243 22568960 1127 18446744073709551615 4194304 6642060 140734095356992 140734095355352 140354342450976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3114/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 11.94
Current children cumulated vsize (KiB) 172356

[startup+25.5003 s]
/proc/loadavg: 0.87 0.45 0.25 2/68 3114
/proc/meminfo: memFree=268216/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=10.57
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 804 152411 2 8 0 0 974 83 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650419552 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3113] ppid=3095 vsize=141104 CPUtime=14.07
/proc/3113/stat : 3113 (clasp) R 3095 3095 1745 0 -1 4202496 41122 0 0 0 1393 14 0 0 20 0 1 0 115135243 144490496 34917 18446744073709551615 4194304 6238623 140734409546272 140734409543296 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3113/statm: 35276 34917 264 500 0 34773 0
[pid=3114] ppid=3095 vsize=22040 CPUtime=0
/proc/3114/stat : 3114 (parse.py) S 3095 3095 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115135243 22568960 1127 18446744073709551615 4194304 6642060 140734095356992 140734095355352 140354342450976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3114/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 24.64
Current children cumulated vsize (KiB) 172356

[startup+51.1003 s]
/proc/loadavg: 0.91 0.49 0.27 2/68 3114
/proc/meminfo: memFree=246268/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=10.57
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 804 152411 2 8 0 0 974 83 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650419552 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3113] ppid=3095 vsize=163048 CPUtime=39.47
/proc/3113/stat : 3113 (clasp) R 3095 3095 1745 0 -1 4202496 46601 0 0 0 3931 16 0 0 20 0 1 0 115135243 166961152 40396 18446744073709551615 4194304 6238623 140734409546272 140734409542824 4332816 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3113/statm: 40762 40396 264 500 0 40259 0
[pid=3114] ppid=3095 vsize=22040 CPUtime=0
/proc/3114/stat : 3114 (parse.py) S 3095 3095 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115135243 22568960 1127 18446744073709551615 4194304 6642060 140734095356992 140734095355352 140354342450976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3114/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.04
Current children cumulated vsize (KiB) 194300

[startup+102.3 s]
/proc/loadavg: 0.96 0.57 0.31 2/68 3114
/proc/meminfo: memFree=114208/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=10.57
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 804 152411 2 8 0 0 974 83 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650419552 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3113] ppid=3095 vsize=294888 CPUtime=90.3
/proc/3113/stat : 3113 (clasp) R 3095 3095 1745 0 -1 4202496 79520 0 0 0 9001 29 0 0 20 0 1 0 115135243 301965312 73315 18446744073709551615 4194304 6238623 140734409546272 140734409542824 4677363 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3113/statm: 73722 73315 264 500 0 73219 0
[pid=3114] ppid=3095 vsize=22040 CPUtime=0
/proc/3114/stat : 3114 (parse.py) S 3095 3095 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115135243 22568960 1127 18446744073709551615 4194304 6642060 140734095356992 140734095355352 140354342450976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3114/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 100.87
Current children cumulated vsize (KiB) 326140



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.904 s]
/proc/loadavg: 1.03 0.65 0.35 2/68 3122
/proc/meminfo: memFree=98336/1022884 swapFree=0/0
[pid=3095] ppid=3094 vsize=9212 CPUtime=10.57
/proc/3095/stat : 3095 (aspcud-basic) S 3094 3095 1745 0 -1 4202496 804 152411 2 8 0 0 974 83 20 0 1 0 115134113 9433088 365 18446744073709551615 4194304 5129932 140733650421488 140733650419552 140558255776862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3095/statm: 2303 365 303 229 0 63 0
[pid=3113] ppid=3095 vsize=310332 CPUtime=139.5
/proc/3113/stat : 3113 (clasp) R 3095 3095 1745 0 -1 4202496 83398 0 0 0 13920 30 0 0 20 0 1 0 115135243 317779968 77193 18446744073709551615 4194304 6238623 140734409546272 140734409542824 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3113/statm: 77583 77193 264 500 0 77080 0
[pid=3114] ppid=3095 vsize=22040 CPUtime=0
/proc/3114/stat : 3114 (parse.py) S 3095 3095 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115135243 22568960 1127 18446744073709551615 4194304 6642060 140734095356992 140734095355352 140354342450976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3114/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 150.07
Current children cumulated vsize (KiB) 341584

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.946
CPU time (s): 150.161
CPU user time (s): 148.969
CPU system time (s): 1.19207
CPU usage (%): 98.8252
Max. virtual memory (cumulated for all children) (KiB): 474800

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.969
system time used= 1.19207
maximum resident set size= 400804
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 238247
page faults= 10
swaps= 0
block input operations= 69208
block output operations= 50944
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 126
involuntary context switches= 17292

runsolver used 0.316019 second user time and 0.544034 second system time

The end