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

[startup+0 s]
/proc/loadavg: 0.85 0.75 0.44 2/61 6560
/proc/meminfo: memFree=441968/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=3152 CPUtime=0
/proc/6560/stat : 6560 (runsolver) R 6559 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 36941861 3227648 32 18446744073709551615 134512640 134586868 4287482656 4287480704 4151383088 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.151503 s]
/proc/loadavg: 0.85 0.75 0.44 2/61 6560
/proc/meminfo: memFree=441968/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=0.04
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 679 3078 0 0 0 0 3 1 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494295024 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200328 s]
/proc/loadavg: 0.85 0.75 0.44 2/61 6560
/proc/meminfo: memFree=441968/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=0.04
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 732 3613 0 0 0 0 3 1 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494295024 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300302 s]
/proc/loadavg: 0.85 0.75 0.44 2/61 6560
/proc/meminfo: memFree=441968/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=0.04
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 732 3613 0 0 0 0 3 1 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494295024 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700196 s]
/proc/loadavg: 0.85 0.75 0.44 2/61 6560
/proc/meminfo: memFree=441968/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=0.04
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 732 3613 0 0 0 0 3 1 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494295024 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 0.85 0.75 0.44 2/63 6576
/proc/meminfo: memFree=404868/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=0.04
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 732 3613 0 0 0 0 3 1 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494295024 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6576] ppid=6560 vsize=50676 CPUtime=1.27
/proc/6576/stat : 6576 (cudf2lp) R 6560 6560 32685 0 -1 4202496 14489 0 0 0 123 4 0 0 20 0 1 0 36941880 51892224 11091 18446744073709551615 4194304 5690517 140736880398096 140736880395736 4357511 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/6576/statm: 12669 11091 160 366 0 12300 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 59888

[startup+3.10032 s]
/proc/loadavg: 0.86 0.76 0.44 2/63 6576
/proc/meminfo: memFree=366552/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=0.04
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 732 3613 0 0 0 0 3 1 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494295024 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6576] ppid=6560 vsize=93028 CPUtime=2.78
/proc/6576/stat : 6576 (cudf2lp) R 6560 6560 32685 0 -1 4202496 27244 0 0 0 270 8 0 0 20 0 1 0 36941880 95260672 20517 18446744073709551615 4194304 5690517 140736880398096 140736880395736 4328216 0 0 16781316 0 0 0 0 17 0 0 0 11 0 0
/proc/6576/statm: 23257 20517 160 366 0 22888 0
Current children cumulated CPU time (s) 2.82
Current children cumulated vsize (KiB) 102240

[startup+6.30027 s]
/proc/loadavg: 0.86 0.76 0.44 2/63 6577
/proc/meminfo: memFree=359980/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=4.14
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 758 42933 0 0 0 0 394 20 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494295024 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6577] ppid=6560 vsize=113356 CPUtime=1.86
/proc/6577/stat : 6577 (gringo) R 6560 6560 32685 0 -1 4202496 30099 0 0 0 178 8 0 0 20 0 1 0 36942303 116076544 24917 18446744073709551615 4194304 6531320 140737072192576 140737072189192 4358841 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6577/statm: 28339 24917 281 571 0 27760 0
Current children cumulated CPU time (s) 6
Current children cumulated vsize (KiB) 122568

[startup+12.7003 s]
/proc/loadavg: 0.88 0.77 0.45 2/64 6579
/proc/meminfo: memFree=275776/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=9.48
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 798 155001 0 0 0 0 886 62 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494294432 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6578] ppid=6560 vsize=145004 CPUtime=2.81
/proc/6578/stat : 6578 (clasp) R 6560 6560 32685 0 -1 4202496 41869 0 0 0 268 13 0 0 20 0 1 0 36942846 148484096 35681 18446744073709551615 4194304 6238623 140735310906080 140735310903104 4662328 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6578/statm: 36251 35681 263 500 0 35748 0
[pid=6579] ppid=6560 vsize=22040 CPUtime=0.01
/proc/6579/stat : 6579 (parse.py) S 6560 6560 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 36942846 22568960 1128 18446744073709551615 4194304 6642060 140734367776512 140734367774872 140502504167200 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6579/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.3
Current children cumulated vsize (KiB) 176256

[startup+25.5003 s]
/proc/loadavg: 0.90 0.77 0.45 2/64 6579
/proc/meminfo: memFree=275776/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=9.48
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 798 155001 0 0 0 0 886 62 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494294432 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6578] ppid=6560 vsize=145004 CPUtime=15.53
/proc/6578/stat : 6578 (clasp) R 6560 6560 32685 0 -1 4202496 41946 0 0 0 1540 13 0 0 20 0 1 0 36942846 148484096 35758 18446744073709551615 4194304 6238623 140735310906080 140735310903104 4355569 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6578/statm: 36251 35758 264 500 0 35748 0
[pid=6579] ppid=6560 vsize=22040 CPUtime=0.01
/proc/6579/stat : 6579 (parse.py) S 6560 6560 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 36942846 22568960 1128 18446744073709551615 4194304 6642060 140734367776512 140734367774872 140502504167200 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6579/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.02
Current children cumulated vsize (KiB) 176256

[startup+51.1003 s]
/proc/loadavg: 0.93 0.79 0.47 2/64 6579
/proc/meminfo: memFree=275528/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=9.48
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 798 155001 0 0 0 0 886 62 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494294432 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6578] ppid=6560 vsize=145004 CPUtime=41
/proc/6578/stat : 6578 (clasp) R 6560 6560 32685 0 -1 4202496 42038 0 0 0 4086 14 0 0 20 0 1 0 36942846 148484096 35850 18446744073709551615 4194304 6238623 140735310906080 140735310903104 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6578/statm: 36251 35850 264 500 0 35748 0
[pid=6579] ppid=6560 vsize=22040 CPUtime=0.01
/proc/6579/stat : 6579 (parse.py) S 6560 6560 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 36942846 22568960 1128 18446744073709551615 4194304 6642060 140734367776512 140734367774872 140502504167200 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6579/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.49
Current children cumulated vsize (KiB) 176256

[startup+102.3 s]
/proc/loadavg: 0.97 0.82 0.49 2/64 6579
/proc/meminfo: memFree=170128/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=9.48
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 798 155001 0 0 0 0 886 62 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494294432 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6578] ppid=6560 vsize=250480 CPUtime=91.91
/proc/6578/stat : 6578 (clasp) R 6560 6560 32685 0 -1 4202496 68345 0 0 0 9166 25 0 0 20 0 1 0 36942846 256491520 62157 18446744073709551615 4194304 6238623 140735310906080 140735310902632 4635539 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6578/statm: 62620 62157 264 500 0 62117 0
[pid=6579] ppid=6560 vsize=22040 CPUtime=0.01
/proc/6579/stat : 6579 (parse.py) S 6560 6560 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 36942846 22568960 1128 18446744073709551615 4194304 6642060 140734367776512 140734367774872 140502504167200 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6579/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.4
Current children cumulated vsize (KiB) 281732



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.2 s]
/proc/loadavg: 0.98 0.85 0.51 2/64 6579
/proc/meminfo: memFree=103664/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=9.48
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 798 155001 0 0 0 0 886 62 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494294432 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6578] ppid=6560 vsize=317164 CPUtime=140.55
/proc/6578/stat : 6578 (clasp) R 6560 6560 32685 0 -1 4202496 84902 0 0 0 14023 32 0 0 20 0 1 0 36942846 324775936 78714 18446744073709551615 4194304 6238623 140735310906080 140735310902632 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6578/statm: 79291 78714 264 500 0 78788 0
[pid=6579] ppid=6560 vsize=22040 CPUtime=0.01
/proc/6579/stat : 6579 (parse.py) S 6560 6560 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 36942846 22568960 1128 18446744073709551615 4194304 6642060 140734367776512 140734367774872 140502504167200 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6579/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.04
Current children cumulated vsize (KiB) 348416

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.2 s]
/proc/loadavg: 0.98 0.85 0.51 2/64 6579
/proc/meminfo: memFree=103664/1022884 swapFree=0/0
[pid=6560] ppid=6559 vsize=9212 CPUtime=9.48
/proc/6560/stat : 6560 (aspcud-basic) S 6559 6560 32685 0 -1 4202496 798 155001 0 0 0 0 886 62 20 0 1 0 36941861 9433088 365 18446744073709551615 4194304 5129932 140733494296368 140733494294432 140124173919326 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6560/statm: 2303 365 303 229 0 63 0
[pid=6578] ppid=6560 vsize=317164 CPUtime=140.55
/proc/6578/stat : 6578 (clasp) R 6560 6560 32685 0 -1 4202496 84902 0 0 0 14023 32 0 0 20 0 1 0 36942846 324775936 78714 18446744073709551615 4194304 6238623 140735310906080 140735310902632 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6578/statm: 79291 78714 264 500 0 78788 0
[pid=6579] ppid=6560 vsize=22040 CPUtime=0.01
/proc/6579/stat : 6579 (parse.py) S 6560 6560 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 36942846 22568960 1128 18446744073709551615 4194304 6642060 140734367776512 140734367774872 140502504167200 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6579/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.04
Current children cumulated vsize (KiB) 348416

Child status: 0
Real time (s): 151.24
CPU time (s): 150.113
CPU user time (s): 149.133
CPU system time (s): 0.980061
CPU usage (%): 99.255
Max. virtual memory (cumulated for all children) (KiB): 481504

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.133
system time used= 0.980061
maximum resident set size= 411140
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 242334
page faults= 0
swaps= 0
block input operations= 68560
block output operations= 52296
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 109
involuntary context switches= 2284

runsolver used 0.244015 second user time and 0.588036 second system time

The end