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/45.runsolver.aptitude aptitude -s -y --without-recommends install ftpgrab libtag1-doc libparams-validate-perl dovecot-common python-tclink 

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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.32 1.15 1.06 2/55 25607
/proc/meminfo: memFree=777672/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=3152 CPUtime=0
/proc/25607/stat : 25607 (runsolver) R 25606 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29506421 3227648 33 18446744073709551615 134512640 134586868 4290959616 4290957664 4151436336 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 13715 488 399 1052 0 73 0

[startup+0.149433 s]
/proc/loadavg: 1.32 1.15 1.06 2/55 25607
/proc/meminfo: memFree=777672/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=103288 CPUtime=0.13
/proc/25607/stat : 25607 (aptitude) R 25606 25607 17863 34816 17863 4202496 11274 1710 0 0 11 2 0 0 20 0 1 0 29506421 105766912 11075 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852032 139768505668864 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 25822 11075 9863 1052 0 1159 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 103288

[startup+0.200282 s]
/proc/loadavg: 1.32 1.15 1.06 2/55 25607
/proc/meminfo: memFree=777672/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=103288 CPUtime=0.18
/proc/25607/stat : 25607 (aptitude) R 25606 25607 17863 34816 17863 4202496 11300 1710 0 0 16 2 0 0 20 0 1 0 29506421 105766912 11101 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852032 139768542916145 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300265 s]
/proc/loadavg: 1.32 1.15 1.06 2/55 25607
/proc/meminfo: memFree=777672/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=103432 CPUtime=0.28
/proc/25607/stat : 25607 (aptitude) R 25606 25607 17863 34816 17863 4202496 11427 1710 0 0 26 2 0 0 20 0 1 0 29506421 105914368 11220 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804850544 139768542333044 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700197 s]
/proc/loadavg: 1.32 1.15 1.06 2/55 25607
/proc/meminfo: memFree=777672/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=123068 CPUtime=0.68
/proc/25607/stat : 25607 (aptitude) R 25606 25607 17863 34816 17863 4202496 17689 1710 0 0 61 7 0 0 20 0 1 0 29506421 126021632 15965 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804850200 139768542417036 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.32 1.15 1.06 2/57 25612
/proc/meminfo: memFree=757700/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=136068 CPUtime=1.48
/proc/25607/stat : 25607 (aptitude) R 25606 25607 17863 34816 17863 4202496 20644 1710 0 0 140 8 0 0 20 0 2 0 29506421 139333632 17563 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852040 139768505016600 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 34017 17563 10207 1052 0 9354 0
[pid=25607/tid=25612] ppid=25606 vsize=136068 CPUtime=0
/proc/25607/task/25612/stat : 25612 (aptitude) S 25606 25607 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29506498 139333632 17563 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435193856 139768516260564 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 136068

[startup+3.10024 s]
/proc/loadavg: 1.29 1.15 1.06 2/57 25612
/proc/meminfo: memFree=747532/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=137820 CPUtime=3.08
/proc/25607/stat : 25607 (aptitude) R 25606 25607 17863 34816 17863 4202496 21978 2208 0 0 292 15 1 0 20 0 2 0 29506421 141127680 17929 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804847472 139768549151980 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 34455 17929 10303 1052 0 9792 0
[pid=25607/tid=25612] ppid=25606 vsize=137820 CPUtime=0.01
/proc/25607/task/25612/stat : 25612 (aptitude) S 25606 25607 17863 34816 17863 4202560 6 2208 0 0 0 0 1 0 20 0 2 0 29506498 141127680 17929 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435193856 139768516260564 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 137820

[startup+6.30023 s]
/proc/loadavg: 1.29 1.15 1.06 2/57 25613
/proc/meminfo: memFree=706240/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=251044 CPUtime=6.27
/proc/25607/stat : 25607 (aptitude) S 25606 25607 17863 34816 17863 4202496 34755 2208 0 0 606 20 1 0 20 0 2 0 29506421 257069056 30106 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852528 139768516261451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 62761 30106 10359 1052 0 38098 0
[pid=25607/tid=25612] ppid=25606 vsize=251044 CPUtime=2.85
/proc/25607/task/25612/stat : 25612 (aptitude) R 25606 25607 17863 34816 17863 4202560 12776 2208 0 0 280 4 1 0 20 0 2 0 29506498 257069056 30106 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435185304 139768550212453 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 251044

[startup+12.7002 s]
/proc/loadavg: 1.25 1.14 1.06 2/57 25613
/proc/meminfo: memFree=656144/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=296768 CPUtime=12.63
/proc/25607/stat : 25607 (aptitude) S 25606 25607 17863 34816 17863 4202496 46333 2208 0 0 1238 24 1 0 20 0 2 0 29506421 303890432 41502 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852528 139768516261451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 74192 41502 10360 1052 0 49529 0
[pid=25607/tid=25612] ppid=25606 vsize=296768 CPUtime=9.22
/proc/25607/task/25612/stat : 25612 (aptitude) R 25606 25607 17863 34816 17863 4202560 24354 2208 0 0 912 9 1 0 20 0 2 0 29506498 303890432 41502 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435186784 139768549727325 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 296768

[startup+25.5003 s]
/proc/loadavg: 1.21 1.14 1.06 2/57 25613
/proc/meminfo: memFree=578644/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=371784 CPUtime=25.36
/proc/25607/stat : 25607 (aptitude) S 25606 25607 17863 34816 17863 4202496 65732 2208 0 0 2499 36 1 0 20 0 2 0 29506421 380706816 60258 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852528 139768516261451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 92946 60258 10360 1052 0 68283 0
[pid=25607/tid=25612] ppid=25606 vsize=371784 CPUtime=21.94
/proc/25607/task/25612/stat : 25612 (aptitude) R 25606 25607 17863 34816 17863 4202560 43753 2208 0 0 2172 21 1 0 20 0 2 0 29506498 380706816 60258 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435185176 139768542917170 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 371784

[startup+51.1003 s]
/proc/loadavg: 1.14 1.13 1.06 2/57 25613
/proc/meminfo: memFree=403184/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=548696 CPUtime=50.84
/proc/25607/stat : 25607 (aptitude) S 25606 25607 17863 34816 17863 4202496 110105 2208 0 0 5033 50 1 0 20 0 2 0 29506421 561864704 104501 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852528 139768516261451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 137174 104501 10360 1052 0 112511 0
[pid=25607/tid=25612] ppid=25606 vsize=548696 CPUtime=47.42
/proc/25607/task/25612/stat : 25612 (aptitude) R 25606 25607 17863 34816 17863 4202560 88126 2208 0 0 4706 35 1 0 20 0 2 0 29506498 561864704 104501 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435185176 139768550162971 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 50.84
Current children cumulated vsize (KiB) 548696

[startup+102.3 s]
/proc/loadavg: 1.05 1.10 1.05 2/57 25613
/proc/meminfo: memFree=117984/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=830460 CPUtime=101.8
/proc/25607/stat : 25607 (aptitude) S 25606 25607 17863 34816 17863 4202496 180518 2208 0 0 10095 84 1 0 20 0 2 0 29506421 850391040 174902 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852528 139768516261451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 207615 174912 10375 1052 0 182952 0
[pid=25607/tid=25612] ppid=25606 vsize=830460 CPUtime=98.39
/proc/25607/task/25612/stat : 25612 (aptitude) R 25606 25607 17863 34816 17863 4202560 158543 2208 0 0 9769 69 1 0 20 0 2 0 29506498 850391040 174912 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435187992 139768550141004 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 101.8
Current children cumulated vsize (KiB) 830460



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+150.1 s]
/proc/loadavg: 1.27 1.15 1.07 2/57 25613
/proc/meminfo: memFree=8620/1022884 swapFree=0/0
[pid=25607] ppid=25606 vsize=1152240 CPUtime=146.76
/proc/25607/stat : 25607 (aptitude) S 25606 25607 17863 34816 17863 4202496 261029 2208 242 0 14537 138 1 0 20 0 2 0 29506421 1179893760 247623 18446744073709551615 139768547516416 139768551823768 140736804860768 140736804852528 139768516261451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25607/statm: 288060 247623 8613 1052 0 263397 0
[pid=25607/tid=25612] ppid=25606 vsize=1152240 CPUtime=143.33
/proc/25607/task/25612/stat : 25612 (aptitude) R 25606 25607 17863 34816 17863 4202560 239044 2208 242 0 14209 123 1 0 20 0 2 0 29506498 1179893760 247623 18446744073709551615 139768547516416 139768551823768 140736804860768 139768435187384 139768550290587 0 134217728 4096 0 0 0 0 -1 0 0 0 235 0 0
Current children cumulated CPU time (s) 146.76
Current children cumulated vsize (KiB) 1152240

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): 150.401
CPU time (s): 146.921
CPU user time (s): 145.469
CPU system time (s): 1.45209
CPU usage (%): 97.6861
Max. virtual memory (cumulated for all children) (KiB): 1152240

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 145.469
system time used= 1.45209
maximum resident set size= 993324
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263366
page faults= 242
swaps= 0
block input operations= 4416
block output operations= 80
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 643
involuntary context switches= 3374

runsolver used 0.216013 second user time and 0.49203 second system time

The end