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/8680dd8a-8600-11e0-b285-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/8680dd8a-8600-11e0-b285-00163e1e087d.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/real/8680dd8a-8600-11e0-b285-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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.04 0.99 0.98 2/59 509
/proc/meminfo: memFree=627848/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=3152 CPUtime=0
/proc/509/stat : 509 (runsolver) R 508 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119079236 3227648 32 18446744073709551615 134512640 134586868 4289873008 4289871056 4151596080 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 788 32 0 19 0 73 0

[startup+0.119453 s]
/proc/loadavg: 1.04 0.99 0.98 2/59 509
/proc/meminfo: memFree=627848/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=0.05
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 740 3617 0 0 0 1 2 2 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200315 s]
/proc/loadavg: 1.04 0.99 0.98 2/59 509
/proc/meminfo: memFree=627848/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=0.05
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 740 3617 0 0 0 1 2 2 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300298 s]
/proc/loadavg: 1.04 0.99 0.98 2/59 509
/proc/meminfo: memFree=627848/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=0.05
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 740 3617 0 0 0 1 2 2 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700226 s]
/proc/loadavg: 1.04 0.99 0.98 2/59 509
/proc/meminfo: memFree=627848/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=0.05
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 740 3617 0 0 0 1 2 2 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.04 0.99 0.98 2/61 525
/proc/meminfo: memFree=590500/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=0.05
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 740 3617 0 0 0 1 2 2 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=525] ppid=509 vsize=50212 CPUtime=1.28
/proc/525/stat : 525 (cudf2lp) R 509 509 1733 0 -1 4202496 14123 0 0 0 117 11 0 0 20 0 1 0 119079240 51417088 10725 18446744073709551615 4194304 5690517 140736964637904 140736964635576 5058400 0 0 16781316 0 0 0 0 17 0 0 0 12 0 0
/proc/525/statm: 12553 10725 160 366 0 12184 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 59424

[startup+3.10033 s]
/proc/loadavg: 1.04 0.99 0.98 2/61 533
/proc/meminfo: memFree=562972/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=0.05
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 740 3617 0 0 0 1 2 2 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=525] ppid=509 vsize=76232 CPUtime=2.75
/proc/525/stat : 525 (cudf2lp) R 509 509 1733 0 -1 4202496 24901 0 0 0 252 23 0 0 20 0 1 0 119079240 78061568 18793 18446744073709551615 4194304 5690517 140736964637904 140736964635272 4951936 0 0 16781316 0 0 0 0 17 0 0 0 19 0 0
/proc/525/statm: 19058 18793 174 366 0 18689 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 85444

[startup+6.30123 s]
/proc/loadavg: 1.11 1.00 0.98 4/61 548
/proc/meminfo: memFree=506536/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=2.88
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 766 28520 0 0 0 1 260 27 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=534] ppid=509 vsize=126828 CPUtime=2.52
/proc/534/stat : 534 (gringo) R 509 509 1733 0 -1 4202496 31181 0 0 0 234 18 0 0 20 0 1 0 119079554 129871872 26996 18446744073709551615 4194304 6531320 140733359450336 140733359447400 4549281 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/534/statm: 31707 26996 280 571 0 31128 0
Current children cumulated CPU time (s) 5.4
Current children cumulated vsize (KiB) 136040

[startup+12.7003 s]
/proc/loadavg: 1.18 1.02 0.99 3/61 674
/proc/meminfo: memFree=200644/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=2.88
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 766 28520 0 0 0 1 260 27 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672720 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=534] ppid=509 vsize=433808 CPUtime=6.74
/proc/534/stat : 534 (gringo) R 509 509 1733 0 -1 4202496 101713 0 0 0 626 48 0 0 20 0 1 0 119079554 444219392 93431 18446744073709551615 4194304 6531320 140733359450336 140733359447144 5502363 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/534/statm: 108452 93431 283 571 0 107873 0
Current children cumulated CPU time (s) 9.62
Current children cumulated vsize (KiB) 443020
heavy processes:
  %CPU=50 pid=675 uid=0 cmd=/usr/bin/ruby1.8 /usr/bin/puppet agent 

[startup+25.5004 s]
/proc/loadavg: 1.36 1.07 1.01 3/62 779
/proc/meminfo: memFree=306848/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=10.02
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 805 130237 0 0 0 1 911 90 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672128 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=686] ppid=509 vsize=133764 CPUtime=7.07
/proc/686/stat : 686 (clasp) R 509 509 1733 0 -1 4202496 38978 0 0 0 691 16 0 0 20 0 1 0 119080573 136974336 32885 18446744073709551615 4194304 6238623 140735387268752 140735387265776 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/686/statm: 33441 32885 264 500 0 32938 0
[pid=687] ppid=509 vsize=22040 CPUtime=0.02
/proc/687/stat : 687 (parse.py) S 509 509 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119080573 22568960 1128 18446744073709551615 4194304 6642060 140733859171488 140733859169848 139958255658784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/687/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 17.11
Current children cumulated vsize (KiB) 165016
heavy processes:

[startup+51.1004 s]
/proc/loadavg: 1.24 1.06 1.00 2/62 779
/proc/meminfo: memFree=303508/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=10.02
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 805 130237 0 0 0 1 911 90 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672128 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=686] ppid=509 vsize=143744 CPUtime=32.21
/proc/686/stat : 686 (clasp) R 509 509 1733 0 -1 4202496 41727 0 0 0 3202 19 0 0 20 0 1 0 119080573 147193856 35634 18446744073709551615 4194304 6238623 140735387268752 140735387265304 4331840 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/686/statm: 35936 35634 264 500 0 35433 0
[pid=687] ppid=509 vsize=22040 CPUtime=0.02
/proc/687/stat : 687 (parse.py) S 509 509 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119080573 22568960 1128 18446744073709551615 4194304 6642060 140733859171488 140733859169848 139958255658784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/687/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 42.25
Current children cumulated vsize (KiB) 174996

[startup+102.3 s]
/proc/loadavg: 1.10 1.05 1.00 2/62 779
/proc/meminfo: memFree=198108/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=10.02
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 805 130237 0 0 0 1 911 90 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672128 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=686] ppid=509 vsize=242840 CPUtime=82.91
/proc/686/stat : 686 (clasp) R 509 509 1733 0 -1 4202496 66477 0 0 0 8260 31 0 0 20 0 1 0 119080573 248668160 60382 18446744073709551615 4194304 6238623 140735387268752 140735387265304 4413038 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/686/statm: 60710 60382 264 500 0 60207 0
[pid=687] ppid=509 vsize=22040 CPUtime=0.02
/proc/687/stat : 687 (parse.py) S 509 509 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119080573 22568960 1128 18446744073709551615 4194304 6642060 140733859171488 140733859169848 139958255658784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/687/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 92.95
Current children cumulated vsize (KiB) 274092

[startup+162.3 s]
/proc/loadavg: 1.04 1.04 1.00 2/62 779
/proc/meminfo: memFree=131892/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=10.02
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 805 130237 0 0 0 1 911 90 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672128 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=686] ppid=509 vsize=308892 CPUtime=142.43
/proc/686/stat : 686 (clasp) R 509 509 1733 0 -1 4202496 82972 0 0 0 14204 39 0 0 20 0 1 0 119080573 316305408 76877 18446744073709551615 4194304 6238623 140735387268752 140735387265304 4331840 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/686/statm: 77223 76877 264 500 0 76720 0
[pid=687] ppid=509 vsize=22040 CPUtime=0.02
/proc/687/stat : 687 (parse.py) S 509 509 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119080573 22568960 1128 18446744073709551615 4194304 6642060 140733859171488 140733859169848 139958255658784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/687/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 152.47
Current children cumulated vsize (KiB) 340144

[startup+222.303 s]
/proc/loadavg: 1.01 1.03 1.00 2/62 779
/proc/meminfo: memFree=126188/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=10.02
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 805 130237 0 0 0 1 911 90 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672128 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=686] ppid=509 vsize=314644 CPUtime=202.02
/proc/686/stat : 686 (clasp) R 509 509 1733 0 -1 4202496 84424 0 0 0 20162 40 0 0 20 0 1 0 119080573 322195456 78328 18446744073709551615 4194304 6238623 140735387268752 140735387265304 4421834 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/686/statm: 78661 78328 264 500 0 78158 0
[pid=687] ppid=509 vsize=22040 CPUtime=0.02
/proc/687/stat : 687 (parse.py) S 509 509 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119080573 22568960 1128 18446744073709551615 4194304 6642060 140733859171488 140733859169848 139958255658784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/687/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 212.06
Current children cumulated vsize (KiB) 345896

[startup+282.3 s]
/proc/loadavg: 1.00 1.02 1.00 2/62 779
/proc/meminfo: memFree=118252/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=10.02
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 805 130237 0 0 0 1 911 90 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672128 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=686] ppid=509 vsize=322560 CPUtime=261.61
/proc/686/stat : 686 (clasp) R 509 509 1733 0 -1 4202496 86404 0 0 0 26120 41 0 0 20 0 1 0 119080573 330301440 80308 18446744073709551615 4194304 6238623 140735387268752 140735387265304 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/686/statm: 80640 80308 264 500 0 80137 0
[pid=687] ppid=509 vsize=22040 CPUtime=0.02
/proc/687/stat : 687 (parse.py) S 509 509 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119080573 22568960 1128 18446744073709551615 4194304 6642060 140733859171488 140733859169848 139958255658784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/687/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 271.65
Current children cumulated vsize (KiB) 353812



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+310.9 s]
/proc/loadavg: 1.06 1.03 1.00 3/62 779
/proc/meminfo: memFree=116516/1022884 swapFree=0/0
[pid=509] ppid=508 vsize=9212 CPUtime=10.02
/proc/509/stat : 509 (aspcud-full) S 508 509 1733 0 -1 4202496 805 130237 0 0 0 1 911 90 20 0 1 0 119079236 9433088 364 18446744073709551615 4194304 5129932 140736915674064 140736915672128 139660146037854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/509/statm: 2303 364 303 229 0 63 0
[pid=686] ppid=509 vsize=324180 CPUtime=290.02
/proc/686/stat : 686 (clasp) R 509 509 1733 0 -1 4202496 86821 0 0 0 28961 41 0 0 20 0 1 0 119080573 331960320 80725 18446744073709551615 4194304 6238623 140735387268752 140735387265304 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/686/statm: 81045 80725 264 500 0 80542 0
[pid=687] ppid=509 vsize=22040 CPUtime=0.02
/proc/687/stat : 687 (parse.py) S 509 509 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119080573 22568960 1128 18446744073709551615 4194304 6642060 140733859171488 140733859169848 139958255658784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/687/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.06
Current children cumulated vsize (KiB) 355432

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): 310.944
CPU time (s): 300.115
CPU user time (s): 298.747
CPU system time (s): 1.36808
CPU usage (%): 96.5174
Max. virtual memory (cumulated for all children) (KiB): 443020

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.747
system time used= 1.36808
maximum resident set size= 373724
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 219533
page faults= 0
swaps= 0
block input operations= 38336
block output operations= 46648
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 95
involuntary context switches= 37384

runsolver used 0.624039 second user time and 1.28808 second system time

The end