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/upgrade/difficult/rand131.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand131.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/difficult/rand131.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

[startup+0 s]
/proc/loadavg: 0.87 0.95 0.94 2/64 16882
/proc/meminfo: memFree=431260/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=3152 CPUtime=0
/proc/16882/stat : 16882 (runsolver) R 16881 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119480548 3227648 32 18446744073709551615 134512640 134586868 4287506976 4287505024 4151370800 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.134573 s]
/proc/loadavg: 0.87 0.95 0.94 2/64 16882
/proc/meminfo: memFree=431260/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=0.05
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 739 3626 0 0 0 0 3 2 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200332 s]
/proc/loadavg: 0.87 0.95 0.94 2/64 16882
/proc/meminfo: memFree=431260/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=0.05
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 739 3626 0 0 0 0 3 2 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.30031 s]
/proc/loadavg: 0.87 0.95 0.94 2/64 16882
/proc/meminfo: memFree=431260/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=0.05
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 739 3626 0 0 0 0 3 2 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700231 s]
/proc/loadavg: 0.87 0.95 0.94 2/64 16882
/proc/meminfo: memFree=431260/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=0.05
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 739 3626 0 0 0 0 3 2 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.87 0.95 0.94 2/66 16898
/proc/meminfo: memFree=397632/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=0.05
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 739 3626 0 0 0 0 3 2 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16898] ppid=16882 vsize=33064 CPUtime=1.38
/proc/16898/stat : 16898 (cudf2lp) R 16882 16882 1745 0 -1 4202496 9678 0 0 0 134 4 0 0 20 0 1 0 119480552 33857536 7944 18446744073709551615 4194304 5690517 140733510561248 140733510558616 4360825 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/16898/statm: 8266 7944 160 366 0 7897 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 42276

[startup+3.10033 s]
/proc/loadavg: 0.87 0.95 0.94 2/66 16898
/proc/meminfo: memFree=365640/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=0.05
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 739 3626 0 0 0 0 3 2 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16898] ppid=16882 vsize=93028 CPUtime=2.95
/proc/16898/stat : 16898 (cudf2lp) R 16882 16882 1745 0 -1 4202496 26441 0 0 0 285 10 0 0 20 0 1 0 119480552 95260672 19713 18446744073709551615 4194304 5690517 140733510561248 140733510558888 4357582 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/16898/statm: 23257 19713 160 366 0 22888 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.88 0.95 0.94 2/66 16899
/proc/meminfo: memFree=377916/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=5.26
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 763 42950 0 0 0 0 500 26 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16899] ppid=16882 vsize=27436 CPUtime=0.9
/proc/16899/stat : 16899 (gringo) R 16882 16882 1745 0 -1 4202496 7180 0 0 0 86 4 0 0 20 0 1 0 119481086 28094464 6069 18446744073709551615 4194304 6531320 140736944145536 140736944142152 5563180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/16899/statm: 6859 6069 259 571 0 6280 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 36648

[startup+12.7003 s]
/proc/loadavg: 0.89 0.95 0.94 2/66 16899
/proc/meminfo: memFree=95196/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=5.26
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 763 42950 0 0 0 0 500 26 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038177504 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16899] ppid=16882 vsize=420204 CPUtime=7.23
/proc/16899/stat : 16899 (gringo) R 16882 16882 1745 0 -1 4202496 100182 0 0 0 682 41 0 0 20 0 1 0 119481086 430288896 83707 18446744073709551615 4194304 6531320 140736944145536 140736944142152 4360156 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/16899/statm: 105051 83707 282 571 0 104472 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 429416

[startup+25.5004 s]
/proc/loadavg: 0.91 0.95 0.94 2/67 16901
/proc/meminfo: memFree=410664/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=18.38
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 800 222286 0 0 0 0 1711 127 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038176912 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16900] ppid=16882 vsize=237744 CPUtime=6.3
/proc/16900/stat : 16900 (clasp) R 16882 16882 1745 0 -1 4202496 71310 0 1 0 604 26 0 0 20 0 1 0 119482452 243449856 58187 18446744073709551615 4194304 6238623 140735771833952 140735771830976 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/16900/statm: 59436 58187 263 500 0 58933 0
[pid=16901] ppid=16882 vsize=22040 CPUtime=0.02
/proc/16901/stat : 16901 (parse.py) S 16882 16882 1745 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 119482452 22568960 1127 18446744073709551615 4194304 6642060 140735027386224 140735027384584 140285598373664 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/16901/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 24.7
Current children cumulated vsize (KiB) 268996

[startup+51.1003 s]
/proc/loadavg: 0.94 0.96 0.94 2/67 16901
/proc/meminfo: memFree=407440/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=18.38
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 800 222286 0 0 0 0 1711 127 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038176912 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16900] ppid=16882 vsize=237744 CPUtime=31.63
/proc/16900/stat : 16900 (clasp) R 16882 16882 1745 0 -1 4202496 72198 0 1 0 3137 26 0 0 20 0 1 0 119482452 243449856 59075 18446744073709551615 4194304 6238623 140735771833952 140735771830976 4421728 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/16900/statm: 59436 59075 264 500 0 58933 0
[pid=16901] ppid=16882 vsize=22040 CPUtime=0.02
/proc/16901/stat : 16901 (parse.py) S 16882 16882 1745 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 119482452 22568960 1127 18446744073709551615 4194304 6642060 140735027386224 140735027384584 140285598373664 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/16901/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.03
Current children cumulated vsize (KiB) 268996

[startup+102.3 s]
/proc/loadavg: 0.97 0.96 0.94 2/67 16901
/proc/meminfo: memFree=326964/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=18.38
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 800 222286 0 0 0 0 1711 127 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038176912 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16900] ppid=16882 vsize=318212 CPUtime=82.44
/proc/16900/stat : 16900 (clasp) R 16882 16882 1745 0 -1 4202496 92253 0 1 0 8210 34 0 0 20 0 1 0 119482452 325849088 79130 18446744073709551615 4194304 6238623 140735771833952 140735771830504 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/16900/statm: 79553 79130 264 500 0 79050 0
[pid=16901] ppid=16882 vsize=22040 CPUtime=0.02
/proc/16901/stat : 16901 (parse.py) S 16882 16882 1745 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 119482452 22568960 1127 18446744073709551615 4194304 6642060 140735027386224 140735027384584 140285598373664 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/16901/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 100.84
Current children cumulated vsize (KiB) 349464

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.94 2/67 16901
/proc/meminfo: memFree=309852/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=18.38
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 800 222286 0 0 0 0 1711 127 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038176912 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16900] ppid=16882 vsize=335136 CPUtime=141.98
/proc/16900/stat : 16900 (clasp) R 16882 16882 1745 0 -1 4202496 96507 0 1 0 14162 36 0 0 20 0 1 0 119482452 343179264 83384 18446744073709551615 4194304 6238623 140735771833952 140735771830504 4333106 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/16900/statm: 83784 83384 264 500 0 83281 0
[pid=16901] ppid=16882 vsize=22040 CPUtime=0.02
/proc/16901/stat : 16901 (parse.py) S 16882 16882 1745 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 119482452 22568960 1127 18446744073709551615 4194304 6642060 140735027386224 140735027384584 140285598373664 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/16901/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.38
Current children cumulated vsize (KiB) 366388

[startup+222.304 s]
/proc/loadavg: 0.99 0.97 0.94 2/67 16901
/proc/meminfo: memFree=307496/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=18.38
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 800 222286 0 0 0 0 1711 127 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038176912 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16900] ppid=16882 vsize=337660 CPUtime=201.52
/proc/16900/stat : 16900 (clasp) R 16882 16882 1745 0 -1 4202496 97135 0 1 0 20116 36 0 0 20 0 1 0 119482452 345763840 84012 18446744073709551615 4194304 6238623 140735771833952 140735771830504 4697050 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/16900/statm: 84415 84012 264 500 0 83912 0
[pid=16901] ppid=16882 vsize=22040 CPUtime=0.02
/proc/16901/stat : 16901 (parse.py) S 16882 16882 1745 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 119482452 22568960 1127 18446744073709551615 4194304 6642060 140735027386224 140735027384584 140285598373664 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/16901/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 219.92
Current children cumulated vsize (KiB) 368912

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.94 2/67 16901
/proc/meminfo: memFree=297080/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=18.38
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 800 222286 0 0 0 0 1711 127 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038176912 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16900] ppid=16882 vsize=348156 CPUtime=261.04
/proc/16900/stat : 16900 (clasp) R 16882 16882 1745 0 -1 4202496 99739 0 1 0 26068 36 0 0 20 0 1 0 119482452 356511744 86615 18446744073709551615 4194304 6238623 140735771833952 140735771830504 4687675 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/16900/statm: 87039 86615 264 500 0 86536 0
[pid=16901] ppid=16882 vsize=22040 CPUtime=0.02
/proc/16901/stat : 16901 (parse.py) S 16882 16882 1745 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 119482452 22568960 1127 18446744073709551615 4194304 6642060 140735027386224 140735027384584 140285598373664 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/16901/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.44
Current children cumulated vsize (KiB) 379408



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.1 s]
/proc/loadavg: 0.99 0.97 0.94 2/67 16901
/proc/meminfo: memFree=295964/1022884 swapFree=0/0
[pid=16882] ppid=16881 vsize=9212 CPUtime=18.38
/proc/16882/stat : 16882 (aspcud-full) S 16881 16882 1745 0 -1 4202496 800 222286 0 0 0 0 1711 127 20 0 1 0 119480548 9433088 365 18446744073709551615 4194304 5129932 140737038178848 140737038176912 139933239931998 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16882/statm: 2303 365 303 229 0 63 0
[pid=16900] ppid=16882 vsize=349084 CPUtime=281.67
/proc/16900/stat : 16900 (clasp) R 16882 16882 1745 0 -1 4202496 99986 0 1 0 28131 36 0 0 20 0 1 0 119482452 357462016 86862 18446744073709551615 4194304 6238623 140735771833952 140735771830504 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/16900/statm: 87271 86862 264 500 0 86768 0
[pid=16901] ppid=16882 vsize=22040 CPUtime=0.02
/proc/16901/stat : 16901 (parse.py) S 16882 16882 1745 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 119482452 22568960 1127 18446744073709551615 4194304 6642060 140735027386224 140735027384584 140285598373664 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/16901/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 380336

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): 303.183
CPU time (s): 300.171
CPU user time (s): 298.459
CPU system time (s): 1.71211
CPU usage (%): 99.0064
Max. virtual memory (cumulated for all children) (KiB): 784840

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.459
system time used= 1.71211
maximum resident set size= 651428
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 324694
page faults= 15
swaps= 0
block input operations= 98688
block output operations= 82120
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 124
involuntary context switches= 34502

runsolver used 0.596037 second user time and 1.22408 second system time

The end