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/rand583.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand583.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand583.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.99 0.97 0.98 2/59 1311
/proc/meminfo: memFree=429628/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=3152 CPUtime=0
/proc/1311/stat : 1311 (runsolver) R 1310 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119379128 3227648 32 18446744073709551615 134512640 134586868 4287574672 4287572720 4151247920 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 788 32 0 19 0 73 0

[startup+0.188526 s]
/proc/loadavg: 0.99 0.97 0.98 2/59 1311
/proc/meminfo: memFree=429628/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=0.03
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 741 3615 0 0 0 0 3 0 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089334544 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.20032 s]
/proc/loadavg: 0.99 0.97 0.98 2/59 1311
/proc/meminfo: memFree=429628/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=0.03
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 741 3615 0 0 0 0 3 0 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089334544 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300287 s]
/proc/loadavg: 0.99 0.97 0.98 2/59 1311
/proc/meminfo: memFree=429628/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=0.03
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 741 3615 0 0 0 0 3 0 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089334544 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700193 s]
/proc/loadavg: 0.99 0.97 0.98 2/59 1311
/proc/meminfo: memFree=429628/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=0.03
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 741 3615 0 0 0 0 3 0 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089334544 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.99 0.97 0.98 2/61 1327
/proc/meminfo: memFree=374920/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=0.03
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 741 3615 0 0 0 0 3 0 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089334544 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1327] ppid=1311 vsize=48864 CPUtime=1.42
/proc/1327/stat : 1327 (cudf2lp) R 1311 1311 1733 0 -1 4202496 14139 0 0 0 135 7 0 0 20 0 1 0 119379131 50036736 10741 18446744073709551615 4194304 5690517 140736437045056 140736437042696 4293705 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/1327/statm: 12216 10741 160 366 0 11847 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 58076

[startup+3.10025 s]
/proc/loadavg: 0.99 0.97 0.98 2/61 1327
/proc/meminfo: memFree=327056/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=2.73
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 768 27438 0 0 0 0 258 15 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089334544 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.73
Current children cumulated vsize (KiB) 9212

[startup+6.30031 s]
/proc/loadavg: 0.99 0.97 0.98 2/61 1328
/proc/meminfo: memFree=283904/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=2.73
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 768 27438 0 0 0 0 258 15 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089334544 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1328] ppid=1311 vsize=182204 CPUtime=3.46
/proc/1328/stat : 1328 (gringo) R 1311 1311 1733 0 -1 4202496 46073 0 0 0 321 25 0 0 20 0 1 0 119379408 186576896 37534 18446744073709551615 4194304 6531320 140736677710416 140736677707032 4359010 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/1328/statm: 45551 37534 281 571 0 44972 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 191416

[startup+12.7004 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=268968/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=138088 CPUtime=2.33
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 40107 0 1 0 221 12 0 0 20 0 1 0 119380160 141402112 33953 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 34522 33953 263 500 0 34019 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 169340

[startup+25.5004 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=267852/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=138088 CPUtime=15
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 40370 0 1 0 1488 12 0 0 20 0 1 0 119380160 141402112 34216 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4635167 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 34522 34216 264 500 0 34019 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 169340

[startup+51.1004 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=267852/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=138088 CPUtime=40.35
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 40370 0 1 0 4023 12 0 0 20 0 1 0 119380160 141402112 34216 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4372622 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 34522 34216 264 500 0 34019 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.51
Current children cumulated vsize (KiB) 169340

[startup+102.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=244416/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=161320 CPUtime=91.16
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 46197 0 1 0 9101 15 0 0 20 0 1 0 119380160 165191680 40043 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4409931 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 40330 40043 264 500 0 39827 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.32
Current children cumulated vsize (KiB) 192572

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=215276/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=190496 CPUtime=150.72
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 53468 0 1 0 15054 18 0 0 20 0 1 0 119380160 195067904 47314 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 47624 47314 264 500 0 47121 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.88
Current children cumulated vsize (KiB) 221748

[startup+222.303 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=142736/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=263080 CPUtime=210.28
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 71599 0 1 0 20999 29 0 0 20 0 1 0 119380160 269393920 65445 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4422166 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 65770 65445 264 500 0 65267 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.44
Current children cumulated vsize (KiB) 294332

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=112728/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=293312 CPUtime=269.84
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 79129 0 1 0 26952 32 0 0 20 0 1 0 119380160 300351488 72975 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 73328 72975 264 500 0 72825 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 280
Current children cumulated vsize (KiB) 324564



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.5 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1331
/proc/meminfo: memFree=112356/1022884 swapFree=0/0
[pid=1311] ppid=1310 vsize=9212 CPUtime=10.14
/proc/1311/stat : 1311 (aspcud-full) S 1310 1311 1733 0 -1 4202496 809 135113 0 0 0 0 936 78 20 0 1 0 119379128 9433088 364 18446744073709551615 4194304 5129932 140737089335888 140737089333952 139683320190046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1311/statm: 2303 364 303 229 0 63 0
[pid=1329] ppid=1311 vsize=293576 CPUtime=289.89
/proc/1329/stat : 1329 (clasp) R 1311 1311 1733 0 -1 4202496 79194 0 1 0 28957 32 0 0 20 0 1 0 119380160 300621824 73040 18446744073709551615 4194304 6238623 140735547325712 140735547322736 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/1329/statm: 73394 73040 264 500 0 72891 0
[pid=1331] ppid=1311 vsize=22040 CPUtime=0.02
/proc/1331/stat : 1331 (parse.py) S 1311 1311 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 119380160 22568960 1128 18446744073709551615 4194304 6642060 140737414999408 140737414997768 140388697745184 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1331/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.05
Current children cumulated vsize (KiB) 324828

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.55
CPU time (s): 300.123
CPU user time (s): 298.959
CPU system time (s): 1.16407
CPU usage (%): 99.1979
Max. virtual memory (cumulated for all children) (KiB): 456528

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.959
system time used= 1.16407
maximum resident set size= 396528
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 216751
page faults= 1
swaps= 0
block input operations= 42504
block output operations= 46712
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 76
involuntary context switches= 34317

runsolver used 0.584036 second user time and 1.11207 second system time

The end