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/rand411.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand411.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/install/rand411.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.83 0.42 0.24 2/59 20557
/proc/meminfo: memFree=405892/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=1068 CPUtime=0
/proc/20557/stat : 20557 (aspcud-basic) D 20556 20557 1733 0 -1 4194304 75 0 0 0 0 0 0 0 20 0 1 0 115136172 1093632 1 18446744073709551615 0 0 140736629021666 4292541648 4151710768 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/20557/statm: 267 1 0 0 0 28 0

[startup+0.164587 s]
/proc/loadavg: 0.83 0.42 0.24 2/59 20557
/proc/meminfo: memFree=405892/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=0.05
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 737 3603 2 8 1 0 4 0 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013808 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200326 s]
/proc/loadavg: 0.83 0.42 0.24 2/59 20557
/proc/meminfo: memFree=405892/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=0.05
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 737 3603 2 8 1 0 4 0 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013808 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/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.83 0.42 0.24 2/59 20557
/proc/meminfo: memFree=405892/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=0.05
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 737 3603 2 8 1 0 4 0 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013808 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700203 s]
/proc/loadavg: 0.83 0.42 0.24 2/59 20557
/proc/meminfo: memFree=405892/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=0.05
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 737 3603 2 8 1 0 4 0 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013808 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.83 0.42 0.24 2/61 20573
/proc/meminfo: memFree=365700/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=0.05
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 737 3603 2 8 1 0 4 0 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013808 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20573] ppid=20557 vsize=50676 CPUtime=1.21
/proc/20573/stat : 20573 (cudf2lp) R 20557 20557 1733 0 -1 4202496 14415 0 1 0 115 6 0 0 20 0 1 0 115136183 51892224 11018 18446744073709551615 4194304 5690517 140735799738528 140735799736168 4293711 0 0 16781316 0 0 0 0 17 0 0 0 17 0 0
/proc/20573/statm: 12669 11018 160 366 0 12300 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 59888

[startup+3.10032 s]
/proc/loadavg: 0.83 0.42 0.24 1/61 20573
/proc/meminfo: memFree=334700/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=0.05
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 737 3603 2 8 1 0 4 0 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013808 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20573] ppid=20557 vsize=93028 CPUtime=2.36
/proc/20573/stat : 20573 (cudf2lp) R 20557 20557 1733 0 -1 4202496 26741 0 1 0 225 11 0 0 20 0 1 0 115136183 95260672 20015 18446744073709551615 4194304 5690517 140735799738528 140735799736168 4293647 0 0 16781316 0 0 0 0 17 0 0 0 61 0 0
/proc/20573/statm: 23257 20015 160 366 0 22888 0
Current children cumulated CPU time (s) 2.41
Current children cumulated vsize (KiB) 102240
heavy processes:

[startup+6.30026 s]
/proc/loadavg: 0.84 0.43 0.25 2/61 20574
/proc/meminfo: memFree=315728/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=3.68
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 764 42921 2 9 1 0 348 19 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013808 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20574] ppid=20557 vsize=129284 CPUtime=1.88
/proc/20574/stat : 20574 (gringo) R 20557 20557 1733 0 -1 4202496 33978 0 0 0 178 10 0 0 20 0 1 0 115136613 132386816 28796 18446744073709551615 4194304 6531320 140736567129344 140736567125688 4640386 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20574/statm: 32321 28796 280 571 0 31742 0
Current children cumulated CPU time (s) 5.56
Current children cumulated vsize (KiB) 138496

[startup+12.7004 s]
/proc/loadavg: 0.85 0.44 0.25 2/62 20576
/proc/meminfo: memFree=273592/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=9.29
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 805 153984 2 9 1 0 859 69 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013216 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20575] ppid=20557 vsize=143360 CPUtime=2.44
/proc/20575/stat : 20575 (clasp) R 20557 20557 1733 0 -1 4202496 41439 0 0 0 228 16 0 0 20 0 1 0 115137193 146800640 35276 18446744073709551615 4194304 6238623 140735605183616 140735605180640 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20575/statm: 35840 35276 263 500 0 35337 0
[pid=20576] ppid=20557 vsize=22040 CPUtime=0.02
/proc/20576/stat : 20576 (parse.py) S 20557 20557 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115137193 22568960 1128 18446744073709551615 4194304 6642060 140734993018640 140734993017000 139658327201568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 11.75
Current children cumulated vsize (KiB) 174612

[startup+25.5004 s]
/proc/loadavg: 0.96 0.48 0.27 2/62 20576
/proc/meminfo: memFree=273592/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=9.29
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 805 153984 2 9 1 0 859 69 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013216 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20575] ppid=20557 vsize=143360 CPUtime=15.12
/proc/20575/stat : 20575 (clasp) R 20557 20557 1733 0 -1 4202496 41491 0 0 0 1496 16 0 0 20 0 1 0 115137193 146800640 35328 18446744073709551615 4194304 6238623 140735605183616 140735605180640 4306765 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20575/statm: 35840 35328 263 500 0 35337 0
[pid=20576] ppid=20557 vsize=22040 CPUtime=0.02
/proc/20576/stat : 20576 (parse.py) S 20557 20557 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115137193 22568960 1128 18446744073709551615 4194304 6642060 140734993018640 140734993017000 139658327201568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.43
Current children cumulated vsize (KiB) 174612

[startup+51.1004 s]
/proc/loadavg: 0.97 0.52 0.29 2/62 20576
/proc/meminfo: memFree=272972/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=9.29
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 805 153984 2 9 1 0 859 69 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013216 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20575] ppid=20557 vsize=143360 CPUtime=40.47
/proc/20575/stat : 20575 (clasp) R 20557 20557 1733 0 -1 4202496 41676 0 0 0 4031 16 0 0 20 0 1 0 115137193 146800640 35513 18446744073709551615 4194304 6238623 140735605183616 140735605180640 4687800 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20575/statm: 35840 35513 264 500 0 35337 0
[pid=20576] ppid=20557 vsize=22040 CPUtime=0.02
/proc/20576/stat : 20576 (parse.py) S 20557 20557 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115137193 22568960 1128 18446744073709551615 4194304 6642060 140734993018640 140734993017000 139658327201568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 49.78
Current children cumulated vsize (KiB) 174612

[startup+102.3 s]
/proc/loadavg: 0.99 0.59 0.32 2/62 20576
/proc/meminfo: memFree=230440/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=9.29
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 805 153984 2 9 1 0 859 69 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013216 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20575] ppid=20557 vsize=185684 CPUtime=91.2
/proc/20575/stat : 20575 (clasp) R 20557 20557 1733 0 -1 4202496 52268 0 0 0 9098 22 0 0 20 0 1 0 115137193 190140416 46105 18446744073709551615 4194304 6238623 140735605183616 140735605180168 4669499 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20575/statm: 46421 46105 264 500 0 45918 0
[pid=20576] ppid=20557 vsize=22040 CPUtime=0.02
/proc/20576/stat : 20576 (parse.py) S 20557 20557 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115137193 22568960 1128 18446744073709551615 4194304 6642060 140734993018640 140734993017000 139658327201568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 100.51
Current children cumulated vsize (KiB) 216936



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+152.3 s]
/proc/loadavg: 0.99 0.65 0.36 2/62 20576
/proc/meminfo: memFree=170424/1022884 swapFree=0/0
[pid=20557] ppid=20556 vsize=9212 CPUtime=9.29
/proc/20557/stat : 20557 (aspcud-basic) S 20556 20557 1733 0 -1 4202496 805 153984 2 9 1 0 859 69 20 0 1 0 115136172 9433088 365 18446744073709551615 4194304 5129932 140736629015152 140736629013216 139799113692254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/20557/statm: 2303 365 303 229 0 63 0
[pid=20575] ppid=20557 vsize=245524 CPUtime=140.72
/proc/20575/stat : 20575 (clasp) R 20557 20557 1733 0 -1 4202496 67230 0 0 0 14044 28 0 0 20 0 1 0 115137193 251416576 61067 18446744073709551615 4194304 6238623 140735605183616 140735605180168 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20575/statm: 61381 61067 264 500 0 60878 0
[pid=20576] ppid=20557 vsize=22040 CPUtime=0.02
/proc/20576/stat : 20576 (parse.py) S 20557 20557 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 115137193 22568960 1128 18446744073709551615 4194304 6642060 140734993018640 140734993017000 139658327201568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.03
Current children cumulated vsize (KiB) 276776

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): 152.334
CPU time (s): 150.093
CPU user time (s): 149.081
CPU system time (s): 1.01206
CPU usage (%): 98.5289
Max. virtual memory (cumulated for all children) (KiB): 478752

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.081
system time used= 1.01206
maximum resident set size= 407120
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 223655
page faults= 11
swaps= 0
block input operations= 69456
block output operations= 51688
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 153
involuntary context switches= 17235

runsolver used 0.364022 second user time and 0.732045 second system time

The end