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/98.runsolver.aptitude aptitude -s -y --without-recommends install xabacus wmanx rwall amiga-fdisk-cross libganglia1-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.10 1.09 1.08 2/55 26558
/proc/meminfo: memFree=948308/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=3152 CPUtime=0
/proc/26558/stat : 26558 (runsolver) R 26557 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29884968 3227648 33 18446744073709551615 134512640 134586868 4290326944 4290324992 4151747632 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26558/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.106146 s]
/proc/loadavg: 1.10 1.09 1.08 2/55 26558
/proc/meminfo: memFree=948308/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=28716 CPUtime=0
/proc/26558/stat : 26558 (aptitude) D 26557 26558 17863 34816 17863 4202496 156 0 10 0 0 0 0 0 20 0 1 0 29884968 29405184 78 18446744073709551615 139844384182272 139844388489624 140735279005952 140735279002568 139844382041635 0 0 0 0 0 0 0 17 0 0 0 9 0 0
/proc/26558/statm: 7179 78 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.200271 s]
/proc/loadavg: 1.10 1.09 1.08 2/55 26558
/proc/meminfo: memFree=948308/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=54860 CPUtime=0
/proc/26558/stat : 26558 (aptitude) R 26557 26558 17863 34816 17863 4202496 412 0 22 0 0 0 0 0 20 0 1 0 29884968 56176640 334 18446744073709551615 139844384182272 139844388489624 140735279005952 140735279005160 139844381991408 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/26558/statm: 13715 334 258 1052 0 73 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54860

[startup+0.300356 s]
/proc/loadavg: 1.10 1.09 1.08 2/55 26558
/proc/meminfo: memFree=948308/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=63384 CPUtime=0.01
/proc/26558/stat : 26558 (aptitude) S 26557 26558 17863 34816 17863 4202496 1215 0 28 0 0 1 0 0 20 0 1 0 29884968 64905216 1109 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278997000 139844342028016 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/26558/statm: 15846 1109 929 1052 0 109 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 63384

[startup+0.700229 s]
/proc/loadavg: 1.10 1.09 1.08 2/55 26558
/proc/meminfo: memFree=948308/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=103288 CPUtime=0.02
/proc/26558/stat : 26558 (aptitude) D 26557 26558 17863 34816 17863 4202496 4229 1707 92 2 0 2 0 0 20 0 1 0 29884968 105766912 4122 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278997424 139844379232154 0 134217728 4096 0 0 0 0 17 0 0 0 65 0 0
/proc/26558/statm: 25822 4122 2910 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.10 1.09 1.08 2/56 26562
/proc/meminfo: memFree=941108/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=123068 CPUtime=0.48
/proc/26558/stat : 26558 (aptitude) D 26557 26558 17863 34816 17863 4202496 17508 1707 156 2 44 4 0 0 20 0 1 0 29884968 126021632 15941 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278995384 139844352938352 0 134217728 4096 0 0 0 0 17 0 0 0 98 0 0
/proc/26558/statm: 30767 15941 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.48
Current children cumulated vsize (KiB) 123068

[startup+3.10023 s]
/proc/loadavg: 1.10 1.09 1.08 2/56 26562
/proc/meminfo: memFree=843396/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=136040 CPUtime=1.38
/proc/26558/stat : 26558 (aptitude) R 26557 26558 17863 34816 17863 4202496 20482 1707 156 2 125 13 0 0 20 0 2 0 29884968 139304960 17557 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278997224 139844386384255 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 168 0 0
/proc/26558/statm: 34010 17557 10207 1052 0 9347 0
Current children cumulated CPU time (s) 1.38
Current children cumulated vsize (KiB) 136040
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.10 1.09 1.08 2/57 26564
/proc/meminfo: memFree=796020/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=160892 CPUtime=4.56
/proc/26558/stat : 26558 (aptitude) S 26557 26558 17863 34816 17863 4202496 28070 2204 156 3 435 20 1 0 20 0 2 0 29884968 164753408 23945 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278997712 139844352927307 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 168 0 0
/proc/26558/statm: 40223 23945 10359 1052 0 15560 0
[pid=26558/tid=26563] ppid=26557 vsize=160892 CPUtime=1.12
/proc/26558/task/26563/stat : 26563 (aptitude) R 26557 26558 17863 34816 17863 4202560 6256 2204 0 3 108 3 1 0 20 0 2 0 29885220 164753408 23945 18446744073709551615 139844384182272 139844388489624 140735279005952 139844271853240 139844386956317 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.56
Current children cumulated vsize (KiB) 160892
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.09 1.09 1.08 2/57 26564
/proc/meminfo: memFree=727200/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=284360 CPUtime=10.92
/proc/26558/stat : 26558 (aptitude) S 26557 26558 17863 34816 17863 4202496 43010 2204 156 3 1066 25 1 0 20 0 2 0 29884968 291184640 38427 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278997712 139844352927307 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 168 0 0
/proc/26558/statm: 71090 38427 10359 1052 0 46427 0
[pid=26558/tid=26563] ppid=26557 vsize=284360 CPUtime=7.47
/proc/26558/task/26563/stat : 26563 (aptitude) R 26557 26558 17863 34816 17863 4202560 21195 2204 0 3 738 8 1 0 20 0 2 0 29885220 291184640 38427 18446744073709551615 139844384182272 139844388489624 140735279005952 139844271853288 139844379006073 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.92
Current children cumulated vsize (KiB) 284360

[startup+25.5003 s]
/proc/loadavg: 1.07 1.08 1.08 2/57 26564
/proc/meminfo: memFree=650196/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=355832 CPUtime=23.57
/proc/26558/stat : 26558 (aptitude) R 26557 26558 17863 34816 17863 4202496 63990 2204 169 3 2324 32 1 0 20 0 2 0 29884968 364371968 56488 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278997656 139844379079992 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 177 0 0
/proc/26558/statm: 88958 56488 10409 1052 0 64288 0
[pid=26558/tid=26563] ppid=26557 vsize=355832 CPUtime=19.46
/proc/26558/task/26563/stat : 26563 (aptitude) S 26557 26558 17863 34816 17863 4202560 39326 2204 1 3 1931 14 1 0 20 0 2 0 29885220 364371968 56488 18446744073709551615 139844384182272 139844388489624 140735279005952 139844271859712 139844352926420 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 23.57
Current children cumulated vsize (KiB) 355832

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

[startup+25.6003 s]
/proc/loadavg: 1.07 1.08 1.08 2/57 26564
/proc/meminfo: memFree=650196/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=355832 CPUtime=23.66
/proc/26558/stat : 26558 (aptitude) R 26557 26558 17863 34816 17863 4202496 63998 2204 169 3 2331 34 1 0 20 0 2 0 29884968 364371968 56488 18446744073709551615 139844384182272 139844388489624 140735279005952 140735278995712 139844341885238 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 177 0 0
/proc/26558/statm: 88958 56488 10409 1052 0 64288 0
[pid=26558/tid=26563] ppid=26557 vsize=355832 CPUtime=19.46
/proc/26558/task/26563/stat : 26563 (aptitude) S 26557 26558 17863 34816 17863 4202560 39326 2204 1 3 1931 14 1 0 20 0 2 0 29885220 364371968 56488 18446744073709551615 139844384182272 139844388489624 140735279005952 139844271859712 139844352926420 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 23.66
Current children cumulated vsize (KiB) 355832

[startup+25.8002 s]
/proc/loadavg: 1.07 1.08 1.08 2/57 26564
/proc/meminfo: memFree=650196/1022884 swapFree=0/0
[pid=26558] ppid=26557 vsize=256636 CPUtime=23.86
/proc/26558/stat : 26558 (aptitude) D 26557 26558 17863 34816 17863 4202496 64658 2703 170 3 2341 43 1 1 20 0 2 0 29884968 262795264 31871 18446744073709551615 139844384182272 139844388489624 140735279005952 140735279002216 139844366481536 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 177 0 0
/proc/26558/statm: 64159 31871 10411 1052 0 39489 0
[pid=26558/tid=26563] ppid=26557 vsize=256636 CPUtime=19.47
/proc/26558/task/26563/stat : 26563 (aptitude) S 26557 26558 17863 34816 17863 4202560 39326 2703 1 3 1931 14 1 1 20 0 2 0 29885220 262795264 31871 18446744073709551615 139844384182272 139844388489624 140735279005952 139844271859712 139844352926420 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 23.86
Current children cumulated vsize (KiB) 256636

Child status: 0
Real time (s): 25.8813
CPU time (s): 23.9135
CPU user time (s): 23.4295
CPU system time (s): 0.48403
CPU usage (%): 92.3968
Max. virtual memory (cumulated for all children) (KiB): 355832

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.4295
system time used= 0.48403
maximum resident set size= 226528
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67491
page faults= 189
swaps= 0
block input operations= 229032
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2218
involuntary context switches= 463

runsolver used 0.128008 second user time and 0 second system time

The end