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/93.runsolver.aptitude aptitude -s -y --without-recommends install libccid wmrack librrd0 xbindkeys freeradius-mysql 

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.38 1.14 1.08 2/55 26281
/proc/meminfo: memFree=959520/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=3152 CPUtime=0
/proc/26281/stat : 26281 (runsolver) R 26280 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29835791 3227648 32 18446744073709551615 134512640 134586868 4288756672 4288754720 4151333936 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26281/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.146187 s]
/proc/loadavg: 1.38 1.14 1.08 2/55 26281
/proc/meminfo: memFree=959520/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=12328 CPUtime=0
/proc/26281/stat : 26281 (aptitude) D 26280 26281 17863 34816 17863 4202496 129 0 5 0 0 0 0 0 20 0 1 0 29835791 12623872 51 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419987576 140473834370595 0 0 0 0 0 0 0 17 0 0 0 13 0 0
/proc/26281/statm: 3082 51 36 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.200406 s]
/proc/loadavg: 1.38 1.14 1.08 2/55 26281
/proc/meminfo: memFree=959520/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=25980 CPUtime=0
/proc/26281/stat : 26281 (aptitude) D 26280 26281 17863 34816 17863 4202496 150 0 10 0 0 0 0 0 20 0 1 0 29835791 26603520 73 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419987336 140473834369814 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/26281/statm: 6495 73 48 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 25980

[startup+0.300388 s]
/proc/loadavg: 1.38 1.14 1.08 2/55 26281
/proc/meminfo: memFree=959520/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=48572 CPUtime=0
/proc/26281/stat : 26281 (aptitude) D 26280 26281 17863 34816 17863 4202496 187 0 19 0 0 0 0 0 20 0 1 0 29835791 49737728 112 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419986488 140473834369758 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/26281/statm: 12143 112 68 1052 0 66 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 48572

[startup+0.700324 s]
/proc/loadavg: 1.38 1.14 1.08 2/55 26281
/proc/meminfo: memFree=959520/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=103288 CPUtime=0.02
/proc/26281/stat : 26281 (aptitude) D 26280 26281 17863 34816 17863 4202496 2668 1705 39 4 0 2 0 0 20 0 1 0 29835791 105766912 2509 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982144 140473831561114 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/26281/statm: 25822 2509 1297 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.5002 s]
/proc/loadavg: 1.35 1.13 1.08 1/56 26285
/proc/meminfo: memFree=951692/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=103288 CPUtime=0.06
/proc/26281/stat : 26281 (aptitude) R 26280 26281 17863 34816 17863 4202496 8271 1705 178 4 4 2 0 0 20 0 1 0 29835791 105766912 8251 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419981936 140473831352067 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/26281/statm: 25822 8251 7039 1052 0 1159 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 103288

[startup+3.10021 s]
/proc/loadavg: 1.35 1.13 1.08 2/56 26285
/proc/meminfo: memFree=936440/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=123068 CPUtime=0.7
/proc/26281/stat : 26281 (aptitude) R 26280 26281 17863 34816 17863 4202496 17474 1705 212 4 58 12 0 0 20 0 1 0 29835791 126021632 15964 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419980104 140473805267312 0 134217728 4096 0 0 0 0 17 0 0 0 235 0 0
/proc/26281/statm: 30767 15964 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30025 s]
/proc/loadavg: 1.35 1.13 1.08 2/57 26287
/proc/meminfo: memFree=804620/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=141760 CPUtime=3.54
/proc/26281/stat : 26281 (aptitude) S 26280 26281 17863 34816 17863 4202496 23036 2202 212 6 336 18 0 0 20 0 2 0 29835791 145162240 19148 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982432 140473805256267 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 267 0 0
/proc/26281/statm: 35440 19148 10355 1052 0 10777 0
[pid=26281/tid=26286] ppid=26280 vsize=141760 CPUtime=0.1
/proc/26281/task/26286/stat : 26286 (aptitude) R 26280 26281 17863 34816 17863 4202560 1265 2202 0 6 10 0 0 0 20 0 2 0 29836142 145162240 19148 18446744073709551615 140473836511232 140473840818584 140734419990672 140473724178920 140473794021753 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.54
Current children cumulated vsize (KiB) 141760
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.30 1.13 1.08 2/57 26287
/proc/meminfo: memFree=693020/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=318588 CPUtime=9.92
/proc/26281/stat : 26281 (aptitude) S 26280 26281 17863 34816 17863 4202496 51854 2202 212 6 964 28 0 0 20 0 2 0 29835791 326234112 46969 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982432 140473805256267 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 267 0 0
/proc/26281/statm: 79647 46969 10359 1052 0 54984 0
[pid=26281/tid=26286] ppid=26280 vsize=318588 CPUtime=6.47
/proc/26281/task/26286/stat : 26286 (aptitude) R 26280 26281 17863 34816 17863 4202560 30081 2202 0 6 637 10 0 0 20 0 2 0 29836142 326234112 46969 18446744073709551615 140473836511232 140473840818584 140734419990672 140473724179992 140473839153045 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.92
Current children cumulated vsize (KiB) 318588
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.25 1.12 1.08 2/57 26287
/proc/meminfo: memFree=596424/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=413956 CPUtime=22.65
/proc/26281/stat : 26281 (aptitude) S 26280 26281 17863 34816 17863 4202496 76252 2202 212 6 2231 34 0 0 20 0 2 0 29835791 423890944 70833 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982432 140473805256267 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 267 0 0
/proc/26281/statm: 103489 70833 10360 1052 0 78826 0
[pid=26281/tid=26286] ppid=26280 vsize=413956 CPUtime=19.2
/proc/26281/task/26286/stat : 26286 (aptitude) R 26280 26281 17863 34816 17863 4202560 54479 2202 0 6 1904 16 0 0 20 0 2 0 29836142 423890944 70833 18446744073709551615 140473836511232 140473840818584 140734419990672 140473724177720 140473839107649 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.65
Current children cumulated vsize (KiB) 413956

[startup+51.1003 s]
/proc/loadavg: 1.16 1.11 1.08 2/57 26287
/proc/meminfo: memFree=377936/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=633328 CPUtime=48.05
/proc/26281/stat : 26281 (aptitude) S 26280 26281 17863 34816 17863 4202496 131011 2202 212 6 4739 66 0 0 20 0 2 0 29835791 648527872 125590 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982432 140473805256267 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 267 0 0
/proc/26281/statm: 158332 125590 10375 1052 0 133669 0
[pid=26281/tid=26286] ppid=26280 vsize=633328 CPUtime=44.6
/proc/26281/task/26286/stat : 26286 (aptitude) R 26280 26281 17863 34816 17863 4202560 109231 2202 0 6 4411 49 0 0 20 0 2 0 29836142 648527872 125590 18446744073709551615 140473836511232 140473840818584 140734419990672 140473724181688 140473838139553 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 48.05
Current children cumulated vsize (KiB) 633328

[startup+102.3 s]
/proc/loadavg: 1.42 1.18 1.10 1/57 26511
/proc/meminfo: memFree=8128/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=1029052 CPUtime=94.05
/proc/26281/stat : 26281 (aptitude) S 26280 26281 17863 34816 17863 4202496 229916 2202 212 6 9278 127 0 0 20 0 2 0 29835791 1053749248 224468 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982432 140473805256267 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 267 0 0
/proc/26281/statm: 257263 224468 10375 1052 0 232600 0
[pid=26281/tid=26286] ppid=26280 vsize=1029052 CPUtime=90.61
/proc/26281/task/26286/stat : 26286 (aptitude) R 26280 26281 17863 34816 17863 4202560 208136 2202 0 6 8951 110 0 0 20 0 2 0 29836142 1053749248 224468 18446744073709551615 140473836511232 140473840818584 140734419990672 140473724180200 140473838140974 0 134217728 4096 0 0 0 0 -1 0 0 0 153 0 0
Current children cumulated CPU time (s) 94.05
Current children cumulated vsize (KiB) 1029052



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+119.3 s]
/proc/loadavg: 1.33 1.17 1.10 2/57 26511
/proc/meminfo: memFree=9284/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=1151812 CPUtime=108.57
/proc/26281/stat : 26281 (aptitude) S 26280 26281 17863 34816 17863 4202496 260775 2202 425 6 10709 148 0 0 20 0 2 0 29835791 1179455488 232988 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982432 140473805256267 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 267 0 0
/proc/26281/statm: 287953 232988 8699 1052 0 263290 0
[pid=26281/tid=26286] ppid=26280 vsize=1151812 CPUtime=105.12
/proc/26281/task/26286/stat : 26286 (aptitude) R 26280 26281 17863 34816 17863 4202560 238995 2202 213 6 10381 131 0 0 20 0 2 0 29836142 1179455488 232988 18446744073709551615 140473836511232 140473840818584 140734419990672 140473724179992 140473838740608 0 134217728 4096 0 0 0 0 -1 0 0 0 370 0 0
Current children cumulated CPU time (s) 108.57
Current children cumulated vsize (KiB) 1151812

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

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

[startup+119.3 s]
/proc/loadavg: 1.33 1.17 1.10 2/57 26511
/proc/meminfo: memFree=9284/1022884 swapFree=0/0
[pid=26281] ppid=26280 vsize=1151812 CPUtime=108.57
/proc/26281/stat : 26281 (aptitude) S 26280 26281 17863 34816 17863 4202496 260775 2202 425 6 10709 148 0 0 20 0 2 0 29835791 1179455488 232988 18446744073709551615 140473836511232 140473840818584 140734419990672 140734419982432 140473805256267 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 267 0 0
/proc/26281/statm: 287953 232988 8699 1052 0 263290 0
[pid=26281/tid=26286] ppid=26280 vsize=1151812 CPUtime=105.12
/proc/26281/task/26286/stat : 26286 (aptitude) R 26280 26281 17863 34816 17863 4202560 238995 2202 213 6 10381 131 0 0 20 0 2 0 29836142 1179455488 232988 18446744073709551615 140473836511232 140473840818584 140734419990672 140473724179992 140473838740608 0 134217728 4096 0 0 0 0 -1 0 0 0 370 0 0
Current children cumulated CPU time (s) 108.57
Current children cumulated vsize (KiB) 1151812

Child ended because it received signal 15 (SIGTERM)
Real time (s): 119.475
CPU time (s): 108.739
CPU user time (s): 107.199
CPU system time (s): 1.5401
CPU usage (%): 91.0137
Max. virtual memory (cumulated for all children) (KiB): 1151812

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 107.199
system time used= 1.5401
maximum resident set size= 935772
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263115
page faults= 431
swaps= 0
block input operations= 258288
block output operations= 128
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2871
involuntary context switches= 7071

runsolver used 0.16801 second user time and 0.400025 second system time

The end