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/rand268.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand268.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand268.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.97 2/59 16728
/proc/meminfo: memFree=429364/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=3152 CPUtime=0
/proc/16728/stat : 16728 (runsolver) R 16727 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119377326 3227648 32 18446744073709551615 134512640 134586868 4292522016 4292520064 4151792688 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 788 32 0 19 0 73 0

[startup+0.204878 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 16728
/proc/meminfo: memFree=429364/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=0.05
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 735 3624 0 0 1 0 2 2 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668512432 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300337 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 16728
/proc/meminfo: memFree=429364/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=0.05
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 735 3624 0 0 1 0 2 2 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668512432 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.400312 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 16728
/proc/meminfo: memFree=429364/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=0.05
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 735 3624 0 0 1 0 2 2 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668512432 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700222 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 16728
/proc/meminfo: memFree=429364/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=0.05
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 735 3624 0 0 1 0 2 2 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668512432 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/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.97 2/61 16744
/proc/meminfo: memFree=393504/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=0.05
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 735 3624 0 0 1 0 2 2 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668512432 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16744] ppid=16728 vsize=48864 CPUtime=1.43
/proc/16744/stat : 16744 (cudf2lp) R 16728 16728 1750 0 -1 4202496 13684 0 0 0 138 5 0 0 20 0 1 0 119377330 50036736 10286 18446744073709551615 4194304 5690517 140735943501776 140735943499416 4329480 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/16744/statm: 12216 10286 159 366 0 11847 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 58076

[startup+3.10031 s]
/proc/loadavg: 0.87 0.94 0.97 2/61 16744
/proc/meminfo: memFree=356924/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=0.05
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 735 3624 0 0 1 0 2 2 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668512432 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16744] ppid=16728 vsize=72092 CPUtime=3.01
/proc/16744/stat : 16744 (cudf2lp) R 16728 16728 1750 0 -1 4202496 23821 0 0 0 287 14 0 0 20 0 1 0 119377330 73822208 17758 18446744073709551615 4194304 5690517 140735943501776 140735943499112 4951751 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/16744/statm: 18023 17758 174 366 0 17654 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 81304

[startup+6.30031 s]
/proc/loadavg: 0.87 0.94 0.97 2/61 16745
/proc/meminfo: memFree=296164/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=3.15
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 761 27447 0 0 1 0 295 19 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668512432 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16745] ppid=16728 vsize=162348 CPUtime=3.09
/proc/16745/stat : 16745 (gringo) R 16728 16728 1750 0 -1 4202496 40992 0 0 0 289 20 0 0 20 0 1 0 119377643 166244352 36550 18446744073709551615 4194304 6531320 140734193873696 140734193870312 5554606 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/16745/statm: 40587 36550 281 571 0 40008 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 171560

[startup+12.7003 s]
/proc/loadavg: 0.89 0.94 0.97 2/62 16747
/proc/meminfo: memFree=271108/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=139932 CPUtime=2.58
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 40593 0 0 0 246 12 0 0 20 0 1 0 119378334 143290368 34412 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4669529 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 34983 34412 264 500 0 34480 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 171184

[startup+25.5033 s]
/proc/loadavg: 0.90 0.94 0.97 2/62 16747
/proc/meminfo: memFree=270364/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=139932 CPUtime=15.28
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 40836 0 0 0 1516 12 0 0 20 0 1 0 119378334 143290368 34655 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4332735 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 34983 34655 264 500 0 34480 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 171184

[startup+51.1003 s]
/proc/loadavg: 0.93 0.95 0.97 2/62 16747
/proc/meminfo: memFree=249160/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=160980 CPUtime=40.69
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 46117 0 0 0 4054 15 0 0 20 0 1 0 119378334 164843520 39936 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4687659 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 40245 39936 264 500 0 39742 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.64
Current children cumulated vsize (KiB) 192232

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.97 2/62 16747
/proc/meminfo: memFree=117968/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=292024 CPUtime=91.52
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 78809 0 0 0 9123 29 0 0 20 0 1 0 119378334 299032576 72628 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 73006 72628 264 500 0 72503 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.47
Current children cumulated vsize (KiB) 323276

[startup+162.3 s]
/proc/loadavg: 1.03 0.97 0.97 2/62 16747
/proc/meminfo: memFree=113628/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=296276 CPUtime=151.07
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 79871 0 0 0 15078 29 0 0 20 0 1 0 119378334 303386624 73690 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4331882 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 74069 73690 264 500 0 73566 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 161.02
Current children cumulated vsize (KiB) 327528

[startup+222.3 s]
/proc/loadavg: 1.01 0.97 0.97 2/62 16747
/proc/meminfo: memFree=112388/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=297608 CPUtime=210.62
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 80188 0 0 0 21032 30 0 0 20 0 1 0 119378334 304750592 74007 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4677133 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 74402 74007 264 500 0 73899 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.57
Current children cumulated vsize (KiB) 328860

[startup+282.3 s]
/proc/loadavg: 1.00 0.97 0.97 2/62 16747
/proc/meminfo: memFree=110032/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=300000 CPUtime=270.17
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 80790 0 0 0 26986 31 0 0 20 0 1 0 119378334 307200000 74609 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4663111 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 75000 74609 264 500 0 74497 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 280.12
Current children cumulated vsize (KiB) 331252



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.4 s]
/proc/loadavg: 1.00 0.97 0.97 2/62 16747
/proc/meminfo: memFree=110032/1022884 swapFree=0/0
[pid=16728] ppid=16727 vsize=9212 CPUtime=9.95
/proc/16728/stat : 16728 (aspcud-full) S 16727 16728 1750 0 -1 4202496 801 136047 0 0 1 0 924 70 20 0 1 0 119377326 9433088 364 18446744073709551615 4194304 5129932 140735668513776 140735668511840 139855301309534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16728/statm: 2303 364 303 229 0 63 0
[pid=16746] ppid=16728 vsize=300000 CPUtime=290.12
/proc/16746/stat : 16746 (clasp) R 16728 16728 1750 0 -1 4202496 80790 0 0 0 28980 32 0 0 20 0 1 0 119378334 307200000 74609 18446744073709551615 4194304 6238623 140734543461456 140734543458480 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16746/statm: 75000 74609 264 500 0 74497 0
[pid=16747] ppid=16728 vsize=22040 CPUtime=0
/proc/16747/stat : 16747 (parse.py) S 16728 16728 1750 0 -1 4202496 1317 0 0 0 0 0 0 0 20 0 1 0 119378334 22568960 1127 18446744073709551615 4194304 6642060 140735546501008 140735546499368 140398499309344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16747/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 331252

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.446
CPU time (s): 300.151
CPU user time (s): 299.079
CPU system time (s): 1.07207
CPU usage (%): 99.2412
Max. virtual memory (cumulated for all children) (KiB): 458584

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.079
system time used= 1.07207
maximum resident set size= 400228
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 219272
page faults= 0
swaps= 0
block input operations= 42368
block output operations= 47224
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 74
involuntary context switches= 34413

runsolver used 0.48403 second user time and 1.14007 second system time

The end