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/25.runsolver.aptitude aptitude -s -y --without-recommends install librmail-ruby1.8 python2.3-tz libbonobo-activation-dev fsviewer amrita 

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.25 1.13 1.05 2/55 25195
/proc/meminfo: memFree=830792/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=3152 CPUtime=0
/proc/25195/stat : 25195 (runsolver) R 25194 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29399525 3227648 32 18446744073709551615 134512640 134586868 4292113696 4292111744 4151727152 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.198307 s]
/proc/loadavg: 1.25 1.13 1.05 2/55 25195
/proc/meminfo: memFree=830792/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=103288 CPUtime=0.18
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 11302 1710 0 0 15 3 0 0 20 0 1 0 29399525 105766912 11100 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514841600 139722399434315 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 25822 11100 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.200271 s]
/proc/loadavg: 1.25 1.13 1.05 2/55 25195
/proc/meminfo: memFree=830792/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=103288 CPUtime=0.19
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 11302 1710 0 0 16 3 0 0 20 0 1 0 29399525 105766912 11100 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514841600 139722399994274 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 25822 11100 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300219 s]
/proc/loadavg: 1.25 1.13 1.05 2/55 25195
/proc/meminfo: memFree=830792/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=103432 CPUtime=0.29
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 11429 1710 0 0 26 3 0 0 20 0 1 0 29399525 105914368 11219 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514840112 139722399447010 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 25858 11219 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103432

[startup+0.700196 s]
/proc/loadavg: 1.25 1.13 1.05 2/55 25195
/proc/meminfo: memFree=830792/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=123068 CPUtime=0.68
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 17690 1710 0 0 59 9 0 0 20 0 1 0 29399525 126021632 15964 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514839768 139722399494621 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 30767 15964 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50023 s]
/proc/loadavg: 1.25 1.13 1.05 2/57 25200
/proc/meminfo: memFree=810696/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=136048 CPUtime=1.48
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 20641 1710 0 0 136 12 0 0 20 0 2 0 29399525 139313152 17558 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514841608 139722406795595 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 34012 17558 10207 1052 0 9349 0
[pid=25195/tid=25200] ppid=25194 vsize=136048 CPUtime=0
/proc/25195/task/25200/stat : 25200 (aptitude) S 25194 25195 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29399602 139313152 17558 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292271104 139722373337812 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) 136048

[startup+3.10024 s]
/proc/loadavg: 1.25 1.13 1.05 2/57 25200
/proc/meminfo: memFree=800528/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=137800 CPUtime=3.07
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 21982 2208 0 0 290 16 1 0 20 0 2 0 29399525 141107200 17922 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514837040 139722407301729 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 34450 17922 10303 1052 0 9787 0
[pid=25195/tid=25200] ppid=25194 vsize=137800 CPUtime=0.01
/proc/25195/task/25200/stat : 25200 (aptitude) S 25194 25195 17863 34816 17863 4202560 6 2208 0 0 0 0 1 0 20 0 2 0 29399602 141107200 17922 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292271104 139722373337812 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 137800

[startup+6.30024 s]
/proc/loadavg: 1.23 1.13 1.05 2/57 25201
/proc/meminfo: memFree=758988/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=250352 CPUtime=6.27
/proc/25195/stat : 25195 (aptitude) S 25194 25195 17863 34816 17863 4202496 34503 2208 0 0 606 20 1 0 20 0 2 0 29399525 256360448 29910 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514842096 139722373338699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 62588 29910 10359 1052 0 37925 0
[pid=25195/tid=25200] ppid=25194 vsize=250352 CPUtime=2.88
/proc/25195/task/25200/stat : 25200 (aptitude) R 25194 25195 17863 34816 17863 4202560 12520 2208 0 0 284 3 1 0 20 0 2 0 29399602 256360448 29910 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292262424 139722407240195 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) 250352

[startup+12.7002 s]
/proc/loadavg: 1.21 1.13 1.05 2/57 25201
/proc/meminfo: memFree=710132/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=297428 CPUtime=12.63
/proc/25195/stat : 25195 (aptitude) S 25194 25195 17863 34816 17863 4202496 46677 2208 0 0 1235 27 1 0 20 0 2 0 29399525 304566272 41678 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514842096 139722373338699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 74357 41678 10360 1052 0 49694 0
[pid=25195/tid=25200] ppid=25194 vsize=297428 CPUtime=9.25
/proc/25195/task/25200/stat : 25200 (aptitude) R 25194 25195 17863 34816 17863 4202560 24694 2208 0 0 914 10 1 0 20 0 2 0 29399602 304566272 41678 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292264032 139722362093848 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) 297428

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

[startup+12.8003 s]
/proc/loadavg: 1.21 1.13 1.05 2/57 25201
/proc/meminfo: memFree=710132/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=297956 CPUtime=12.73
/proc/25195/stat : 25195 (aptitude) S 25194 25195 17863 34816 17863 4202496 46818 2208 0 0 1245 27 1 0 20 0 2 0 29399525 305106944 41819 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514842096 139722373338699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 74489 41819 10360 1052 0 49826 0
[pid=25195/tid=25200] ppid=25194 vsize=297956 CPUtime=9.35
/proc/25195/task/25200/stat : 25200 (aptitude) R 25194 25195 17863 34816 17863 4202560 24835 2208 0 0 924 10 1 0 20 0 2 0 29399602 305106944 41819 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292264632 139722373334736 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.73
Current children cumulated vsize (KiB) 297956

[startup+19.2002 s]
/proc/loadavg: 1.19 1.12 1.05 2/57 25201
/proc/meminfo: memFree=666484/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=337608 CPUtime=19.1
/proc/25195/stat : 25195 (aptitude) S 25194 25195 17863 34816 17863 4202496 56747 2208 0 0 1877 32 1 0 20 0 2 0 29399525 345710592 51727 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514842096 139722373338699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 84402 51727 10360 1052 0 59739 0
[pid=25195/tid=25200] ppid=25194 vsize=337608 CPUtime=15.72
/proc/25195/task/25200/stat : 25200 (aptitude) R 25194 25195 17863 34816 17863 4202560 34764 2208 0 0 1556 15 1 0 20 0 2 0 29399602 345710592 51727 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292262424 139722407239962 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.1
Current children cumulated vsize (KiB) 337608

[startup+22.4002 s]
/proc/loadavg: 1.18 1.12 1.04 2/57 25201
/proc/meminfo: memFree=649992/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=353932 CPUtime=22.29
/proc/25195/stat : 25195 (aptitude) S 25194 25195 17863 34816 17863 4202496 60834 2208 0 0 2194 34 1 0 20 0 2 0 29399525 362426368 55790 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514842096 139722373338699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 88483 55790 10360 1052 0 63820 0
[pid=25195/tid=25200] ppid=25194 vsize=353932 CPUtime=18.9
/proc/25195/task/25200/stat : 25200 (aptitude) R 25194 25195 17863 34816 17863 4202560 38851 2208 0 0 1872 17 1 0 20 0 2 0 29399602 362426368 55790 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292264032 139722406795035 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.29
Current children cumulated vsize (KiB) 353932

[startup+23.2032 s]
/proc/loadavg: 1.18 1.12 1.04 2/57 25201
/proc/meminfo: memFree=645528/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=356072 CPUtime=23.08
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 61583 2208 0 0 2272 35 1 0 20 0 2 0 29399525 364617728 56484 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514840472 139722407195928 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 89018 56484 10408 1052 0 64348 0
[pid=25195/tid=25200] ppid=25194 vsize=356072 CPUtime=19.52
/proc/25195/task/25200/stat : 25200 (aptitude) S 25194 25195 17863 34816 17863 4202560 39388 2208 0 0 1933 18 1 0 20 0 2 0 29399602 364617728 56484 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292271104 139722373337812 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.08
Current children cumulated vsize (KiB) 356072

[startup+23.6002 s]
/proc/loadavg: 1.18 1.12 1.04 2/57 25201
/proc/meminfo: memFree=645528/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=356100 CPUtime=23.48
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 64135 2208 0 0 2312 35 1 0 20 0 2 0 29399525 364646400 56466 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514842536 139722405422731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 89025 56466 10409 1052 0 64355 0
[pid=25195/tid=25200] ppid=25194 vsize=356100 CPUtime=19.52
/proc/25195/task/25200/stat : 25200 (aptitude) S 25194 25195 17863 34816 17863 4202560 39388 2208 0 0 1933 18 1 0 20 0 2 0 29399602 364646400 56466 18446744073709551615 139722404593664 139722408901016 140735514850336 139722292271104 139722373337812 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.48
Current children cumulated vsize (KiB) 356100

[startup+24.0002 s]
/proc/loadavg: 1.18 1.12 1.04 2/57 25201
/proc/meminfo: memFree=645528/1022884 swapFree=0/0
[pid=25195] ppid=25194 vsize=142072 CPUtime=23.88
/proc/25195/stat : 25195 (aptitude) R 25194 25195 17863 34816 17863 4202496 64990 2707 0 0 2340 47 1 0 20 0 1 0 29399525 145481728 3253 18446744073709551615 139722404593664 139722408901016 140735514850336 140735514849896 139722362459626 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25195/statm: 35518 3253 1508 1052 0 19774 0
Current children cumulated CPU time (s) 23.88
Current children cumulated vsize (KiB) 142072

Child status: 0
Real time (s): 24.0023
CPU time (s): 23.8975
CPU user time (s): 23.4175
CPU system time (s): 0.48003
CPU usage (%): 99.5634
Max. virtual memory (cumulated for all children) (KiB): 356100

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.4175
system time used= 0.48003
maximum resident set size= 226784
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67764
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= 102
involuntary context switches= 467

runsolver used 0 second user time and 0.112007 second system time

The end