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/51.runsolver.aptitude aptitude -s -y --without-recommends install kdesdk-misc libdb4.1++ libwxgtk2.4 alsa-modules-2.4.27-3-k7 libminc0 

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.13 1.08 1.05 2/55 25661
/proc/meminfo: memFree=949448/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=3152 CPUtime=0
/proc/25661/stat : 25661 (runsolver) R 25660 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29569516 3227648 33 18446744073709551615 134512640 134586868 4286679232 4286677280 4152206384 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25661/statm: 788 33 0 19 0 73 0

[startup+0.131802 s]
/proc/loadavg: 1.13 1.08 1.05 2/55 25661
/proc/meminfo: memFree=949448/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=38696 CPUtime=0
/proc/25661/stat : 25661 (aptitude) D 25660 25661 17863 34816 17863 4202496 175 0 14 0 0 0 0 0 20 0 1 0 29569516 39624704 97 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122019480 139698261664502 0 0 0 0 0 0 0 17 0 0 0 12 0 0
/proc/25661/statm: 9674 97 61 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 38696

[startup+0.200434 s]
/proc/loadavg: 1.13 1.08 1.05 2/55 25661
/proc/meminfo: memFree=949448/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=54860 CPUtime=0
/proc/25661/stat : 25661 (aptitude) D 25660 25661 17863 34816 17863 4202496 624 0 22 0 0 0 0 0 20 0 1 0 29569516 56176640 545 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122022360 139698261616569 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/25661/statm: 13715 545 448 1052 0 73 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54860

[startup+0.30039 s]
/proc/loadavg: 1.13 1.08 1.05 2/55 25661
/proc/meminfo: memFree=949448/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=63384 CPUtime=0.01
/proc/25661/stat : 25661 (aptitude) S 25660 25661 17863 34816 17863 4202496 1215 0 28 0 0 1 0 0 20 0 1 0 29569516 64905216 1108 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014200 139698221651696 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/25661/statm: 15846 1108 929 1052 0 109 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 63384

[startup+0.700337 s]
/proc/loadavg: 1.13 1.08 1.05 2/55 25661
/proc/meminfo: memFree=949448/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=103288 CPUtime=0.02
/proc/25661/stat : 25661 (aptitude) D 25660 25661 17863 34816 17863 4202496 5851 1705 93 2 0 2 0 0 20 0 1 0 29569516 105766912 5745 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014624 139698258855834 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/25661/statm: 25822 5745 4533 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.50031 s]
/proc/loadavg: 1.13 1.08 1.05 2/56 25665
/proc/meminfo: memFree=931452/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=123068 CPUtime=0.54
/proc/25661/stat : 25661 (aptitude) D 25660 25661 17863 34816 17863 4202496 17563 1705 114 2 47 7 0 0 20 0 1 0 29569516 126021632 15954 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122012584 139698232562032 0 134217728 4096 0 0 0 0 17 0 0 0 93 0 0
/proc/25661/statm: 30767 15954 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.54
Current children cumulated vsize (KiB) 123068

[startup+3.10021 s]
/proc/loadavg: 1.12 1.08 1.05 2/56 25665
/proc/meminfo: memFree=826548/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=136048 CPUtime=1.56
/proc/25661/stat : 25661 (aptitude) R 25660 25661 17863 34816 17863 4202496 20527 1705 114 2 141 15 0 0 20 0 2 0 29569516 139313152 17559 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014424 139698258509328 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/25661/statm: 34012 17559 10207 1052 0 9349 0
Current children cumulated CPU time (s) 1.56
Current children cumulated vsize (KiB) 136048
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.12 1.08 1.05 2/57 25667
/proc/meminfo: memFree=793804/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=228976 CPUtime=4.72
/proc/25661/stat : 25661 (aptitude) S 25660 25661 17863 34816 17863 4202496 28758 2201 114 3 448 23 0 1 20 0 2 0 29569516 234471424 24576 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014912 139698232550987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 152 0 0
/proc/25661/statm: 57244 24576 10359 1052 0 32581 0
[pid=25661/tid=25666] ppid=25660 vsize=228976 CPUtime=1.28
/proc/25661/task/25666/stat : 25666 (aptitude) R 25660 25661 17863 34816 17863 4202560 6875 2201 0 3 125 2 0 1 20 0 2 0 29569750 234471424 24576 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151476920 139698266513989 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.72
Current children cumulated vsize (KiB) 228976
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.10 1.08 1.05 2/57 25667
/proc/meminfo: memFree=725604/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=297804 CPUtime=11.08
/proc/25661/stat : 25661 (aptitude) S 25660 25661 17863 34816 17863 4202496 46499 2201 114 3 1077 30 0 1 20 0 2 0 29569516 304951296 41797 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014912 139698232550987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 152 0 0
/proc/25661/statm: 74451 41797 10360 1052 0 49788 0
[pid=25661/tid=25666] ppid=25660 vsize=297804 CPUtime=7.65
/proc/25661/task/25666/stat : 25666 (aptitude) R 25660 25661 17863 34816 17863 4202560 24616 2201 0 3 754 10 0 1 20 0 2 0 29569750 304951296 41797 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151474712 139698259206550 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.08
Current children cumulated vsize (KiB) 297804

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

[startup+12.8003 s]
/proc/loadavg: 1.10 1.08 1.05 2/57 25667
/proc/meminfo: memFree=725604/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=298596 CPUtime=11.18
/proc/25661/stat : 25661 (aptitude) S 25660 25661 17863 34816 17863 4202496 46698 2201 114 3 1087 30 0 1 20 0 2 0 29569516 305762304 41996 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014912 139698232550987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 152 0 0
/proc/25661/statm: 74649 41996 10360 1052 0 49986 0
[pid=25661/tid=25666] ppid=25660 vsize=298596 CPUtime=7.75
/proc/25661/task/25666/stat : 25666 (aptitude) R 25660 25661 17863 34816 17863 4202560 24815 2201 0 3 764 10 0 1 20 0 2 0 29569750 305762304 41996 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151476920 139698266636013 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.18
Current children cumulated vsize (KiB) 298596

[startup+19.2002 s]
/proc/loadavg: 1.09 1.07 1.05 2/57 25667
/proc/meminfo: memFree=679848/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=332060 CPUtime=17.55
/proc/25661/stat : 25661 (aptitude) S 25660 25661 17863 34816 17863 4202496 55291 2201 114 3 1720 34 0 1 20 0 2 0 29569516 340029440 50355 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014912 139698232550987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 152 0 0
/proc/25661/statm: 83015 50355 10360 1052 0 58352 0
[pid=25661/tid=25666] ppid=25660 vsize=332060 CPUtime=14.11
/proc/25661/task/25666/stat : 25666 (aptitude) R 25660 25661 17863 34816 17863 4202560 33408 2201 0 3 1397 13 0 1 20 0 2 0 29569750 340029440 50355 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151474712 139698221316473 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.55
Current children cumulated vsize (KiB) 332060

[startup+20.8002 s]
/proc/loadavg: 1.09 1.07 1.05 2/57 25667
/proc/meminfo: memFree=670920/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=344260 CPUtime=19.15
/proc/25661/stat : 25661 (aptitude) S 25660 25661 17863 34816 17863 4202496 58334 2201 114 3 1879 35 0 1 20 0 2 0 29569516 352522240 53381 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014912 139698232550987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 152 0 0
/proc/25661/statm: 86065 53381 10360 1052 0 61402 0
[pid=25661/tid=25666] ppid=25660 vsize=344260 CPUtime=15.71
/proc/25661/task/25666/stat : 25666 (aptitude) R 25660 25661 17863 34816 17863 4202560 36451 2201 0 3 1556 14 0 1 20 0 2 0 29569750 352522240 53381 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151476920 139698221306160 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.15
Current children cumulated vsize (KiB) 344260

[startup+21.6004 s]
/proc/loadavg: 1.09 1.07 1.05 2/57 25667
/proc/meminfo: memFree=663356/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=347860 CPUtime=19.85
/proc/25661/stat : 25661 (aptitude) D 25660 25661 17863 34816 17863 4202496 59267 2201 119 3 1948 36 0 1 20 0 2 0 29569516 356208640 54317 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014840 139698220949824 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 158 0 0
/proc/25661/statm: 86965 54317 10377 1052 0 62302 0
[pid=25661/tid=25666] ppid=25660 vsize=347860 CPUtime=16.41
/proc/25661/task/25666/stat : 25666 (aptitude) S 25660 25661 17863 34816 17863 4202560 37354 2201 1 3 1625 15 0 1 20 0 2 0 29569750 356208640 54317 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151483392 139698232550100 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 19.85
Current children cumulated vsize (KiB) 347860

[startup+22.4002 s]
/proc/loadavg: 1.08 1.07 1.05 2/57 25667
/proc/meminfo: memFree=658892/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=347920 CPUtime=20.53
/proc/25661/stat : 25661 (aptitude) R 25660 25661 17863 34816 17863 4202496 62128 2201 127 3 2016 36 0 1 20 0 2 0 29569516 356270080 54515 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014968 139698264634987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 171 0 0
/proc/25661/statm: 86980 54515 10410 1052 0 62310 0
[pid=25661/tid=25666] ppid=25660 vsize=347920 CPUtime=16.41
/proc/25661/task/25666/stat : 25666 (aptitude) S 25660 25661 17863 34816 17863 4202560 37354 2201 1 3 1625 15 0 1 20 0 2 0 29569750 356270080 54515 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151483392 139698232550100 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 20.53
Current children cumulated vsize (KiB) 347920

[startup+22.6002 s]
/proc/loadavg: 1.08 1.07 1.05 2/57 25667
/proc/meminfo: memFree=658892/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=347920 CPUtime=20.74
/proc/25661/stat : 25661 (aptitude) R 25660 25661 17863 34816 17863 4202496 62449 2701 127 3 2028 44 0 2 20 0 2 0 29569516 356270080 54386 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122014968 139698221649989 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 171 0 0
/proc/25661/statm: 86980 54386 10410 1052 0 62310 0
[pid=25661/tid=25666] ppid=25660 vsize=347920 CPUtime=16.42
/proc/25661/task/25666/stat : 25666 (aptitude) S 25660 25661 17863 34816 17863 4202560 37354 2701 1 3 1625 15 0 2 20 0 2 0 29569750 356270080 54386 18446744073709551615 139698263805952 139698268113304 140736122023152 139698151483392 139698232550100 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 20.74
Current children cumulated vsize (KiB) 347920

[startup+22.7009 s]
/proc/loadavg: 1.08 1.07 1.05 2/57 25667
/proc/meminfo: memFree=658892/1022884 swapFree=0/0
[pid=25661] ppid=25660 vsize=183956 CPUtime=20.81
/proc/25661/stat : 25661 (aptitude) R 25660 25661 17863 34816 17863 4202496 62925 2701 133 3 2029 50 0 2 20 0 1 0 29569516 188370944 5263 18446744073709551615 139698263805952 139698268113304 140736122023152 140736122022712 139698221671914 0 134217728 4096 0 0 0 0 17 0 0 0 174 0 0
/proc/25661/statm: 45989 5263 1509 1052 0 30245 0
Current children cumulated CPU time (s) 20.81
Current children cumulated vsize (KiB) 183956

Child status: 0
Real time (s): 22.7467
CPU time (s): 20.8213
CPU user time (s): 20.2973
CPU system time (s): 0.524032
CPU usage (%): 91.5354
Max. virtual memory (cumulated for all children) (KiB): 347920

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 20.2973
system time used= 0.524032
maximum resident set size= 218672
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 65682
page faults= 147
swaps= 0
block input operations= 229416
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2139
involuntary context switches= 416

runsolver used 0.044002 second user time and 0.072004 second system time

The end