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/trendy-size/real/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/real/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.88 0.97 0.99 2/59 948
/proc/meminfo: memFree=469652/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=3152 CPUtime=0
/proc/948/stat : 948 (runsolver) R 947 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119252046 3227648 32 18446744073709551615 134512640 134586868 4291815728 4291813776 4152185904 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 788 32 0 19 0 73 0

[startup+0.127678 s]
/proc/loadavg: 0.88 0.97 0.99 2/59 948
/proc/meminfo: memFree=469652/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=0.05
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 738 3616 0 0 0 1 3 1 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923712 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200318 s]
/proc/loadavg: 0.88 0.97 0.99 2/59 948
/proc/meminfo: memFree=469652/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=0.05
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 738 3616 0 0 0 1 3 1 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923712 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300322 s]
/proc/loadavg: 0.88 0.97 0.99 2/59 948
/proc/meminfo: memFree=469652/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=0.05
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 738 3616 0 0 0 1 3 1 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923712 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/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.88 0.97 0.99 2/59 948
/proc/meminfo: memFree=469652/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=0.05
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 738 3616 0 0 0 1 3 1 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923712 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50034 s]
/proc/loadavg: 0.88 0.97 0.99 2/61 964
/proc/meminfo: memFree=432924/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=0.05
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 738 3616 0 0 0 1 3 1 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923712 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=964] ppid=948 vsize=50252 CPUtime=1.43
/proc/964/stat : 964 (cudf2lp) R 948 948 1733 0 -1 4202496 14124 0 0 0 139 4 0 0 20 0 1 0 119252049 51458048 10725 18446744073709551615 4194304 5690517 140733201423440 140733201421080 4293666 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/964/statm: 12563 10725 160 366 0 12194 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 59464

[startup+3.10022 s]
/proc/loadavg: 0.88 0.97 0.99 2/61 964
/proc/meminfo: memFree=374272/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=2.62
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 763 26196 0 0 0 1 246 15 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923712 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.62
Current children cumulated vsize (KiB) 9212

[startup+6.30033 s]
/proc/loadavg: 0.89 0.97 0.99 2/61 965
/proc/meminfo: memFree=284620/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=2.62
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 763 26196 0 0 0 1 246 15 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923712 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=965] ppid=948 vsize=241380 CPUtime=3.61
/proc/965/stat : 965 (gringo) R 948 948 1733 0 -1 4202496 57775 0 0 0 342 19 0 0 20 0 1 0 119252311 247173120 53589 18446744073709551615 4194304 6531320 140737269820736 140737269817080 4554946 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/965/statm: 60345 53589 282 571 0 59766 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 250592

[startup+12.7004 s]
/proc/loadavg: 0.90 0.97 0.99 2/62 967
/proc/meminfo: memFree=352564/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=5.59
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 551 8 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4687659 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 113192

[startup+25.5003 s]
/proc/loadavg: 0.99 0.99 0.99 2/62 967
/proc/meminfo: memFree=352564/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=18.28
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 1820 8 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4635678 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.24
Current children cumulated vsize (KiB) 113192

[startup+51.1004 s]
/proc/loadavg: 0.99 0.99 0.99 2/62 967
/proc/meminfo: memFree=352564/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=43.65
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 4357 8 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4409923 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.61
Current children cumulated vsize (KiB) 113192

[startup+102.3 s]
/proc/loadavg: 1.22 1.03 1.01 2/63 1127
/proc/meminfo: memFree=314408/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=88.28
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 8819 9 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4320912 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 95.24
Current children cumulated vsize (KiB) 113192

[startup+162.3 s]
/proc/loadavg: 1.25 1.08 1.02 2/62 1218
/proc/meminfo: memFree=313392/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=145.52
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 14542 10 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4421899 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 152.48
Current children cumulated vsize (KiB) 113192

[startup+222.31 s]
/proc/loadavg: 1.09 1.07 1.02 2/62 1218
/proc/meminfo: memFree=313516/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=204.94
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 20484 10 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4409931 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 211.9
Current children cumulated vsize (KiB) 113192

[startup+282.3 s]
/proc/loadavg: 1.03 1.05 1.01 2/62 1218
/proc/meminfo: memFree=313516/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=264.35
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 26425 10 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4409931 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 271.31
Current children cumulated vsize (KiB) 113192



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+311.3 s]
/proc/loadavg: 1.02 1.05 1.01 2/62 1218
/proc/meminfo: memFree=313516/1022884 swapFree=0/0
[pid=948] ppid=947 vsize=9212 CPUtime=6.95
/proc/948/stat : 948 (aspcud-full) S 947 948 1733 0 -1 4202496 803 94641 0 0 0 1 650 44 20 0 1 0 119252046 9433088 364 18446744073709551615 4194304 5129932 140733430925056 140733430923120 139714076787806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/948/statm: 2303 364 303 229 0 63 0
[pid=966] ppid=948 vsize=81940 CPUtime=293.11
/proc/966/stat : 966 (clasp) R 948 948 1733 0 -1 4202496 24131 0 0 0 29301 10 0 0 20 0 1 0 119252748 83906560 20032 18446744073709551615 4194304 6238623 140734335599856 140734335596880 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/966/statm: 20485 20032 263 500 0 19982 0
[pid=967] ppid=948 vsize=22040 CPUtime=0.01
/proc/967/stat : 967 (parse.py) S 948 948 1733 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 119252748 22568960 1128 18446744073709551615 4194304 6642060 140734741374640 140734741373000 140465733580576 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/967/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 113192

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): 311.345
CPU time (s): 300.123
CPU user time (s): 299.539
CPU system time (s): 0.584036
CPU usage (%): 96.3954
Max. virtual memory (cumulated for all children) (KiB): 295948

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.539
system time used= 0.584036
maximum resident set size= 240632
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 121209
page faults= 0
swaps= 0
block input operations= 37880
block output operations= 31248
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 73
involuntary context switches= 36296

runsolver used 0.976061 second user time and 1.34008 second system time

The end