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/rand290.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand290.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/install/rand290.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.00 0.02 0.11 2/60 20531
/proc/meminfo: memFree=64440/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9204 CPUtime=0
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 115119281 9424896 332 18446744073709551615 4194304 5129932 140737412217360 140737412214824 140002526115616 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/20531/statm: 2301 332 272 229 0 61 0

[startup+0.160506 s]
/proc/loadavg: 0.00 0.02 0.11 2/60 20531
/proc/meminfo: memFree=64440/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=0.03
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 737 3616 1 3 0 0 3 0 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412216016 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200252 s]
/proc/loadavg: 0.00 0.02 0.11 2/60 20531
/proc/meminfo: memFree=64440/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=0.03
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 737 3616 1 3 0 0 3 0 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412216016 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300247 s]
/proc/loadavg: 0.00 0.02 0.11 2/60 20531
/proc/meminfo: memFree=64440/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=0.03
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 737 3616 1 3 0 0 3 0 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412216016 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70019 s]
/proc/loadavg: 0.00 0.02 0.11 2/60 20531
/proc/meminfo: memFree=64440/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=0.03
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 737 3616 1 3 0 0 3 0 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412216016 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/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.00 0.02 0.11 2/62 20547
/proc/meminfo: memFree=9528/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=0.03
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 737 3616 1 3 0 0 3 0 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412216016 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20547] ppid=20531 vsize=50676 CPUtime=1.32
/proc/20547/stat : 20547 (cudf2lp) R 20531 20531 1733 0 -1 4202496 14924 0 0 0 127 5 0 0 20 0 1 0 115119294 51892224 11525 18446744073709551615 4194304 5690517 140736968705360 140736968703000 4293666 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/20547/statm: 12669 11525 160 366 0 12300 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 59888

[startup+3.1003 s]
/proc/loadavg: 0.00 0.02 0.11 2/62 20547
/proc/meminfo: memFree=19824/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=0.03
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 737 3616 1 3 0 0 3 0 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412216016 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20547] ppid=20531 vsize=139672 CPUtime=2.87
/proc/20547/stat : 20547 (cudf2lp) R 20531 20531 1733 0 -1 4202496 38881 0 0 0 275 12 0 0 20 0 1 0 115119294 143024128 32153 18446744073709551615 4194304 5690517 140736968705360 140736968702488 4253172 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/20547/statm: 34918 32153 168 366 0 34549 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 148884

[startup+6.30031 s]
/proc/loadavg: 0.08 0.03 0.11 2/62 20548
/proc/meminfo: memFree=86820/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=3.68
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 763 42937 1 3 0 0 348 20 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412216016 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20548] ppid=20531 vsize=95044 CPUtime=2.38
/proc/20548/stat : 20548 (gringo) R 20531 20531 1733 0 -1 4202496 25451 0 0 0 224 14 0 0 20 0 1 0 115119670 97325056 20269 18446744073709551615 4194304 6531320 140734364662656 140734364659272 4554880 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20548/statm: 23761 20269 280 571 0 23182 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 104256

[startup+12.7003 s]
/proc/loadavg: 0.16 0.05 0.12 2/63 20550
/proc/meminfo: memFree=268096/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=10.49
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 803 154435 1 3 0 0 974 75 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412215424 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20549] ppid=20531 vsize=144028 CPUtime=1.42
/proc/20549/stat : 20549 (clasp) R 20531 20531 1733 0 -1 4202496 41597 0 22 0 126 16 0 0 20 0 1 0 115120373 147484672 35443 18446744073709551615 4194304 6238623 140736663904256 140736663901280 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 32 0 0
/proc/20549/statm: 36007 35443 263 500 0 35504 0
[pid=20550] ppid=20531 vsize=22040 CPUtime=0.02
/proc/20550/stat : 20550 (parse.py) S 20531 20531 1733 0 -1 4202496 1305 0 15 0 1 1 0 0 20 0 1 0 115120373 22568960 1129 18446744073709551615 4194304 6642060 140736172470144 140736172468504 139885437564704 0 0 16777220 20994 0 0 0 17 0 0 0 38 0 0
/proc/20550/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 11.93
Current children cumulated vsize (KiB) 175280

[startup+25.5003 s]
/proc/loadavg: 0.34 0.09 0.13 2/63 20550
/proc/meminfo: memFree=271816/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=10.49
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 803 154435 1 3 0 0 974 75 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412215424 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20549] ppid=20531 vsize=144028 CPUtime=14.13
/proc/20549/stat : 20549 (clasp) R 20531 20531 1733 0 -1 4202496 41657 0 22 0 1397 16 0 0 20 0 1 0 115120373 147484672 35503 18446744073709551615 4194304 6238623 140736663904256 140736663901280 4413000 0 0 16781316 18946 0 0 0 17 0 0 0 32 0 0
/proc/20549/statm: 36007 35503 264 500 0 35504 0
[pid=20550] ppid=20531 vsize=22040 CPUtime=0.02
/proc/20550/stat : 20550 (parse.py) S 20531 20531 1733 0 -1 4202496 1305 0 15 0 1 1 0 0 20 0 1 0 115120373 22568960 1129 18446744073709551615 4194304 6642060 140736172470144 140736172468504 139885437564704 0 0 16777220 20994 0 0 0 17 0 0 0 38 0 0
/proc/20550/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 24.64
Current children cumulated vsize (KiB) 175280

[startup+51.1003 s]
/proc/loadavg: 0.57 0.16 0.15 2/63 20550
/proc/meminfo: memFree=261400/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=10.49
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 803 154435 1 3 0 0 974 75 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412215424 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20549] ppid=20531 vsize=153584 CPUtime=39.55
/proc/20549/stat : 20549 (clasp) R 20531 20531 1733 0 -1 4202496 44242 0 22 0 3937 18 0 0 20 0 1 0 115120373 157270016 38088 18446744073709551615 4194304 6238623 140736663904256 140736663900808 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 32 0 0
/proc/20549/statm: 38396 38088 264 500 0 37893 0
[pid=20550] ppid=20531 vsize=22040 CPUtime=0.02
/proc/20550/stat : 20550 (parse.py) S 20531 20531 1733 0 -1 4202496 1305 0 15 0 1 1 0 0 20 0 1 0 115120373 22568960 1129 18446744073709551615 4194304 6642060 140736172470144 140736172468504 139885437564704 0 0 16777220 20994 0 0 0 17 0 0 0 38 0 0
/proc/20550/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.06
Current children cumulated vsize (KiB) 184836

[startup+102.3 s]
/proc/loadavg: 0.87 0.31 0.20 2/63 20550
/proc/meminfo: memFree=125124/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=10.49
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 803 154435 1 3 0 0 974 75 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412215424 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20549] ppid=20531 vsize=289816 CPUtime=90.38
/proc/20549/stat : 20549 (clasp) R 20531 20531 1733 0 -1 4202496 78232 0 22 0 9004 34 0 0 20 0 1 0 115120373 296771584 72078 18446744073709551615 4194304 6238623 140736663904256 140736663900808 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 32 0 0
/proc/20549/statm: 72454 72078 264 500 0 71951 0
[pid=20550] ppid=20531 vsize=22040 CPUtime=0.02
/proc/20550/stat : 20550 (parse.py) S 20531 20531 1733 0 -1 4202496 1305 0 15 0 1 1 0 0 20 0 1 0 115120373 22568960 1129 18446744073709551615 4194304 6642060 140736172470144 140736172468504 139885437564704 0 0 16777220 20994 0 0 0 17 0 0 0 38 0 0
/proc/20550/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 100.89
Current children cumulated vsize (KiB) 321068



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.8 s]
/proc/loadavg: 0.94 0.41 0.24 2/63 20550
/proc/meminfo: memFree=103300/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=10.49
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 803 154435 1 3 0 0 974 75 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412215424 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20549] ppid=20531 vsize=311520 CPUtime=139.54
/proc/20549/stat : 20549 (clasp) R 20531 20531 1733 0 -1 4202496 83669 0 22 0 13917 37 0 0 20 0 1 0 115120373 318996480 77515 18446744073709551615 4194304 6238623 140736663904256 140736663900808 4684978 0 0 16781316 18946 0 0 0 17 0 0 0 32 0 0
/proc/20549/statm: 77880 77515 264 500 0 77377 0
[pid=20550] ppid=20531 vsize=22040 CPUtime=0.02
/proc/20550/stat : 20550 (parse.py) S 20531 20531 1733 0 -1 4202496 1305 0 15 0 1 1 0 0 20 0 1 0 115120373 22568960 1129 18446744073709551615 4194304 6642060 140736172470144 140736172468504 139885437564704 0 0 16777220 20994 0 0 0 17 0 0 0 38 0 0
/proc/20550/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 342772

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.8 s]
/proc/loadavg: 0.94 0.41 0.24 2/63 20550
/proc/meminfo: memFree=103300/1022884 swapFree=0/0
[pid=20531] ppid=20530 vsize=9212 CPUtime=10.49
/proc/20531/stat : 20531 (aspcud-basic) S 20530 20531 1733 0 -1 4202496 803 154435 1 3 0 0 974 75 20 0 1 0 115119281 9433088 365 18446744073709551615 4194304 5129932 140737412217360 140737412215424 140002525971550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20531/statm: 2303 365 303 229 0 63 0
[pid=20549] ppid=20531 vsize=311520 CPUtime=139.54
/proc/20549/stat : 20549 (clasp) R 20531 20531 1733 0 -1 4202496 83669 0 22 0 13917 37 0 0 20 0 1 0 115120373 318996480 77515 18446744073709551615 4194304 6238623 140736663904256 140736663900808 4684978 0 0 16781316 18946 0 0 0 17 0 0 0 32 0 0
/proc/20549/statm: 77880 77515 264 500 0 77377 0
[pid=20550] ppid=20531 vsize=22040 CPUtime=0.02
/proc/20550/stat : 20550 (parse.py) S 20531 20531 1733 0 -1 4202496 1305 0 15 0 1 1 0 0 20 0 1 0 115120373 22568960 1129 18446744073709551615 4194304 6642060 140736172470144 140736172468504 139885437564704 0 0 16777220 20994 0 0 0 17 0 0 0 38 0 0
/proc/20550/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 342772

Child status: 0
Real time (s): 151.919
CPU time (s): 150.185
CPU user time (s): 148.997
CPU system time (s): 1.18807
CPU usage (%): 98.8588
Max. virtual memory (cumulated for all children) (KiB): 479408

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.997
system time used= 1.18807
maximum resident set size= 408860
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 240530
page faults= 43
swaps= 0
block input operations= 74432
block output operations= 51984
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 147
involuntary context switches= 17507

runsolver used 0.288018 second user time and 0.512032 second system time

The end