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 -W 300 -M 1124 -w /home/cbse/results/sarge-etch-lenny-squeeze-sid/logs/50.runsolver.aptitude aptitude -s -y --without-recommends install libdebconfclient0 krec libhesiod0 python2.3-diacanvas2 kudzu 

Enforcing wall clock limit (soft limit, will send signal-name then SIGKILL): 300 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: 1.18 1.09 1.05 2/55 25652
/proc/meminfo: memFree=961892/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=3152 CPUtime=0
/proc/25652/stat : 25652 (runsolver) R 25651 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29553687 3227648 33 18446744073709551615 134512640 134586868 4293453632 4293451680 4151542832 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25652/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.200626 s]
/proc/loadavg: 1.18 1.09 1.05 2/55 25652
/proc/meminfo: memFree=961892/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=23840 CPUtime=0
/proc/25652/stat : 25652 (aptitude) D 25651 25652 17863 34816 17863 4202496 145 0 9 0 0 0 0 0 20 0 1 0 29553687 24412160 67 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137578104 140492456354574 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/25652/statm: 5960 67 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300338 s]
/proc/loadavg: 1.18 1.09 1.05 2/55 25652
/proc/meminfo: memFree=961892/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=40832 CPUtime=0
/proc/25652/stat : 25652 (aptitude) D 25651 25652 17863 34816 17863 4202496 178 0 16 0 0 0 0 0 20 0 1 0 29553687 41811968 101 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137577816 140492456355363 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/25652/statm: 10208 101 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.400325 s]
/proc/loadavg: 1.18 1.09 1.05 2/55 25652
/proc/meminfo: memFree=961892/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=54968 CPUtime=0
/proc/25652/stat : 25652 (aptitude) D 25651 25652 17863 34816 17863 4202496 1051 0 25 0 0 0 0 0 20 0 1 0 29553687 56287232 966 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137578168 140492416340037 0 134217728 4096 0 0 0 0 17 0 0 0 38 0 0
/proc/25652/statm: 13742 966 806 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.70025 s]
/proc/loadavg: 1.18 1.09 1.05 2/55 25652
/proc/meminfo: memFree=961892/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=103288 CPUtime=0.01
/proc/25652/stat : 25652 (aptitude) D 25651 25652 17863 34816 17863 4202496 2417 1704 38 4 1 0 0 0 20 0 1 0 29553687 105766912 2256 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137572864 140492453545882 0 134217728 4096 0 0 0 0 17 0 0 0 64 0 0
/proc/25652/statm: 25822 2256 1044 1052 0 1159 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 103288

[startup+1.50031 s]
/proc/loadavg: 1.18 1.09 1.05 1/56 25656
/proc/meminfo: memFree=953568/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=103288 CPUtime=0.03
/proc/25652/stat : 25652 (aptitude) D 25651 25652 17863 34816 17863 4202496 6484 1704 155 4 1 2 0 0 20 0 1 0 29553687 105766912 6440 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137572864 140492453545816 0 134217728 4096 0 0 0 0 17 0 0 0 143 0 0
/proc/25652/statm: 25822 6440 5228 1052 0 1159 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 103288

[startup+3.10019 s]
/proc/loadavg: 1.18 1.09 1.05 2/56 25656
/proc/meminfo: memFree=914260/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=123068 CPUtime=0.78
/proc/25652/stat : 25652 (aptitude) R 25651 25652 17863 34816 17863 4202496 17501 1704 187 4 64 14 0 0 20 0 1 0 29553687 126021632 15965 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137570824 140492416036340 0 134217728 4096 0 0 0 0 17 0 0 0 228 0 0
/proc/25652/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.78
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.17 1.09 1.05 2/57 25658
/proc/meminfo: memFree=804612/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=147212 CPUtime=3.89
/proc/25652/stat : 25652 (aptitude) S 25651 25652 17863 34816 17863 4202496 24640 2200 187 6 364 24 0 1 20 0 2 0 29553687 150745088 20511 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137573152 140492427241035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 234 0 0
/proc/25652/statm: 36803 20511 10357 1052 0 12140 0
[pid=25652/tid=25657] ppid=25651 vsize=147212 CPUtime=0.4
/proc/25652/task/25657/stat : 25657 (aptitude) R 25651 25652 17863 34816 17863 4202560 2811 2200 0 6 39 0 0 1 20 0 2 0 29554007 150745088 20511 18446744073709551615 140492458496000 140492462803352 140737137581392 140492346164328 140492415996580 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.89
Current children cumulated vsize (KiB) 147212
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.15 1.09 1.05 2/57 25658
/proc/meminfo: memFree=748688/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=261784 CPUtime=10.25
/proc/25652/stat : 25652 (aptitude) S 25651 25652 17863 34816 17863 4202496 37054 2200 187 6 996 28 0 1 20 0 2 0 29553687 268066816 32771 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137573152 140492427241035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 234 0 0
/proc/25652/statm: 65446 32771 10359 1052 0 40783 0
[pid=25652/tid=25657] ppid=25651 vsize=261784 CPUtime=6.77
/proc/25652/task/25657/stat : 25657 (aptitude) R 25651 25652 17863 34816 17863 4202560 15223 2200 0 6 670 6 0 1 20 0 2 0 29554007 268066816 32771 18446744073709551615 140492458496000 140492462803352 140737137581392 140492346167240 140492459906802 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.25
Current children cumulated vsize (KiB) 261784

[startup+25.5032 s]
/proc/loadavg: 1.12 1.08 1.05 2/57 25658
/proc/meminfo: memFree=647380/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=360284 CPUtime=23
/proc/25652/stat : 25652 (aptitude) S 25651 25652 17863 34816 17863 4202496 61961 2200 187 6 2259 40 0 1 20 0 2 0 29553687 368930816 57378 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137573152 140492427241035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 234 0 0
/proc/25652/statm: 90071 57378 10359 1052 0 65408 0
[pid=25652/tid=25657] ppid=25651 vsize=360284 CPUtime=19.51
/proc/25652/task/25657/stat : 25657 (aptitude) R 25651 25652 17863 34816 17863 4202560 40130 2200 0 6 1933 17 0 1 20 0 2 0 29554007 368930816 57378 18446744073709551615 140492458496000 140492462803352 140737137581392 140492346166920 140492461193961 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23
Current children cumulated vsize (KiB) 360284

[startup+51.1003 s]
/proc/loadavg: 1.08 1.08 1.05 2/57 25658
/proc/meminfo: memFree=484940/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=524256 CPUtime=48.48
/proc/25652/stat : 25652 (aptitude) S 25651 25652 17863 34816 17863 4202496 103027 2200 187 6 4790 57 0 1 20 0 2 0 29553687 536838144 98314 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137573152 140492427241035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 234 0 0
/proc/25652/statm: 131064 98314 10374 1052 0 106401 0
[pid=25652/tid=25657] ppid=25651 vsize=524256 CPUtime=44.99
/proc/25652/task/25657/stat : 25657 (aptitude) R 25651 25652 17863 34816 17863 4202560 81189 2200 0 6 4464 34 0 1 20 0 2 0 29554007 536838144 98314 18446744073709551615 140492458496000 140492462803352 140737137581392 140492346166920 140492416006389 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.48
Current children cumulated vsize (KiB) 524256

[startup+102.3 s]
/proc/loadavg: 1.03 1.06 1.04 2/57 25658
/proc/meminfo: memFree=164268/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=848580 CPUtime=99.43
/proc/25652/stat : 25652 (aptitude) S 25651 25652 17863 34816 17863 4202496 184213 2200 187 6 9845 97 0 1 20 0 2 0 29553687 868945920 179303 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137573152 140492427241035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 234 0 0
/proc/25652/statm: 212145 179303 10375 1052 0 187482 0
[pid=25652/tid=25657] ppid=25651 vsize=848580 CPUtime=95.93
/proc/25652/task/25657/stat : 25657 (aptitude) R 25651 25652 17863 34816 17863 4202560 162375 2200 0 6 9518 74 0 1 20 0 2 0 29554007 868945920 179303 18446744073709551615 140492458496000 140492462803352 140737137581392 140492346164760 140492461076673 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 99.43
Current children cumulated vsize (KiB) 848580



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+156.1 s]
/proc/loadavg: 1.13 1.08 1.05 3/57 25658
/proc/meminfo: memFree=10132/1022884 swapFree=0/0
[pid=25652] ppid=25651 vsize=1151496 CPUtime=151.33
/proc/25652/stat : 25652 (aptitude) S 25651 25652 17863 34816 17863 4202496 260240 2200 322 6 14990 142 0 1 20 0 2 0 29553687 1179131904 243624 18446744073709551615 140492458496000 140492462803352 140737137581392 140737137573152 140492427241035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 234 0 0
/proc/25652/statm: 287874 243624 10266 1052 0 263211 0
[pid=25652/tid=25657] ppid=25651 vsize=1151496 CPUtime=147.84
/proc/25652/task/25657/stat : 25657 (aptitude) R 25651 25652 17863 34816 17863 4202560 238393 2200 131 6 14663 120 0 1 20 0 2 0 29554007 1179131904 243624 18446744073709551615 140492458496000 140492462803352 140737137581392 140492346166968 140492416036342 0 134217728 4096 0 0 0 0 -1 0 0 0 123 0 0
Current children cumulated CPU time (s) 151.33
Current children cumulated vsize (KiB) 1151496

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

Solver just ended. Dumping a history of the last processes samples

Child ended because it received signal 15 (SIGTERM)
Real time (s): 156.202
CPU time (s): 151.433
CPU user time (s): 149.937
CPU system time (s): 1.49609
CPU usage (%): 96.9471
Max. virtual memory (cumulated for all children) (KiB): 1151496

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.937
system time used= 1.49609
maximum resident set size= 979792
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262462
page faults= 329
swaps= 0
block input operations= 260552
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2789
involuntary context switches= 3409

runsolver used 0.180011 second user time and 0.548034 second system time

The end