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/easy/rand764.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand764.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand764.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.85 0.94 0.98 2/59 16694
/proc/meminfo: memFree=428992/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9204 CPUtime=0
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 119345402 9424896 331 18446744073709551615 4194304 5129932 140736346565568 140736346563032 140462334244640 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2301 331 272 229 0 61 0

[startup+0.165914 s]
/proc/loadavg: 0.85 0.94 0.98 2/59 16694
/proc/meminfo: memFree=428992/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=0.05
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 735 3624 0 0 0 0 4 1 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346564224 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200323 s]
/proc/loadavg: 0.85 0.94 0.98 2/59 16694
/proc/meminfo: memFree=428992/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=0.05
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 735 3624 0 0 0 0 4 1 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346564224 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300303 s]
/proc/loadavg: 0.85 0.94 0.98 2/59 16694
/proc/meminfo: memFree=428992/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=0.05
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 735 3624 0 0 0 0 4 1 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346564224 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700232 s]
/proc/loadavg: 0.85 0.94 0.98 2/59 16694
/proc/meminfo: memFree=428992/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=0.05
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 735 3624 0 0 0 0 4 1 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346564224 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.87 0.94 0.98 2/61 16710
/proc/meminfo: memFree=394744/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=0.05
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 735 3624 0 0 0 0 4 1 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346564224 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16710] ppid=16694 vsize=48864 CPUtime=1.41
/proc/16710/stat : 16710 (cudf2lp) R 16694 16694 1750 0 -1 4202496 13686 0 0 0 132 9 0 0 20 0 1 0 119345406 50036736 10288 18446744073709551615 4194304 5690517 140736960937968 140736960935608 4961154 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/16710/statm: 12216 10288 159 366 0 11847 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 58076

[startup+3.10079 s]
/proc/loadavg: 0.87 0.94 0.98 2/61 16710
/proc/meminfo: memFree=363992/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=0.05
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 735 3624 0 0 0 0 4 1 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346564224 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16710] ppid=16694 vsize=72092 CPUtime=3.01
/proc/16710/stat : 16710 (cudf2lp) R 16694 16694 1750 0 -1 4202496 23821 0 0 0 282 19 0 0 20 0 1 0 119345406 73822208 9566 18446744073709551615 4194304 5690517 140736960937968 140736960935848 5219018 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/16710/statm: 18023 9566 174 366 0 17654 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 81304

[startup+6.30025 s]
/proc/loadavg: 0.88 0.94 0.98 2/61 16711
/proc/meminfo: memFree=247308/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=3.1
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 761 27447 0 0 0 0 289 21 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346564224 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16711] ppid=16694 vsize=255076 CPUtime=3.12
/proc/16711/stat : 16711 (gringo) R 16694 16694 1750 0 -1 4202496 63502 0 0 0 288 24 0 0 20 0 1 0 119345717 261197824 54963 18446744073709551615 4194304 6531320 140735873075872 140735873072488 4315205 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/16711/statm: 63769 54963 282 571 0 63190 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 264288

[startup+12.7003 s]
/proc/loadavg: 0.89 0.95 0.98 2/62 16713
/proc/meminfo: memFree=267760/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=138308 CPUtime=4.36
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 40298 0 0 0 424 12 0 0 20 0 1 0 119346231 141627392 34141 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 34577 34141 264 500 0 34074 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 169560

[startup+25.5004 s]
/proc/loadavg: 0.91 0.95 0.98 2/62 16713
/proc/meminfo: memFree=266768/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=138308 CPUtime=17.04
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 40428 0 0 0 1692 12 0 0 20 0 1 0 119346231 141627392 34271 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 34577 34271 264 500 0 34074 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.21
Current children cumulated vsize (KiB) 169560

[startup+51.1004 s]
/proc/loadavg: 0.94 0.95 0.98 2/62 16713
/proc/meminfo: memFree=258832/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=146172 CPUtime=42.39
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 42413 0 0 0 4225 14 0 0 20 0 1 0 119346231 149680128 36256 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4404425 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 36543 36256 264 500 0 36040 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.56
Current children cumulated vsize (KiB) 177424

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.98 2/62 16713
/proc/meminfo: memFree=216300/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=188752 CPUtime=93.19
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 53028 0 0 0 9300 19 0 0 20 0 1 0 119346231 193282048 46871 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4332646 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 47188 46871 264 500 0 46685 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.36
Current children cumulated vsize (KiB) 220004

[startup+162.3 s]
/proc/loadavg: 0.99 0.96 0.98 2/62 16713
/proc/meminfo: memFree=193484/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=211344 CPUtime=152.72
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 58684 0 0 0 15252 20 0 0 20 0 1 0 119346231 216416256 52527 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 52836 52527 264 500 0 52333 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.89
Current children cumulated vsize (KiB) 242596

[startup+222.305 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 16721
/proc/meminfo: memFree=107304/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=297552 CPUtime=212.1
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 80196 0 0 0 21174 36 0 0 20 0 1 0 119346231 304693248 74039 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 74388 74039 264 500 0 73885 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.27
Current children cumulated vsize (KiB) 328804

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 16721
/proc/meminfo: memFree=106808/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=297952 CPUtime=271.5
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 80308 0 0 0 27114 36 0 0 20 0 1 0 119346231 305102848 74151 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4687995 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 74488 74151 264 500 0 73985 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.67
Current children cumulated vsize (KiB) 329204



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.9 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 16721
/proc/meminfo: memFree=106808/1022884 swapFree=0/0
[pid=16694] ppid=16693 vsize=9212 CPUtime=8.16
/proc/16694/stat : 16694 (aspcud-full) S 16693 16694 1750 0 -1 4202496 801 135136 0 0 0 0 750 66 20 0 1 0 119345402 9433088 364 18446744073709551615 4194304 5129932 140736346565568 140736346563632 140462334100574 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16694/statm: 2303 364 303 229 0 63 0
[pid=16712] ppid=16694 vsize=297952 CPUtime=291.89
/proc/16712/stat : 16712 (clasp) R 16694 16694 1750 0 -1 4202496 80308 0 0 0 29153 36 0 0 20 0 1 0 119346231 305102848 74151 18446744073709551615 4194304 6238623 140735021524336 140735021521360 4407247 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16712/statm: 74488 74151 264 500 0 73985 0
[pid=16713] ppid=16694 vsize=22040 CPUtime=0.01
/proc/16713/stat : 16713 (parse.py) S 16694 16694 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119346231 22568960 1127 18446744073709551615 4194304 6642060 140734974138464 140734974136824 140333706131232 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16713/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.06
Current children cumulated vsize (KiB) 329204

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): 302.959
CPU time (s): 300.159
CPU user time (s): 299.067
CPU system time (s): 1.09207
CPU usage (%): 99.0756
Max. virtual memory (cumulated for all children) (KiB): 456552

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.067
system time used= 1.09207
maximum resident set size= 396584
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 217877
page faults= 0
swaps= 0
block input operations= 42368
block output operations= 46728
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 74
involuntary context switches= 34324

runsolver used 0.716044 second user time and 1.32408 second system time

The end