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/install/rand717.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand717.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand717.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.95 1.00 1.02 2/64 15285
/proc/meminfo: memFree=702076/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=3152 CPUtime=0
/proc/15285/stat : 15285 (runsolver) R 15284 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118848792 3227648 32 18446744073709551615 134512640 134586868 4288545616 4288543664 4151551024 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.198461 s]
/proc/loadavg: 0.95 1.00 1.02 2/64 15285
/proc/meminfo: memFree=702076/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=0.05
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 742 3615 0 0 0 0 3 2 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200357 s]
/proc/loadavg: 0.95 1.00 1.02 2/64 15285
/proc/meminfo: memFree=702076/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=0.05
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 742 3615 0 0 0 0 3 2 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300257 s]
/proc/loadavg: 0.95 1.00 1.02 2/64 15285
/proc/meminfo: memFree=702076/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=0.05
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 742 3615 0 0 0 0 3 2 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700233 s]
/proc/loadavg: 0.95 1.00 1.02 2/64 15285
/proc/meminfo: memFree=702076/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=0.05
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 742 3615 0 0 0 0 3 2 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/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.95 1.00 1.02 2/66 15301
/proc/meminfo: memFree=667704/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=0.05
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 742 3615 0 0 0 0 3 2 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15301] ppid=15285 vsize=50868 CPUtime=1.41
/proc/15301/stat : 15301 (cudf2lp) R 15285 15285 1745 0 -1 4202496 11648 0 0 0 134 7 0 0 20 0 1 0 118848796 52088832 9914 18446744073709551615 4194304 5690517 140733196201504 140733196197672 4371323 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/15301/statm: 12717 9914 160 366 0 12348 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 60080

[startup+3.10034 s]
/proc/loadavg: 0.95 1.00 1.02 2/66 15301
/proc/meminfo: memFree=635712/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=0.05
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 742 3615 0 0 0 0 3 2 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15301] ppid=15285 vsize=93028 CPUtime=2.99
/proc/15301/stat : 15301 (cudf2lp) R 15285 15285 1745 0 -1 4202496 26524 0 0 0 284 15 0 0 20 0 1 0 118848796 95260672 19796 18446744073709551615 4194304 5690517 140733196201504 140733196199144 4293683 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/15301/statm: 23257 19796 160 366 0 22888 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 102240

[startup+6.30033 s]
/proc/loadavg: 0.95 1.00 1.02 2/66 15302
/proc/meminfo: memFree=646996/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=5.25
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 769 42937 0 0 0 0 492 33 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15302] ppid=15285 vsize=28592 CPUtime=0.95
/proc/15302/stat : 15302 (gringo) R 15285 15285 1745 0 -1 4202496 7467 0 0 0 91 4 0 0 20 0 1 0 118849325 29278208 6355 18446744073709551615 4194304 6531320 140735328153696 140735328149096 5101082 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15302/statm: 7148 6355 259 571 0 6569 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 37804

[startup+12.7003 s]
/proc/loadavg: 0.95 1.00 1.02 2/66 15302
/proc/meminfo: memFree=346792/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=5.25
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 769 42937 0 0 0 0 492 33 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556992 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15302] ppid=15285 vsize=420712 CPUtime=7.3
/proc/15302/stat : 15302 (gringo) R 15285 15285 1745 0 -1 4202496 99546 0 0 0 682 48 0 0 20 0 1 0 118849325 430809088 83070 18446744073709551615 4194304 6531320 140735328153696 140735328150040 5510977 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15302/statm: 105178 83070 282 571 0 104599 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 429924

[startup+25.5005 s]
/proc/loadavg: 0.96 1.00 1.01 2/67 15304
/proc/meminfo: memFree=439412/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=243436 CPUtime=6.37
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 72868 0 0 0 612 25 0 0 20 0 1 0 118850695 249278464 59650 18446744073709551615 4194304 6238623 140734687161408 140734687158432 4635763 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 60859 59650 263 500 0 60356 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.06
Current children cumulated vsize (KiB) 274688

[startup+51.1003 s]
/proc/loadavg: 0.97 1.00 1.01 2/67 15304
/proc/meminfo: memFree=436808/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=243436 CPUtime=31.73
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 73611 0 0 0 3148 25 0 0 20 0 1 0 118850695 249278464 60393 18446744073709551615 4194304 6238623 140734687161408 140734687158432 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 60859 60393 263 500 0 60356 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.42
Current children cumulated vsize (KiB) 274688

[startup+102.3 s]
/proc/loadavg: 0.99 1.00 1.01 2/67 15304
/proc/meminfo: memFree=436440/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=243436 CPUtime=82.53
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 73682 0 0 0 8228 25 0 0 20 0 1 0 118850695 249278464 60464 18446744073709551615 4194304 6238623 140734687161408 140734687158432 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 60859 60464 264 500 0 60356 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.22
Current children cumulated vsize (KiB) 274688

[startup+162.3 s]
/proc/loadavg: 0.99 1.00 1.00 2/67 15304
/proc/meminfo: memFree=383740/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=302356 CPUtime=142.07
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 88490 0 0 0 14175 32 0 0 20 0 1 0 118850695 309612544 75272 18446744073709551615 4194304 6238623 140734687161408 140734687157960 4685762 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 75589 75272 264 500 0 75086 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 160.76
Current children cumulated vsize (KiB) 333608

[startup+222.307 s]
/proc/loadavg: 0.99 1.00 1.00 2/70 15334
/proc/meminfo: memFree=292948/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=366200 CPUtime=201.33
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 104426 0 0 0 20093 40 0 0 20 0 1 0 118850695 374988800 91207 18446744073709551615 4194304 6238623 140734687161408 140734687157960 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 91550 91207 264 500 0 91047 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 220.02
Current children cumulated vsize (KiB) 397452

[startup+282.3 s]
/proc/loadavg: 1.14 1.05 1.02 2/67 15565
/proc/meminfo: memFree=166112/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=368184 CPUtime=254.65
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 104924 0 0 0 25424 41 0 0 20 0 1 0 118850695 377020416 91705 18446744073709551615 4194304 6238623 140734687161408 140734687157960 4687643 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 92046 91705 264 500 0 91543 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 273.34
Current children cumulated vsize (KiB) 399436



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+309.204 s]
/proc/loadavg: 1.08 1.05 1.01 2/67 15565
/proc/meminfo: memFree=162888/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=371656 CPUtime=281.35
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 105783 0 0 0 28094 41 0 0 20 0 1 0 118850695 380575744 92564 18446744073709551615 4194304 6238623 140734687161408 140734687158056 4355582 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 92914 92564 264 500 0 92411 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 402908

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+309.204 s]
/proc/loadavg: 1.08 1.05 1.01 2/67 15565
/proc/meminfo: memFree=162888/1022884 swapFree=0/0
[pid=15285] ppid=15284 vsize=9212 CPUtime=18.67
/proc/15285/stat : 15285 (aspcud-full) S 15284 15285 1745 0 -1 4202496 809 227010 0 0 0 0 1731 136 20 0 1 0 118848792 9433088 364 18446744073709551615 4194304 5129932 140735623558336 140735623556400 140142853608542 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15285/statm: 2303 364 303 229 0 63 0
[pid=15303] ppid=15285 vsize=371656 CPUtime=281.35
/proc/15303/stat : 15303 (clasp) R 15285 15285 1745 0 -1 4202496 105783 0 0 0 28094 41 0 0 20 0 1 0 118850695 380575744 92564 18446744073709551615 4194304 6238623 140734687161408 140734687158056 4355582 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15303/statm: 92914 92564 264 500 0 92411 0
[pid=15304] ppid=15285 vsize=22040 CPUtime=0.02
/proc/15304/stat : 15304 (parse.py) S 15285 15285 1745 0 -1 4202496 1309 0 10 0 0 2 0 0 20 0 1 0 118850695 22568960 1129 18446744073709551615 4194304 6642060 140734377964080 140734377962440 139655891961632 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/15304/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 402908

Child status: 0
Real time (s): 309.257
CPU time (s): 300.119
CPU user time (s): 298.287
CPU system time (s): 1.83211
CPU usage (%): 97.0451
Max. virtual memory (cumulated for all children) (KiB): 813616

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.287
system time used= 1.83211
maximum resident set size= 670372
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 335238
page faults= 10
swaps= 0
block input operations= 69576
block output operations= 83992
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 93
involuntary context switches= 37409

runsolver used 0.548034 second user time and 1.26808 second system time

The end