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/real/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/real/ab9005be-bacc-11e0-b0f6-00163e1e087d.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.86 0.96 0.98 2/64 16042
/proc/meminfo: memFree=452264/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=3152 CPUtime=0
/proc/16042/stat : 16042 (runsolver) R 16041 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119107738 3227648 33 18446744073709551615 134512640 134586868 4288223456 4288221504 4151764016 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.145237 s]
/proc/loadavg: 0.86 0.96 0.98 2/64 16042
/proc/meminfo: memFree=452264/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=0.04
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 732 3616 0 0 0 0 3 1 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374608 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200319 s]
/proc/loadavg: 0.86 0.96 0.98 2/64 16042
/proc/meminfo: memFree=452264/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=0.04
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 732 3616 0 0 0 0 3 1 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374608 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300299 s]
/proc/loadavg: 0.86 0.96 0.98 2/64 16042
/proc/meminfo: memFree=452264/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=0.04
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 732 3616 0 0 0 0 3 1 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374608 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700213 s]
/proc/loadavg: 0.86 0.96 0.98 2/64 16042
/proc/meminfo: memFree=452264/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=0.04
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 732 3616 0 0 0 0 3 1 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374608 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.86 0.96 0.98 2/66 16058
/proc/meminfo: memFree=414916/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=0.04
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 732 3616 0 0 0 0 3 1 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374608 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16058] ppid=16042 vsize=50452 CPUtime=1.42
/proc/16058/stat : 16058 (cudf2lp) R 16042 16042 1745 0 -1 4202496 14302 0 0 0 135 7 0 0 20 0 1 0 119107742 51662848 10904 18446744073709551615 4194304 5690517 140735897208736 140735897206376 4811168 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/16058/statm: 12613 10904 160 366 0 12244 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 59664

[startup+3.10033 s]
/proc/loadavg: 0.86 0.96 0.98 2/66 16058
/proc/meminfo: memFree=381156/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=0.04
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 732 3616 0 0 0 0 3 1 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374608 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16058] ppid=16042 vsize=84508 CPUtime=3.01
/proc/16058/stat : 16058 (cudf2lp) R 16042 16042 1745 0 -1 4202496 27255 0 0 0 287 14 0 0 20 0 1 0 119107742 86536192 20855 18446744073709551615 4194304 5690517 140735897208736 140735897206104 4956989 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/16058/statm: 21127 20855 174 366 0 20758 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 93720

[startup+6.30024 s]
/proc/loadavg: 0.87 0.96 0.98 2/66 16059
/proc/meminfo: memFree=269896/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=3.18
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 757 30873 0 0 0 0 299 19 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374608 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16059] ppid=16042 vsize=222224 CPUtime=3.05
/proc/16059/stat : 16059 (gringo) R 16042 16042 1745 0 -1 4202496 55446 0 0 0 286 19 0 0 20 0 1 0 119108060 227557376 47164 18446744073709551615 4194304 6531320 140737460174000 140737460170344 4360311 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/16059/statm: 55556 47164 282 571 0 54977 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 231436

[startup+12.7003 s]
/proc/loadavg: 0.88 0.96 0.98 2/67 16061
/proc/meminfo: memFree=291024/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=155000 CPUtime=3.88
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 46283 0 0 0 375 13 0 0 20 0 1 0 119108615 158720000 37848 18446744073709551615 4194304 6238623 140736499912368 140736499909392 4356260 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 38750 37848 264 500 0 38247 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 186252

[startup+25.5003 s]
/proc/loadavg: 0.91 0.96 0.98 2/67 16061
/proc/meminfo: memFree=289040/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=155000 CPUtime=16.59
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 46858 0 0 0 1646 13 0 0 20 0 1 0 119108615 158720000 38423 18446744073709551615 4194304 6238623 140736499912368 140736499909392 4409917 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 38750 38423 264 500 0 38247 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 186252

[startup+51.1003 s]
/proc/loadavg: 0.94 0.97 0.98 2/67 16061
/proc/meminfo: memFree=149912/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=294056 CPUtime=42
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 81619 0 0 0 4176 24 0 0 20 0 1 0 119108615 301113344 73183 18446744073709551615 4194304 6238623 140736499912368 140736499908920 4305291 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 73514 73183 264 500 0 73011 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.64
Current children cumulated vsize (KiB) 325308

[startup+102.3 s]
/proc/loadavg: 0.97 0.97 0.98 2/67 16061
/proc/meminfo: memFree=135280/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=308572 CPUtime=92.83
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 85257 0 0 0 9258 25 0 0 20 0 1 0 119108615 315977728 76820 18446744073709551615 4194304 6238623 140736499912368 140736499908920 4409871 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 77143 76820 264 500 0 76640 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.47
Current children cumulated vsize (KiB) 339824

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 16061
/proc/meminfo: memFree=121144/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=322516 CPUtime=152.39
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 88749 0 0 0 15212 27 0 0 20 0 1 0 119108615 330256384 80312 18446744073709551615 4194304 6238623 140736499912368 140736499908920 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 80629 80312 264 500 0 80126 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 161.03
Current children cumulated vsize (KiB) 353768

[startup+222.303 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 16061
/proc/meminfo: memFree=119408/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=324400 CPUtime=211.97
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 89207 0 0 0 21170 27 0 0 20 0 1 0 119108615 332185600 80770 18446744073709551615 4194304 6238623 140736499912368 140736499908920 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 81100 80770 264 500 0 80597 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 220.61
Current children cumulated vsize (KiB) 355652

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 16061
/proc/meminfo: memFree=116928/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=326948 CPUtime=271.54
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 89840 0 0 0 27127 27 0 0 20 0 1 0 119108615 334794752 81403 18446744073709551615 4194304 6238623 140736499912368 140736499908920 4635049 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 81737 81403 264 500 0 81234 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 280.18
Current children cumulated vsize (KiB) 358200



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 16061
/proc/meminfo: memFree=116556/1022884 swapFree=0/0
[pid=16042] ppid=16041 vsize=9212 CPUtime=8.64
/proc/16042/stat : 16042 (aspcud-full) S 16041 16042 1745 0 -1 4202496 796 155681 0 0 0 0 793 71 20 0 1 0 119107738 9433088 364 18446744073709551615 4194304 5129932 140736244375952 140736244374016 140148160410718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16042/statm: 2303 364 303 229 0 63 0
[pid=16060] ppid=16042 vsize=327216 CPUtime=291.4
/proc/16060/stat : 16060 (clasp) R 16042 16042 1745 0 -1 4202496 89918 0 0 0 29113 27 0 0 20 0 1 0 119108615 335069184 81481 18446744073709551615 4194304 6238623 140736499912368 140736499908920 4331889 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16060/statm: 81804 81481 264 500 0 81301 0
[pid=16061] ppid=16042 vsize=22040 CPUtime=0
/proc/16061/stat : 16061 (parse.py) S 16042 16042 1745 0 -1 4202496 1307 0 13 0 0 0 0 0 20 0 1 0 119108615 22568960 1129 18446744073709551615 4194304 6642060 140736175866496 140736175864856 140261963896608 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/16061/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 358468

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.365
CPU time (s): 300.127
CPU user time (s): 299.091
CPU system time (s): 1.03606
CPU usage (%): 99.2598
Max. virtual memory (cumulated for all children) (KiB): 530304

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.091
system time used= 1.03606
maximum resident set size= 435996
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 248054
page faults= 14
swaps= 0
block input operations= 44816
block output operations= 53912
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 104
involuntary context switches= 34435

runsolver used 0.520032 second user time and 1.12807 second system time

The end