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/install/rand208.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand208.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/install/rand208.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.87 0.96 0.97 2/56 9342
/proc/meminfo: memFree=385820/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9204 CPUtime=0
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 37524563 9424896 331 18446744073709551615 4194304 5129932 140735633834896 140735633832360 139847216580384 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2301 331 272 229 0 61 0

[startup+0.158714 s]
/proc/loadavg: 0.87 0.96 0.97 2/56 9342
/proc/meminfo: memFree=385820/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=0.04
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 738 3602 0 4 0 0 3 1 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633833552 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200284 s]
/proc/loadavg: 0.87 0.96 0.97 2/56 9342
/proc/meminfo: memFree=385820/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=0.04
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 738 3602 0 4 0 0 3 1 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633833552 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300286 s]
/proc/loadavg: 0.87 0.96 0.97 2/56 9342
/proc/meminfo: memFree=385820/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=0.04
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 738 3602 0 4 0 0 3 1 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633833552 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700251 s]
/proc/loadavg: 0.87 0.96 0.97 2/56 9342
/proc/meminfo: memFree=385820/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=0.04
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 738 3602 0 4 0 0 3 1 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633833552 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/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: 0.87 0.96 0.97 2/58 9358
/proc/meminfo: memFree=361244/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=0.04
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 738 3602 0 4 0 0 3 1 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633833552 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9358] ppid=9342 vsize=56412 CPUtime=1.42
/proc/9358/stat : 9358 (cudf2lp) R 9342 9342 32685 0 -1 4202496 13771 0 1 0 135 7 0 0 20 0 1 0 37524569 57765888 12039 18446744073709551615 4194304 5690517 140733891997600 140733891993768 4363496 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/9358/statm: 14103 12039 160 366 0 13734 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 65624

[startup+3.10029 s]
/proc/loadavg: 0.87 0.96 0.97 2/58 9358
/proc/meminfo: memFree=339420/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=0.04
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 738 3602 0 4 0 0 3 1 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633833552 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9358] ppid=9342 vsize=93028 CPUtime=3.01
/proc/9358/stat : 9358 (cudf2lp) R 9342 9342 32685 0 -1 4202496 26569 0 1 0 286 15 0 0 20 0 1 0 37524569 95260672 19843 18446744073709551615 4194304 5690517 140733891997600 140733891995240 4970735 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/9358/statm: 23257 19843 160 366 0 22888 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 102240

[startup+6.30029 s]
/proc/loadavg: 0.88 0.96 0.97 2/58 9359
/proc/meminfo: memFree=360376/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=4.91
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 765 42923 0 5 0 0 461 30 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633833552 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9359] ppid=9342 vsize=40568 CPUtime=1.31
/proc/9359/stat : 9359 (gringo) R 9342 9342 32685 0 -1 4202496 11335 0 1 0 126 5 0 0 20 0 1 0 37525058 41541632 8203 18446744073709551615 4194304 6531320 140736738539920 140736738536536 4364715 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/9359/statm: 10142 8203 259 571 0 9563 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 49780

[startup+12.7004 s]
/proc/loadavg: 0.89 0.96 0.97 2/59 9361
/proc/meminfo: memFree=330732/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=11.81
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 805 140613 0 6 0 0 1096 85 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633832960 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9360] ppid=9342 vsize=125828 CPUtime=0.73
/proc/9360/stat : 9360 (clasp) R 9342 9342 32685 0 -1 4202496 34677 0 0 0 65 8 0 0 20 0 1 0 37525756 128847872 30492 18446744073709551615 4194304 6238623 140736373334512 140736373332072 4788490 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9360/statm: 31457 30492 211 500 0 30954 0
[pid=9361] ppid=9342 vsize=22040 CPUtime=0.01
/proc/9361/stat : 9361 (parse.py) S 9342 9342 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37525756 22568960 1128 18446744073709551615 4194304 6642060 140734169903424 140734169901784 140434175047456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9361/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 157080

[startup+25.5004 s]
/proc/loadavg: 0.91 0.97 0.97 2/59 9361
/proc/meminfo: memFree=236120/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=11.81
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 805 140613 0 6 0 0 1096 85 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633832960 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9360] ppid=9342 vsize=126712 CPUtime=13.44
/proc/9360/stat : 9360 (clasp) R 9342 9342 32685 0 -1 4202496 37031 0 0 0 1335 9 0 0 20 0 1 0 37525756 129753088 31124 18446744073709551615 4194304 6238623 140736373334512 140736373331536 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9360/statm: 31678 31124 263 500 0 31175 0
[pid=9361] ppid=9342 vsize=22040 CPUtime=0.01
/proc/9361/stat : 9361 (parse.py) S 9342 9342 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37525756 22568960 1128 18446744073709551615 4194304 6642060 140734169903424 140734169901784 140434175047456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9361/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 157964

[startup+51.1003 s]
/proc/loadavg: 0.94 0.97 0.97 2/59 9361
/proc/meminfo: memFree=236120/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=11.81
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 805 140613 0 6 0 0 1096 85 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633832960 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9360] ppid=9342 vsize=126712 CPUtime=38.9
/proc/9360/stat : 9360 (clasp) R 9342 9342 32685 0 -1 4202496 37031 0 0 0 3881 9 0 0 20 0 1 0 37525756 129753088 31124 18446744073709551615 4194304 6238623 140736373334512 140736373331536 4332557 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9360/statm: 31678 31124 263 500 0 31175 0
[pid=9361] ppid=9342 vsize=22040 CPUtime=0.01
/proc/9361/stat : 9361 (parse.py) S 9342 9342 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37525756 22568960 1128 18446744073709551615 4194304 6642060 140734169903424 140734169901784 140434175047456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9361/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.72
Current children cumulated vsize (KiB) 157964

[startup+102.3 s]
/proc/loadavg: 0.97 0.97 0.97 2/59 9361
/proc/meminfo: memFree=146096/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=11.81
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 805 140613 0 6 0 0 1096 85 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633832960 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9360] ppid=9342 vsize=216324 CPUtime=89.81
/proc/9360/stat : 9360 (clasp) R 9342 9342 32685 0 -1 4202496 59522 0 0 0 8961 20 0 0 20 0 1 0 37525756 221515776 53615 18446744073709551615 4194304 6238623 140736373334512 140736373331064 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9360/statm: 54081 53615 263 500 0 53578 0
[pid=9361] ppid=9342 vsize=22040 CPUtime=0.01
/proc/9361/stat : 9361 (parse.py) S 9342 9342 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37525756 22568960 1128 18446744073709551615 4194304 6642060 140734169903424 140734169901784 140434175047456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9361/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.63
Current children cumulated vsize (KiB) 247576



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151 s]
/proc/loadavg: 0.99 0.97 0.97 2/59 9361
/proc/meminfo: memFree=122660/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=11.81
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 805 140613 0 6 0 0 1096 85 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633832960 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9360] ppid=9342 vsize=239664 CPUtime=138.19
/proc/9360/stat : 9360 (clasp) R 9342 9342 32685 0 -1 4202496 65357 0 0 0 13796 23 0 0 20 0 1 0 37525756 245415936 59450 18446744073709551615 4194304 6238623 140736373334512 140736373331160 4635676 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9360/statm: 59916 59450 263 500 0 59413 0
[pid=9361] ppid=9342 vsize=22040 CPUtime=0.01
/proc/9361/stat : 9361 (parse.py) S 9342 9342 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37525756 22568960 1128 18446744073709551615 4194304 6642060 140734169903424 140734169901784 140434175047456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9361/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.01
Current children cumulated vsize (KiB) 270916

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 s]
/proc/loadavg: 0.99 0.97 0.97 2/59 9361
/proc/meminfo: memFree=122660/1022884 swapFree=0/0
[pid=9342] ppid=9341 vsize=9212 CPUtime=11.81
/proc/9342/stat : 9342 (aspcud-basic) S 9341 9342 32685 0 -1 4202496 805 140613 0 6 0 0 1096 85 20 0 1 0 37524563 9433088 364 18446744073709551615 4194304 5129932 140735633834896 140735633832960 139847216436318 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9342/statm: 2303 364 303 229 0 63 0
[pid=9360] ppid=9342 vsize=239664 CPUtime=138.19
/proc/9360/stat : 9360 (clasp) R 9342 9342 32685 0 -1 4202496 65357 0 0 0 13796 23 0 0 20 0 1 0 37525756 245415936 59450 18446744073709551615 4194304 6238623 140736373334512 140736373331160 4635676 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9360/statm: 59916 59450 263 500 0 59413 0
[pid=9361] ppid=9342 vsize=22040 CPUtime=0.01
/proc/9361/stat : 9361 (parse.py) S 9342 9342 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37525756 22568960 1128 18446744073709551615 4194304 6642060 140734169903424 140734169901784 140434175047456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9361/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.01
Current children cumulated vsize (KiB) 270916

Child status: 0
Real time (s): 151.038
CPU time (s): 150.089
CPU user time (s): 148.945
CPU system time (s): 1.14407
CPU usage (%): 99.3722
Max. virtual memory (cumulated for all children) (KiB): 417676

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.945
system time used= 1.14407
maximum resident set size= 353632
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 208396
page faults= 6
swaps= 0
block input operations= 312
block output operations= 47440
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 68
involuntary context switches= 2540

runsolver used 0.188011 second user time and 0.736046 second system time

The end