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 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/install/rand943.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand943.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/install/rand943.cudf.result -count(down),-notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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.79 0.27 0.09 2/65 8650
/proc/meminfo: memFree=530228/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=3152 CPUtime=0
/proc/8650/stat : 8650 (runsolver) R 8649 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117047710 3227648 33 18446744073709551615 134512640 134586868 4288377328 4288375376 4151673904 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.146515 s]
/proc/loadavg: 0.79 0.27 0.09 2/65 8650
/proc/meminfo: memFree=530228/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=0.02
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 734 3617 0 0 0 0 2 0 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713984 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200319 s]
/proc/loadavg: 0.79 0.27 0.09 2/65 8650
/proc/meminfo: memFree=530228/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=0.02
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 734 3617 0 0 0 0 2 0 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713984 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300301 s]
/proc/loadavg: 0.79 0.27 0.09 2/65 8650
/proc/meminfo: memFree=530228/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=0.02
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 734 3617 0 0 0 0 2 0 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713984 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700242 s]
/proc/loadavg: 0.79 0.27 0.09 2/65 8650
/proc/meminfo: memFree=530228/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=0.02
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 734 3617 0 0 0 0 2 0 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713984 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.79 0.27 0.09 2/67 8666
/proc/meminfo: memFree=488912/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=0.02
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 734 3617 0 0 0 0 2 0 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713984 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8666] ppid=8650 vsize=53760 CPUtime=1.43
/proc/8666/stat : 8666 (cudf2lp) R 8650 8650 1745 0 -1 4202496 15294 0 0 0 136 7 0 0 20 0 1 0 117047712 55050240 11896 18446744073709551615 4194304 5690517 140734320306704 140734320304344 4361408 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/8666/statm: 13440 11896 160 366 0 13071 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 62972

[startup+3.10026 s]
/proc/loadavg: 0.79 0.27 0.09 2/67 8666
/proc/meminfo: memFree=418604/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=0.02
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 734 3617 0 0 0 0 2 0 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713984 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8666] ppid=8650 vsize=133508 CPUtime=3
/proc/8666/stat : 8666 (cudf2lp) R 8650 8650 1745 0 -1 4202496 37328 0 0 0 286 14 0 0 20 0 1 0 117047712 136712192 30601 18446744073709551615 4194304 5690517 140734320306704 140734320303832 4269102 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/8666/statm: 33377 30601 168 366 0 33008 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 142720

[startup+6.30025 s]
/proc/loadavg: 0.81 0.28 0.10 2/67 8667
/proc/meminfo: memFree=427656/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=4.05
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 760 44896 0 0 0 0 382 23 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713984 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8667] ppid=8650 vsize=132140 CPUtime=2.16
/proc/8667/stat : 8667 (gringo) R 8650 8650 1745 0 -1 4202496 34059 0 0 0 200 16 0 0 20 0 1 0 117048122 135311360 27852 18446744073709551615 4194304 6531320 140737183424944 140737183421560 5058534 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/8667/statm: 33035 27852 279 571 0 32456 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 141352

[startup+12.7003 s]
/proc/loadavg: 0.82 0.29 0.10 2/68 8669
/proc/meminfo: memFree=324852/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=1.74
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49418 0 0 0 162 12 0 0 20 0 1 0 117048802 170700800 40847 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40847 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 197952

[startup+25.5003 s]
/proc/loadavg: 0.86 0.33 0.12 2/68 8669
/proc/meminfo: memFree=324728/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=14.44
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49452 0 0 0 1431 13 0 0 20 0 1 0 117048802 170700800 40881 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40881 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 197952

[startup+51.1003 s]
/proc/loadavg: 0.91 0.38 0.14 2/68 8669
/proc/meminfo: memFree=324728/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=39.83
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49452 0 0 0 3970 13 0 0 20 0 1 0 117048802 170700800 40881 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40881 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.58
Current children cumulated vsize (KiB) 197952

[startup+102.3 s]
/proc/loadavg: 1.02 0.49 0.19 2/68 8669
/proc/meminfo: memFree=324728/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=90.63
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49452 0 0 0 9050 13 0 0 20 0 1 0 117048802 170700800 40881 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40881 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.38
Current children cumulated vsize (KiB) 197952

[startup+162.3 s]
/proc/loadavg: 1.19 0.63 0.25 2/68 8922
/proc/meminfo: memFree=223652/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=142.55
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49452 0 0 0 14241 14 0 0 20 0 1 0 117048802 170700800 40881 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4739984 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40881 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 153.3
Current children cumulated vsize (KiB) 197952

[startup+222.304 s]
/proc/loadavg: 1.07 0.69 0.29 2/68 8922
/proc/meminfo: memFree=223652/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=202.04
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49452 0 0 0 20190 14 0 0 20 0 1 0 117048802 170700800 40881 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4676862 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40881 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 212.79
Current children cumulated vsize (KiB) 197952

[startup+282.3 s]
/proc/loadavg: 1.02 0.74 0.33 2/68 8922
/proc/meminfo: memFree=223900/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=261.53
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49452 0 0 0 26139 14 0 0 20 0 1 0 117048802 170700800 40881 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40881 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 272.28
Current children cumulated vsize (KiB) 197952



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+310.303 s]
/proc/loadavg: 1.07 0.78 0.36 2/68 8922
/proc/meminfo: memFree=223900/1022884 swapFree=0/0
[pid=8650] ppid=8649 vsize=9212 CPUtime=10.75
/proc/8650/stat : 8650 (aspcud-full) S 8649 8650 1745 0 -1 4202496 800 183591 0 0 0 0 987 88 20 0 1 0 117047710 9433088 365 18446744073709551615 4194304 5129932 140735093715328 140735093713392 140337326400606 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/8650/statm: 2303 365 303 229 0 63 0
[pid=8668] ppid=8650 vsize=166700 CPUtime=289.31
/proc/8668/stat : 8668 (clasp) R 8650 8650 1745 0 -1 4202496 49452 0 0 0 28917 14 0 0 20 0 1 0 117048802 170700800 40881 18446744073709551615 4194304 6238623 140734909095552 140734909092576 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/8668/statm: 41675 40881 264 500 0 41172 0
[pid=8669] ppid=8650 vsize=22040 CPUtime=0
/proc/8669/stat : 8669 (parse.py) S 8650 8650 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117048802 22568960 1128 18446744073709551615 4194304 6642060 140734820375104 140734820373464 139855920428832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/8669/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.06
Current children cumulated vsize (KiB) 197952

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): 310.338
CPU time (s): 300.139
CPU user time (s): 299.075
CPU system time (s): 1.06407
CPU usage (%): 96.7135
Max. virtual memory (cumulated for all children) (KiB): 598040

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.075
system time used= 1.06407
maximum resident set size= 480776
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 235464
page faults= 0
swaps= 0
block input operations= 68432
block output operations= 66984
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 80
involuntary context switches= 36345

runsolver used 0.568035 second user time and 1.27208 second system time

The end