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/logs/35.runsolver.aptitude aptitude -s -y --without-recommends install gnuift-doc mmake koffice-i18n-hsb balsa alsa-modules-2.4-686 

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.03 1.04 0.91 2/55 21146
/proc/meminfo: memFree=906608/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=3152 CPUtime=0
/proc/21146/stat : 21146 (runsolver) R 21145 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28384883 3227648 32 18446744073709551615 134512640 134586868 4292893312 4292891360 4151747632 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.161832 s]
/proc/loadavg: 1.03 1.04 0.91 2/55 21146
/proc/meminfo: memFree=906608/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=89152 CPUtime=0.15
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 7773 1710 0 0 12 3 0 0 20 0 1 0 28384883 91291648 7574 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021056 140715537065425 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 22288 7574 6663 1052 0 858 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 89152

[startup+0.200355 s]
/proc/loadavg: 1.03 1.04 0.91 2/55 21146
/proc/meminfo: memFree=906608/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=89152 CPUtime=0.19
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 7775 1710 0 0 16 3 0 0 20 0 1 0 28384883 91291648 7576 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021056 140715537062236 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 22288 7576 6665 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300296 s]
/proc/loadavg: 1.03 1.04 0.91 2/55 21146
/proc/meminfo: memFree=906608/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=101864 CPUtime=0.29
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 11707 1710 0 0 25 4 0 0 20 0 1 0 28384883 104308736 10755 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465019224 140715499761149 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 25466 10755 6745 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700202 s]
/proc/loadavg: 1.03 1.04 0.91 2/55 21146
/proc/meminfo: memFree=906608/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=114228 CPUtime=0.68
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 13730 1710 0 0 63 5 0 0 20 0 2 0 28384883 116969472 12102 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021064 140715500373334 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 28557 12102 6973 1052 0 7127 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 114228

[startup+1.50024 s]
/proc/loadavg: 1.03 1.04 0.91 2/57 21151
/proc/meminfo: memFree=885644/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=115408 CPUtime=1.47
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 14580 2208 0 0 140 7 0 0 20 0 2 0 28384883 118177792 12366 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021816 140715543849291 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 28852 12366 7073 1052 0 7422 0
[pid=21146/tid=21151] ppid=21145 vsize=115408 CPUtime=0
/proc/21146/task/21151/stat : 21151 (aptitude) S 21145 21146 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 28384928 118177792 12366 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445626880 140715510964948 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 115408

[startup+3.10025 s]
/proc/loadavg: 1.03 1.04 0.91 2/57 21152
/proc/meminfo: memFree=878576/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=137188 CPUtime=3.06
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 20979 2208 0 0 296 10 0 0 20 0 2 0 28384883 140480512 18026 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 34297 18026 7129 1052 0 12867 0
[pid=21146/tid=21151] ppid=21145 vsize=137188 CPUtime=1.06
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 6318 2208 0 0 103 3 0 0 20 0 2 0 28384928 140480512 18026 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445618200 140715508530155 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 137188

[startup+6.30025 s]
/proc/loadavg: 1.02 1.03 0.91 2/57 21152
/proc/meminfo: memFree=831084/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=180508 CPUtime=6.25
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 31797 2208 0 0 609 16 0 0 20 0 2 0 28384883 184840192 28837 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 45127 28837 7129 1052 0 23697 0
[pid=21146/tid=21151] ppid=21145 vsize=180508 CPUtime=4.25
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 17136 2208 0 0 416 9 0 0 20 0 2 0 28384928 184840192 28837 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445618552 140715544868421 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 180508

[startup+12.7003 s]
/proc/loadavg: 1.02 1.03 0.91 2/57 21152
/proc/meminfo: memFree=771192/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=297224 CPUtime=12.62
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 44620 2208 0 0 1240 22 0 0 20 0 2 0 28384883 304357376 41635 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 74306 41635 7129 1052 0 52876 0
[pid=21146/tid=21151] ppid=21145 vsize=297224 CPUtime=10.61
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 29958 2208 0 0 1047 14 0 0 20 0 2 0 28384928 304357376 41635 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445620408 140715544956563 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 297224

[startup+25.5003 s]
/proc/loadavg: 1.02 1.03 0.91 2/57 21152
/proc/meminfo: memFree=702992/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=363192 CPUtime=25.36
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 61283 2208 0 0 2503 33 0 0 20 0 2 0 28384883 371908608 58107 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 90798 58107 7129 1052 0 69368 0
[pid=21146/tid=21151] ppid=21145 vsize=363192 CPUtime=23.36
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 46621 2208 0 0 2310 26 0 0 20 0 2 0 28384928 371908608 58107 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445620408 140715499731321 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 363192

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

[startup+25.6003 s]
/proc/loadavg: 1.02 1.03 0.91 2/57 21152
/proc/meminfo: memFree=702992/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=363720 CPUtime=25.46
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 61415 2208 0 0 2513 33 0 0 20 0 2 0 28384883 372449280 58239 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 90930 58239 7129 1052 0 69500 0
[pid=21146/tid=21151] ppid=21145 vsize=363720 CPUtime=23.46
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 46753 2208 0 0 2320 26 0 0 20 0 2 0 28384928 372449280 58239 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445620408 140715544996057 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 363720

[startup+38.4003 s]
/proc/loadavg: 1.01 1.03 0.91 2/57 21152
/proc/meminfo: memFree=649548/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=419440 CPUtime=38.2
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 75409 2208 0 0 3784 36 0 0 20 0 2 0 28384883 429506560 72190 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 104860 72190 7143 1052 0 83430 0
[pid=21146/tid=21151] ppid=21145 vsize=419440 CPUtime=36.2
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 60740 2208 0 0 3591 29 0 0 20 0 2 0 28384928 429506560 72190 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445618152 140715544422171 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.2
Current children cumulated vsize (KiB) 419440

[startup+44.8003 s]
/proc/loadavg: 1.01 1.03 0.91 2/57 21152
/proc/meminfo: memFree=622516/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=445856 CPUtime=44.57
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 81998 2208 0 0 4417 40 0 0 20 0 2 0 28384883 456556544 78779 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 111464 78779 7143 1052 0 90034 0
[pid=21146/tid=21151] ppid=21145 vsize=445856 CPUtime=42.57
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 67329 2208 0 0 4224 33 0 0 20 0 2 0 28384928 456556544 78779 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445620456 140715544956538 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 44.57
Current children cumulated vsize (KiB) 445856

[startup+46.4002 s]
/proc/loadavg: 1.01 1.03 0.91 2/57 21152
/proc/meminfo: memFree=613216/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=452336 CPUtime=46.16
/proc/21146/stat : 21146 (aptitude) S 21145 21146 17863 34816 17863 4202496 83639 2208 0 0 4575 41 0 0 20 0 2 0 28384883 463192064 80414 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465021552 140715510965835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 113084 80414 7143 1052 0 91654 0
[pid=21146/tid=21151] ppid=21145 vsize=452336 CPUtime=44.16
/proc/21146/task/21151/stat : 21151 (aptitude) R 21145 21146 17863 34816 17863 4202560 68970 2208 0 0 4382 34 0 0 20 0 2 0 28384928 463192064 80414 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445618152 140715544966399 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.16
Current children cumulated vsize (KiB) 452336

[startup+48.0003 s]
/proc/loadavg: 1.01 1.03 0.91 2/57 21152
/proc/meminfo: memFree=608380/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=458660 CPUtime=47.75
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 85493 2208 0 0 4733 42 0 0 20 0 2 0 28384883 469667840 82143 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465019928 140715545652227 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 114665 82143 7191 1052 0 93228 0
[pid=21146/tid=21151] ppid=21145 vsize=458660 CPUtime=45.42
/proc/21146/task/21151/stat : 21151 (aptitude) S 21145 21146 17863 34816 17863 4202560 70485 2208 0 0 4508 34 0 0 20 0 2 0 28384928 469667840 82143 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445626880 140715510964948 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.75
Current children cumulated vsize (KiB) 458660

[startup+48.4003 s]
/proc/loadavg: 1.09 1.04 0.91 2/57 21152
/proc/meminfo: memFree=605156/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=458736 CPUtime=48.15
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 85523 2208 0 0 4773 42 0 0 20 0 2 0 28384883 469745664 82173 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465019928 140715499712062 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 114684 82173 7191 1052 0 93247 0
[pid=21146/tid=21151] ppid=21145 vsize=458736 CPUtime=45.42
/proc/21146/task/21151/stat : 21151 (aptitude) S 21145 21146 17863 34816 17863 4202560 70485 2208 0 0 4508 34 0 0 20 0 2 0 28384928 469745664 82173 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445626880 140715510964948 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.15
Current children cumulated vsize (KiB) 458736

[startup+48.8003 s]
/proc/loadavg: 1.09 1.04 0.91 2/57 21152
/proc/meminfo: memFree=605156/1022884 swapFree=0/0
[pid=21146] ppid=21145 vsize=458736 CPUtime=48.55
/proc/21146/stat : 21146 (aptitude) R 21145 21146 17863 34816 17863 4202496 87598 2707 0 0 4804 50 0 1 20 0 2 0 28384883 469745664 82147 18446744073709551615 140715542220800 140715546528152 140736465029792 140736465020952 140715536916208 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21146/statm: 114684 82147 7192 1052 0 93247 0
[pid=21146/tid=21151] ppid=21145 vsize=458736 CPUtime=45.43
/proc/21146/task/21151/stat : 21151 (aptitude) S 21145 21146 17863 34816 17863 4202560 70485 2707 0 0 4508 34 0 1 20 0 2 0 28384928 469745664 82147 18446744073709551615 140715542220800 140715546528152 140736465029792 140715445626880 140715510964948 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.55
Current children cumulated vsize (KiB) 458736

Child status: 0
Real time (s): 48.8954
CPU time (s): 48.671
CPU user time (s): 48.067
CPU system time (s): 0.604037
CPU usage (%): 99.541
Max. virtual memory (cumulated for all children) (KiB): 458736

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 48.067
system time used= 0.604037
maximum resident set size= 329040
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 91030
page faults= 0
swaps= 0
block input operations= 0
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 157
involuntary context switches= 883

runsolver used 0.076004 second user time and 0.156009 second system time

The end