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


[startup+0 s]
/proc/loadavg: 0.85 0.83 0.52 2/60 3277
/proc/meminfo: memFree=420792/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9176 CPUtime=0
/proc/3277/stat : 3277 (aspcud-basic) R 3276 3277 1750 0 -1 4202496 407 0 0 0 0 0 0 0 20 0 1 0 115186012 9396224 315 18446744073709551615 4194304 5129932 140736687897504 140736687892504 4911939 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2294 315 262 229 0 54 0

[startup+0.117523 s]
/proc/loadavg: 0.85 0.83 0.52 2/60 3277
/proc/meminfo: memFree=420792/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=0.05
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 736 3618 0 0 0 0 4 1 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.20032 s]
/proc/loadavg: 0.85 0.83 0.52 2/60 3277
/proc/meminfo: memFree=420792/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=0.05
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 736 3618 0 0 0 0 4 1 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300303 s]
/proc/loadavg: 0.85 0.83 0.52 2/60 3277
/proc/meminfo: memFree=420792/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=0.05
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 736 3618 0 0 0 0 4 1 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700225 s]
/proc/loadavg: 0.85 0.83 0.52 2/60 3277
/proc/meminfo: memFree=420792/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=0.05
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 736 3618 0 0 0 0 4 1 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.86 0.83 0.52 2/62 3293
/proc/meminfo: memFree=385676/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=0.05
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 736 3618 0 0 0 0 4 1 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3293] ppid=3277 vsize=51528 CPUtime=1.4
/proc/3293/stat : 3293 (cudf2lp) R 3277 3277 1750 0 -1 4202496 11900 0 0 0 132 8 0 0 20 0 1 0 115186016 52764672 10167 18446744073709551615 4194304 5690517 140733410045760 140733410041928 4370991 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/3293/statm: 12882 10167 160 366 0 12513 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 60740

[startup+3.10033 s]
/proc/loadavg: 0.86 0.83 0.52 1/62 3293
/proc/meminfo: memFree=354676/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=0.05
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 736 3618 0 0 0 0 4 1 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3293] ppid=3277 vsize=93028 CPUtime=2.95
/proc/3293/stat : 3293 (cudf2lp) R 3277 3277 1750 0 -1 4202496 26447 0 0 0 279 16 0 0 20 0 1 0 115186016 95260672 19720 18446744073709551615 4194304 5690517 140733410045760 140733410043416 4804567 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/3293/statm: 23257 19720 160 366 0 22888 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 102240

[startup+6.30034 s]
/proc/loadavg: 0.86 0.83 0.52 2/62 3294
/proc/meminfo: memFree=364472/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=4.97
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 762 42938 0 0 0 0 468 29 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3294] ppid=3277 vsize=37876 CPUtime=1.18
/proc/3294/stat : 3294 (gringo) R 3277 3277 1750 0 -1 4202496 10522 0 0 0 110 8 0 0 20 0 1 0 115186523 38785024 7389 18446744073709551615 4194304 6531320 140734945247856 140734945244472 4373616 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3294/statm: 9469 7389 259 571 0 8890 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 47088

[startup+12.7003 s]
/proc/loadavg: 0.88 0.84 0.52 3/62 3294
/proc/meminfo: memFree=9472/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=4.97
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 762 42938 0 0 0 0 468 29 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687896160 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3294] ppid=3277 vsize=459624 CPUtime=7.43
/proc/3294/stat : 3294 (gringo) R 3277 3277 1750 0 -1 4202496 108182 0 0 0 696 47 0 0 20 0 1 0 115186523 470654976 98903 18446744073709551615 4194304 6531320 140734945247856 140734945244984 5502254 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3294/statm: 114906 98903 284 571 0 114327 0
Current children cumulated CPU time (s) 12.4
Current children cumulated vsize (KiB) 468836

[startup+25.5004 s]
/proc/loadavg: 0.90 0.84 0.53 2/63 3296
/proc/meminfo: memFree=265972/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=12.8
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 802 151124 0 0 0 0 1188 92 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687895568 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3295] ppid=3277 vsize=138948 CPUtime=12.26
/proc/3295/stat : 3295 (clasp) R 3277 3277 1750 0 -1 4202496 40582 0 0 0 1212 14 0 0 20 0 1 0 115187320 142282752 34409 18446744073709551615 4194304 6238623 140734741489200 140734741486224 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3295/statm: 34737 34409 264 500 0 34234 0
[pid=3296] ppid=3277 vsize=22040 CPUtime=0.02
/proc/3296/stat : 3296 (parse.py) S 3277 3277 1750 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 115187320 22568960 1129 18446744073709551615 4194304 6642060 140733857898224 140733857896584 140131608835872 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3296/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.08
Current children cumulated vsize (KiB) 170200

[startup+51.1004 s]
/proc/loadavg: 0.93 0.86 0.54 2/63 3296
/proc/meminfo: memFree=265972/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=12.8
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 802 151124 0 0 0 0 1188 92 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687895568 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3295] ppid=3277 vsize=138948 CPUtime=37.61
/proc/3295/stat : 3295 (clasp) R 3277 3277 1750 0 -1 4202496 40582 0 0 0 3747 14 0 0 20 0 1 0 115187320 142282752 34409 18446744073709551615 4194304 6238623 140734741489200 140734741486224 4331904 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3295/statm: 34737 34409 264 500 0 34234 0
[pid=3296] ppid=3277 vsize=22040 CPUtime=0.02
/proc/3296/stat : 3296 (parse.py) S 3277 3277 1750 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 115187320 22568960 1129 18446744073709551615 4194304 6642060 140733857898224 140733857896584 140131608835872 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3296/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.43
Current children cumulated vsize (KiB) 170200

[startup+102.3 s]
/proc/loadavg: 0.97 0.88 0.56 2/63 3296
/proc/meminfo: memFree=265848/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=12.8
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 802 151124 0 0 0 0 1188 92 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687895568 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3295] ppid=3277 vsize=138948 CPUtime=88.31
/proc/3295/stat : 3295 (clasp) R 3277 3277 1750 0 -1 4202496 40582 0 0 0 8817 14 0 0 20 0 1 0 115187320 142282752 34409 18446744073709551615 4194304 6238623 140734741489200 140734741486224 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3295/statm: 34737 34409 264 500 0 34234 0
[pid=3296] ppid=3277 vsize=22040 CPUtime=0.02
/proc/3296/stat : 3296 (parse.py) S 3277 3277 1750 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 115187320 22568960 1129 18446744073709551615 4194304 6642060 140733857898224 140733857896584 140131608835872 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3296/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.13
Current children cumulated vsize (KiB) 170200



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.7 s]
/proc/loadavg: 0.99 0.89 0.58 2/63 3296
/proc/meminfo: memFree=253200/1022884 swapFree=0/0
[pid=3277] ppid=3276 vsize=9212 CPUtime=12.8
/proc/3277/stat : 3277 (aspcud-basic) S 3276 3277 1750 0 -1 4202496 802 151124 0 0 0 0 1188 92 20 0 1 0 115186012 9433088 365 18446744073709551615 4194304 5129932 140736687897504 140736687895568 140079623976030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3277/statm: 2303 365 303 229 0 63 0
[pid=3295] ppid=3277 vsize=151728 CPUtime=137.24
/proc/3295/stat : 3295 (clasp) R 3277 3277 1750 0 -1 4202496 43762 0 0 0 13709 15 0 0 20 0 1 0 115187320 155369472 37589 18446744073709551615 4194304 6238623 140734741489200 140734741485752 4306659 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3295/statm: 37932 37589 264 500 0 37429 0
[pid=3296] ppid=3277 vsize=22040 CPUtime=0.02
/proc/3296/stat : 3296 (parse.py) S 3277 3277 1750 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 115187320 22568960 1129 18446744073709551615 4194304 6642060 140733857898224 140733857896584 140131608835872 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3296/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 182980

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.736
CPU time (s): 150.125
CPU user time (s): 149.005
CPU system time (s): 1.12007
CPU usage (%): 98.9384
Max. virtual memory (cumulated for all children) (KiB): 468836

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.005
system time used= 1.12007
maximum resident set size= 395612
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 197326
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 50352
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 89
involuntary context switches= 17234

runsolver used 0.284017 second user time and 0.848053 second system time

The end