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/logs/160.runsolver.aptitude aptitude -s -y --without-recommends remove kmid tcptraceroute kuickshow libdb1-compat zlib1g-dev 

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.11 1.06 1.02 2/55 24696
/proc/meminfo: memFree=869692/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=3152 CPUtime=0
/proc/24696/stat : 24696 (runsolver) R 24695 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29258088 3227648 32 18446744073709551615 134512640 134586868 4293956688 4293954736 4151604272 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.153187 s]
/proc/loadavg: 1.11 1.06 1.02 2/55 24696
/proc/meminfo: memFree=869692/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=100508 CPUtime=0.13
/proc/24696/stat : 24696 (aptitude) R 24695 24696 17863 34816 17863 4202496 10594 1707 0 0 12 1 0 0 20 0 1 0 29258088 102920192 10395 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673330400 140551840437728 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 25127 10395 9220 1052 0 1122 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 100508

[startup+0.200292 s]
/proc/loadavg: 1.11 1.06 1.02 2/55 24696
/proc/meminfo: memFree=869692/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=100508 CPUtime=0.18
/proc/24696/stat : 24696 (aptitude) R 24695 24696 17863 34816 17863 4202496 10606 1707 0 0 17 1 0 0 20 0 1 0 29258088 102920192 10407 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673330400 140551841014435 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.30029 s]
/proc/loadavg: 1.11 1.06 1.02 2/55 24696
/proc/meminfo: memFree=869692/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=111108 CPUtime=0.28
/proc/24696/stat : 24696 (aptitude) R 24695 24696 17863 34816 17863 4202496 12800 1707 0 0 26 2 0 0 20 0 1 0 29258088 113774592 12593 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673330728 140551803830877 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 27777 12593 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700212 s]
/proc/loadavg: 1.11 1.06 1.02 2/55 24696
/proc/meminfo: memFree=869692/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=123288 CPUtime=0.68
/proc/24696/stat : 24696 (aptitude) R 24695 24696 17863 34816 17863 4202496 17025 1707 0 0 65 3 0 0 20 0 2 0 29258088 126246912 14299 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673332760 140551847738498 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 30822 14299 9478 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50026 s]
/proc/loadavg: 1.11 1.06 1.02 2/57 24701
/proc/meminfo: memFree=841908/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=131940 CPUtime=1.48
/proc/24696/stat : 24696 (aptitude) R 24695 24696 17863 34816 17863 4202496 19301 1707 0 0 144 4 0 0 20 0 2 0 29258088 135106560 16571 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673327304 140551803113797 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 32985 16571 9568 1052 0 8980 0
[pid=24696/tid=24701] ppid=24695 vsize=131940 CPUtime=0
/proc/24696/task/24701/stat : 24701 (aptitude) S 24695 24696 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 29258153 135106560 16571 18446744073709551615 140551845613568 140551849920920 140735673339136 140551736440832 140551814357716 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) 131940

[startup+3.10026 s]
/proc/loadavg: 1.11 1.06 1.02 2/57 24701
/proc/meminfo: memFree=841040/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=219824 CPUtime=3.08
/proc/24696/stat : 24696 (aptitude) S 24695 24696 17863 34816 17863 4202496 24964 1707 0 0 302 6 0 0 20 0 2 0 29258088 225099776 22233 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673330896 140551814358603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 54956 22233 9660 1052 0 30951 0
[pid=24696/tid=24701] ppid=24695 vsize=219824 CPUtime=0.56
/proc/24696/task/24701/stat : 24701 (aptitude) R 24695 24696 17863 34816 17863 4202560 5524 1707 0 0 54 2 0 0 20 0 2 0 29258153 225099776 22233 18446744073709551615 140551845613568 140551849920920 140735673339136 140551736434264 140551803123848 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) 219824

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

[startup+3.20033 s]
/proc/loadavg: 1.11 1.06 1.02 2/57 24701
/proc/meminfo: memFree=841040/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=220880 CPUtime=3.18
/proc/24696/stat : 24696 (aptitude) S 24695 24696 17863 34816 17863 4202496 25250 1707 0 0 312 6 0 0 20 0 2 0 29258088 226181120 22519 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673330896 140551814358603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 55220 22519 9660 1052 0 31215 0
[pid=24696/tid=24701] ppid=24695 vsize=220880 CPUtime=0.66
/proc/24696/task/24701/stat : 24701 (aptitude) R 24695 24696 17863 34816 17863 4202560 5810 1707 0 0 64 2 0 0 20 0 2 0 29258153 226181120 22519 18446744073709551615 140551845613568 140551849920920 140735673339136 140551736431720 140551848210629 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.18
Current children cumulated vsize (KiB) 220880

[startup+4.80024 s]
/proc/loadavg: 1.10 1.06 1.02 2/57 24701
/proc/meminfo: memFree=808924/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=232760 CPUtime=4.76
/proc/24696/stat : 24696 (aptitude) S 24695 24696 17863 34816 17863 4202496 28218 1707 0 0 469 7 0 0 20 0 2 0 29258088 238346240 25487 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673330896 140551814358603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 58190 25487 9662 1052 0 34185 0
[pid=24696/tid=24701] ppid=24695 vsize=232760 CPUtime=2.24
/proc/24696/task/24701/stat : 24701 (aptitude) R 24695 24696 17863 34816 17863 4202560 8778 1707 0 0 221 3 0 0 20 0 2 0 29258153 238346240 25487 18446744073709551615 140551845613568 140551849920920 140735673339136 140551736432152 140551811546704 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.76
Current children cumulated vsize (KiB) 232760

[startup+5.20026 s]
/proc/loadavg: 1.10 1.06 1.02 2/57 24701
/proc/meminfo: memFree=808924/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=235560 CPUtime=5.16
/proc/24696/stat : 24696 (aptitude) R 24695 24696 17863 34816 17863 4202496 28970 1707 0 0 509 7 0 0 20 0 2 0 29258088 241213440 26237 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673331440 140551803104939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24696/statm: 58890 26237 9710 1052 0 34878 0
[pid=24696/tid=24701] ppid=24695 vsize=235560 CPUtime=2.58
/proc/24696/task/24701/stat : 24701 (aptitude) S 24695 24696 17863 34816 17863 4202560 9467 1707 0 0 254 4 0 0 20 0 2 0 29258153 241213440 26237 18446744073709551615 140551845613568 140551849920920 140735673339136 140551736440832 140551814357716 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 5.16
Current children cumulated vsize (KiB) 235560

[startup+5.60324 s]
/proc/loadavg: 1.10 1.06 1.02 2/57 24701
/proc/meminfo: memFree=802848/1022884 swapFree=0/0
[pid=24696] ppid=24695 vsize=141384 CPUtime=5.53
/proc/24696/stat : 24696 (aptitude) R 24695 24696 17863 34816 17863 4202496 29348 2205 0 1 541 12 0 0 20 0 1 0 29258088 144777216 2813 18446744073709551615 140551845613568 140551849920920 140735673339136 140735673338208 140551803459437 0 134217728 4096 0 0 0 0 17 0 0 0 1 0 0
/proc/24696/statm: 35346 2813 1519 1052 0 19602 0
Current children cumulated CPU time (s) 5.53
Current children cumulated vsize (KiB) 141384

Child status: 0
Real time (s): 5.60487
CPU time (s): 5.54835
CPU user time (s): 5.42034
CPU system time (s): 0.128008
CPU usage (%): 98.9914
Max. virtual memory (cumulated for all children) (KiB): 235560

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.42034
system time used= 0.128008
maximum resident set size= 105564
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 31576
page faults= 1
swaps= 0
block input operations= 168
block output operations= 8
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 68
involuntary context switches= 147

runsolver used 0.004 second user time and 0.028001 second system time

The end