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/rand7.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand7.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-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.94 2/64 5456
/proc/meminfo: memFree=403268/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=3152 CPUtime=0
/proc/5456/stat : 5456 (runsolver) R 5455 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115742620 3227648 33 18446744073709551615 134512640 134586868 4292822128 4292820176 4151415856 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.111578 s]
/proc/loadavg: 0.87 0.93 0.94 2/64 5456
/proc/meminfo: memFree=403268/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=0.04
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 730 3609 0 0 0 0 3 1 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139193024 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200341 s]
/proc/loadavg: 0.87 0.93 0.94 2/64 5456
/proc/meminfo: memFree=403268/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=0.04
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 730 3609 0 0 0 0 3 1 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139193024 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300309 s]
/proc/loadavg: 0.87 0.93 0.94 2/64 5456
/proc/meminfo: memFree=403268/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=0.04
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 730 3609 0 0 0 0 3 1 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139193024 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.70022 s]
/proc/loadavg: 0.87 0.93 0.94 2/64 5456
/proc/meminfo: memFree=403268/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=0.04
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 730 3609 0 0 0 0 3 1 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139193024 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.87 0.93 0.94 2/66 5472
/proc/meminfo: memFree=378568/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=0.04
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 730 3609 0 0 0 0 3 1 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139193024 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5472] ppid=5456 vsize=50676 CPUtime=1.44
/proc/5472/stat : 5472 (cudf2lp) R 5456 5456 1745 0 -1 4202496 14155 0 0 0 140 4 0 0 20 0 1 0 115742624 51892224 10757 18446744073709551615 4194304 5690517 140733819712672 140733819710312 4804496 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/5472/statm: 12669 10757 160 366 0 12300 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 59888

[startup+3.10032 s]
/proc/loadavg: 0.87 0.93 0.94 2/66 5472
/proc/meminfo: memFree=356744/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=0.04
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 730 3609 0 0 0 0 3 1 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139193024 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5472] ppid=5456 vsize=93028 CPUtime=3.04
/proc/5472/stat : 5472 (cudf2lp) R 5456 5456 1745 0 -1 4202496 26642 0 0 0 292 12 0 0 20 0 1 0 115742624 95260672 19915 18446744073709551615 4194304 5690517 140733819712672 140733819710312 4970354 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/5472/statm: 23257 19915 160 366 0 22888 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 102240

[startup+6.30032 s]
/proc/loadavg: 0.88 0.93 0.94 2/66 5473
/proc/meminfo: memFree=375096/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=4.87
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 756 42930 0 0 0 0 462 25 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139193024 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5473] ppid=5456 vsize=43004 CPUtime=1.37
/proc/5473/stat : 5473 (gringo) R 5456 5456 1745 0 -1 4202496 11885 0 0 0 133 4 0 0 20 0 1 0 115743110 44036096 8752 18446744073709551615 4194304 6531320 140736659698480 140736659695096 5485010 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/5473/statm: 10751 8752 259 571 0 10172 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 52216

[startup+12.7004 s]
/proc/loadavg: 0.89 0.93 0.94 2/67 5475
/proc/meminfo: memFree=366284/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=11.93
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 796 143355 0 0 0 0 1114 79 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139192432 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5474] ppid=5456 vsize=117732 CPUtime=0.64
/proc/5474/stat : 5474 (clasp) R 5456 5456 1745 0 -1 4202496 32677 0 0 0 54 10 0 0 20 0 1 0 115743823 120557568 28492 18446744073709551615 4194304 6238623 140733242620656 140733242616152 4493160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5474/statm: 29433 28492 200 500 0 28930 0
[pid=5475] ppid=5456 vsize=22040 CPUtime=0.02
/proc/5475/stat : 5475 (parse.py) S 5456 5456 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115743823 22568960 1128 18446744073709551615 4194304 6642060 140733268817632 140733268815992 139927611324192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5475/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.59
Current children cumulated vsize (KiB) 148984

[startup+25.5004 s]
/proc/loadavg: 0.91 0.93 0.94 2/67 5475
/proc/meminfo: memFree=248608/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=11.93
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 796 143355 0 0 0 0 1114 79 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139192432 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5474] ppid=5456 vsize=130048 CPUtime=13.3
/proc/5474/stat : 5474 (clasp) R 5456 5456 1745 0 -1 4202496 38024 0 0 0 1317 13 0 0 20 0 1 0 115743823 133169152 31981 18446744073709551615 4194304 6238623 140733242620656 140733242617680 4687677 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5474/statm: 32512 31981 263 500 0 32009 0
[pid=5475] ppid=5456 vsize=22040 CPUtime=0.02
/proc/5475/stat : 5475 (parse.py) S 5456 5456 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115743823 22568960 1128 18446744073709551615 4194304 6642060 140733268817632 140733268815992 139927611324192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5475/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.25
Current children cumulated vsize (KiB) 161300

[startup+51.1003 s]
/proc/loadavg: 0.94 0.94 0.94 2/67 5475
/proc/meminfo: memFree=247864/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=11.93
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 796 143355 0 0 0 0 1114 79 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139192432 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5474] ppid=5456 vsize=130048 CPUtime=38.67
/proc/5474/stat : 5474 (clasp) R 5456 5456 1745 0 -1 4202496 38219 0 0 0 3854 13 0 0 20 0 1 0 115743823 133169152 32176 18446744073709551615 4194304 6238623 140733242620656 140733242617680 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5474/statm: 32512 32176 263 500 0 32009 0
[pid=5475] ppid=5456 vsize=22040 CPUtime=0.02
/proc/5475/stat : 5475 (parse.py) S 5456 5456 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115743823 22568960 1128 18446744073709551615 4194304 6642060 140733268817632 140733268815992 139927611324192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5475/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.62
Current children cumulated vsize (KiB) 161300

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.94 2/67 5475
/proc/meminfo: memFree=238688/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=11.93
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 796 143355 0 0 0 0 1114 79 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139192432 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5474] ppid=5456 vsize=139180 CPUtime=89.49
/proc/5474/stat : 5474 (clasp) R 5456 5456 1745 0 -1 4202496 40509 0 0 0 8934 15 0 0 20 0 1 0 115743823 142520320 34466 18446744073709551615 4194304 6238623 140733242620656 140733242617208 4687643 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5474/statm: 34795 34466 263 500 0 34292 0
[pid=5475] ppid=5456 vsize=22040 CPUtime=0.02
/proc/5475/stat : 5475 (parse.py) S 5456 5456 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115743823 22568960 1128 18446744073709551615 4194304 6642060 140733268817632 140733268815992 139927611324192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5475/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.44
Current children cumulated vsize (KiB) 170432



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.3 s]
/proc/loadavg: 0.99 0.95 0.94 2/67 5475
/proc/meminfo: memFree=196404/1022884 swapFree=0/0
[pid=5456] ppid=5455 vsize=9212 CPUtime=11.93
/proc/5456/stat : 5456 (aspcud-basic) S 5455 5456 1745 0 -1 4202496 796 143355 0 0 0 0 1114 79 20 0 1 0 115742620 9433088 364 18446744073709551615 4194304 5129932 140736139194368 140736139192432 140321018147934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5456/statm: 2303 364 303 229 0 63 0
[pid=5474] ppid=5456 vsize=181488 CPUtime=138.13
/proc/5474/stat : 5474 (clasp) R 5456 5456 1745 0 -1 4202496 51047 0 0 0 13793 20 0 0 20 0 1 0 115743823 185843712 45004 18446744073709551615 4194304 6238623 140733242620656 140733242617208 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5474/statm: 45372 45004 263 500 0 44869 0
[pid=5475] ppid=5456 vsize=22040 CPUtime=0.02
/proc/5475/stat : 5475 (parse.py) S 5456 5456 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115743823 22568960 1128 18446744073709551615 4194304 6642060 140733268817632 140733268815992 139927611324192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5475/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 212740

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.335
CPU time (s): 150.141
CPU user time (s): 149.105
CPU system time (s): 1.03606
CPU usage (%): 99.2109
Max. virtual memory (cumulated for all children) (KiB): 430348

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.105
system time used= 1.03606
maximum resident set size= 364568
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 196818
page faults= 0
swaps= 0
block input operations= 0
block output operations= 48344
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 60
involuntary context switches= 17248

runsolver used 0.32002 second user time and 0.604037 second system time

The end