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/rand954.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand954.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/install/rand954.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.95 0.93 0.96 2/64 5396
/proc/meminfo: memFree=201848/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=3152 CPUtime=0
/proc/5396/stat : 5396 (runsolver) D 5395 5396 1745 0 -1 4202560 75 0 0 0 0 0 0 0 20 0 1 0 115708186 3227648 96 18446744073709551615 134512640 134586868 4292379792 4292377840 4151653424 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5396/statm: 788 96 64 19 0 73 0

[startup+0.127668 s]
/proc/loadavg: 0.95 0.93 0.96 2/64 5396
/proc/meminfo: memFree=201848/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9204 CPUtime=0.04
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 626 2750 4 5 0 0 2 2 20 0 1 0 115708186 9424896 359 18446744073709551615 4194304 5129932 140735696020016 140735696017480 139955415820064 0 0 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2301 359 300 229 0 61 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9204

[startup+0.200368 s]
/proc/loadavg: 0.95 0.93 0.96 2/64 5396
/proc/meminfo: memFree=201848/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=0.05
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 726 3604 4 8 0 0 3 2 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018672 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300321 s]
/proc/loadavg: 0.95 0.93 0.96 2/64 5396
/proc/meminfo: memFree=201848/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=0.05
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 726 3604 4 8 0 0 3 2 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018672 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700229 s]
/proc/loadavg: 0.95 0.93 0.96 2/64 5396
/proc/meminfo: memFree=201848/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=0.05
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 726 3604 4 8 0 0 3 2 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018672 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.95 0.93 0.96 2/66 5412
/proc/meminfo: memFree=167724/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=0.05
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 726 3604 4 8 0 0 3 2 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018672 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5412] ppid=5396 vsize=29880 CPUtime=1.26
/proc/5412/stat : 5412 (cudf2lp) R 5396 5396 1745 0 -1 4202496 8788 0 16 0 122 4 0 0 20 0 1 0 115708201 30597120 7071 18446744073709551615 4194304 5690517 140734334928912 140734334926552 4293680 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/5412/statm: 7470 7071 159 366 0 7101 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 39092

[startup+3.10032 s]
/proc/loadavg: 0.95 0.93 0.96 2/66 5412
/proc/meminfo: memFree=135980/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=0.05
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 726 3604 4 8 0 0 3 2 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018672 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5412] ppid=5396 vsize=101724 CPUtime=2.83
/proc/5412/stat : 5412 (cudf2lp) R 5396 5396 1745 0 -1 4202496 24589 0 16 0 274 9 0 0 20 0 1 0 115708201 104165376 21207 18446744073709551615 4194304 5690517 140734334928912 140734334925080 4371301 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/5412/statm: 25431 21207 160 366 0 25062 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 110936

[startup+6.30031 s]
/proc/loadavg: 0.95 0.94 0.96 2/66 5413
/proc/meminfo: memFree=145528/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=4.95
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 752 42908 4 24 0 0 468 27 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018672 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5413] ppid=5396 vsize=30528 CPUtime=1.02
/proc/5413/stat : 5413 (gringo) R 5396 5396 1745 0 -1 4202496 8634 0 22 0 98 4 0 0 20 0 1 0 115708706 31260672 6548 18446744073709551615 4194304 6531320 140736641267392 140736641264008 5507400 0 0 16781316 16386 0 0 0 17 0 0 0 6 0 0
/proc/5413/statm: 7632 6548 259 571 0 7053 0
Current children cumulated CPU time (s) 5.97
Current children cumulated vsize (KiB) 39740

[startup+12.7002 s]
/proc/loadavg: 0.95 0.94 0.96 2/66 5413
/proc/meminfo: memFree=12624/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=11.89
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 792 141789 4 47 0 0 1106 83 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018080 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 11.89
Current children cumulated vsize (KiB) 9212

[startup+25.5004 s]
/proc/loadavg: 0.96 0.94 0.96 2/67 5415
/proc/meminfo: memFree=238680/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=11.89
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 792 141789 4 47 0 0 1106 83 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018080 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5414] ppid=5396 vsize=127804 CPUtime=12.7
/proc/5414/stat : 5414 (clasp) R 5396 5396 1745 0 -1 4202496 37285 0 22 0 1256 14 0 0 20 0 1 0 115709429 130871296 31383 18446744073709551615 4194304 6238623 140735889104976 140735889102000 4685844 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/5414/statm: 31951 31383 263 500 0 31448 0
[pid=5415] ppid=5396 vsize=22040 CPUtime=0.02
/proc/5415/stat : 5415 (parse.py) S 5396 5396 1745 0 -1 4202496 1302 0 15 0 0 2 0 0 20 0 1 0 115709429 22568960 1127 18446744073709551615 4194304 6642060 140737180158320 140737180156680 139835326891808 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/5415/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 24.61
Current children cumulated vsize (KiB) 159056

[startup+51.1003 s]
/proc/loadavg: 0.98 0.94 0.96 2/67 5423
/proc/meminfo: memFree=237812/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=11.89
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 792 141789 4 47 0 0 1106 83 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018080 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5414] ppid=5396 vsize=127804 CPUtime=38.02
/proc/5414/stat : 5414 (clasp) R 5396 5396 1745 0 -1 4202496 37285 0 22 0 3788 14 0 0 20 0 1 0 115709429 130871296 31383 18446744073709551615 4194304 6238623 140735889104976 140735889102000 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/5414/statm: 31951 31383 263 500 0 31448 0
[pid=5415] ppid=5396 vsize=22040 CPUtime=0.02
/proc/5415/stat : 5415 (parse.py) S 5396 5396 1745 0 -1 4202496 1302 0 15 0 0 2 0 0 20 0 1 0 115709429 22568960 1127 18446744073709551615 4194304 6642060 140737180158320 140737180156680 139835326891808 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/5415/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 49.93
Current children cumulated vsize (KiB) 159056

[startup+102.3 s]
/proc/loadavg: 0.99 0.95 0.96 2/67 5423
/proc/meminfo: memFree=222560/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=11.89
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 792 141789 4 47 0 0 1106 83 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018080 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5414] ppid=5396 vsize=142512 CPUtime=88.76
/proc/5414/stat : 5414 (clasp) R 5396 5396 1745 0 -1 4202496 41171 0 22 0 8860 16 0 0 20 0 1 0 115709429 145932288 35269 18446744073709551615 4194304 6238623 140735889104976 140735889101528 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/5414/statm: 35628 35269 263 500 0 35125 0
[pid=5415] ppid=5396 vsize=22040 CPUtime=0.02
/proc/5415/stat : 5415 (parse.py) S 5396 5396 1745 0 -1 4202496 1302 0 15 0 0 2 0 0 20 0 1 0 115709429 22568960 1127 18446744073709551615 4194304 6642060 140737180158320 140737180156680 139835326891808 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/5415/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 100.67
Current children cumulated vsize (KiB) 173764



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+152.2 s]
/proc/loadavg: 0.99 0.95 0.96 2/67 5423
/proc/meminfo: memFree=175936/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=11.89
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 792 141789 4 47 0 0 1106 83 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018080 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5414] ppid=5396 vsize=190620 CPUtime=138.18
/proc/5414/stat : 5414 (clasp) R 5396 5396 1745 0 -1 4202496 52777 0 22 0 13796 22 0 0 20 0 1 0 115709429 195194880 46875 18446744073709551615 4194304 6238623 140735889104976 140735889101528 4355569 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/5414/statm: 47655 46875 263 500 0 47152 0
[pid=5415] ppid=5396 vsize=22040 CPUtime=0.02
/proc/5415/stat : 5415 (parse.py) S 5396 5396 1745 0 -1 4202496 1302 0 15 0 0 2 0 0 20 0 1 0 115709429 22568960 1127 18446744073709551615 4194304 6642060 140737180158320 140737180156680 139835326891808 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/5415/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 221872

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+152.2 s]
/proc/loadavg: 0.99 0.95 0.96 2/67 5423
/proc/meminfo: memFree=175936/1022884 swapFree=0/0
[pid=5396] ppid=5395 vsize=9212 CPUtime=11.89
/proc/5396/stat : 5396 (aspcud-basic) S 5395 5396 1745 0 -1 4202496 792 141789 4 47 0 0 1106 83 20 0 1 0 115708186 9433088 364 18446744073709551615 4194304 5129932 140735696020016 140735696018080 139955415675998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/5396/statm: 2303 364 303 229 0 63 0
[pid=5414] ppid=5396 vsize=190620 CPUtime=138.18
/proc/5414/stat : 5414 (clasp) R 5396 5396 1745 0 -1 4202496 52777 0 22 0 13796 22 0 0 20 0 1 0 115709429 195194880 46875 18446744073709551615 4194304 6238623 140735889104976 140735889101528 4355569 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/5414/statm: 47655 46875 263 500 0 47152 0
[pid=5415] ppid=5396 vsize=22040 CPUtime=0.02
/proc/5415/stat : 5415 (parse.py) S 5396 5396 1745 0 -1 4202496 1302 0 15 0 0 2 0 0 20 0 1 0 115709429 22568960 1127 18446744073709551615 4194304 6642060 140737180158320 140737180156680 139835326891808 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/5415/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 221872

Child status: 0
Real time (s): 152.262
CPU time (s): 150.173
CPU user time (s): 149.045
CPU system time (s): 1.12807
CPU usage (%): 98.6281
Max. virtual memory (cumulated for all children) (KiB): 420792

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.045
system time used= 1.12807
maximum resident set size= 358484
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 196959
page faults= 89
swaps= 0
block input operations= 81768
block output operations= 47792
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 183
involuntary context switches= 17373

runsolver used 0.336021 second user time and 0.772048 second system time

The end