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/55.runsolver.aptitude aptitude -s -y --without-recommends install python2.3-egenix-mxqueue libqscintilla-doc positron apache2 intuitively 

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.07 1.05 2/55 25705
/proc/meminfo: memFree=842372/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=3152 CPUtime=0
/proc/25705/stat : 25705 (runsolver) R 25704 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29598599 3227648 32 18446744073709551615 134512640 134586868 4288423264 4288421312 4151608368 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25705/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.160821 s]
/proc/loadavg: 1.03 1.07 1.05 2/55 25705
/proc/meminfo: memFree=842372/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=61308 CPUtime=0.01
/proc/25705/stat : 25705 (aptitude) D 25704 25705 17863 34816 17863 4202496 1154 0 14 0 0 1 0 0 20 0 1 0 29598599 62779392 1050 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694313416 140368981190179 0 134217728 4096 0 0 0 0 17 0 0 0 14 0 0
/proc/25705/statm: 15327 1050 875 1052 0 108 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 61308

[startup+0.200254 s]
/proc/loadavg: 1.03 1.07 1.05 2/55 25705
/proc/meminfo: memFree=842372/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=99200 CPUtime=0.01
/proc/25705/stat : 25705 (aptitude) S 25704 25705 17863 34816 17863 4202496 1292 572 16 2 0 1 0 0 20 0 1 0 29598599 101580800 1146 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312584 140368941176560 0 134217728 4096 0 0 0 0 17 0 0 0 15 0 0
/proc/25705/statm: 24800 1146 963 1052 0 137 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 99200

[startup+0.300234 s]
/proc/loadavg: 1.03 1.07 1.05 2/55 25705
/proc/meminfo: memFree=842372/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=103288 CPUtime=0.1
/proc/25705/stat : 25705 (aptitude) R 25704 25705 17863 34816 17863 4202496 11151 1707 16 2 8 2 0 0 20 0 1 0 29598599 105766912 10968 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694311888 140368978171617 0 134217728 4096 0 0 0 0 17 0 0 0 15 0 0
/proc/25705/statm: 25822 10968 9756 1052 0 1159 0
Current children cumulated CPU time (s) 0.1
Current children cumulated vsize (KiB) 103288

[startup+0.700291 s]
/proc/loadavg: 1.03 1.07 1.05 2/55 25705
/proc/meminfo: memFree=842372/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=123068 CPUtime=0.46
/proc/25705/stat : 25705 (aptitude) D 25704 25705 17863 34816 17863 4202496 17648 1707 16 2 42 4 0 0 20 0 1 0 29598599 126021632 15941 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694310056 140368952086896 0 134217728 4096 0 0 0 0 17 0 0 0 19 0 0
/proc/25705/statm: 30767 15941 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.46
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.03 1.07 1.05 2/57 25710
/proc/meminfo: memFree=811348/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=129716 CPUtime=1.21
/proc/25705/stat : 25705 (aptitude) R 25704 25705 17863 34816 17863 4202496 18987 1707 16 2 112 9 0 0 20 0 2 0 29598599 132829184 15922 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312664 140368986038863 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 32429 15922 10191 1052 0 7766 0
[pid=25705/tid=25710] ppid=25704 vsize=129716 CPUtime=0
/proc/25705/task/25710/stat : 25710 (aptitude) S 25704 25705 17863 34816 17863 4202560 4 1707 0 2 0 0 0 0 20 0 2 0 29598704 132829184 15922 18446744073709551615 140368983330816 140368987638168 140736694320624 140368871008256 140368952074964 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.21
Current children cumulated vsize (KiB) 129716

[startup+3.10025 s]
/proc/loadavg: 1.03 1.07 1.05 2/57 25710
/proc/meminfo: memFree=801056/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=137808 CPUtime=2.8
/proc/25705/stat : 25705 (aptitude) R 25704 25705 17863 34816 17863 4202496 21965 2206 16 2 266 14 0 0 20 0 2 0 29598599 141115392 17929 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694307328 140368985532187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 34452 17929 10303 1052 0 9789 0
[pid=25705/tid=25710] ppid=25704 vsize=137808 CPUtime=0
/proc/25705/task/25710/stat : 25710 (aptitude) S 25704 25705 17863 34816 17863 4202560 6 2206 0 2 0 0 0 0 20 0 2 0 29598704 141115392 17929 18446744073709551615 140368983330816 140368987638168 140736694320624 140368871008256 140368952074964 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 137808

[startup+6.30023 s]
/proc/loadavg: 1.03 1.07 1.05 2/57 25711
/proc/meminfo: memFree=761996/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=249296 CPUtime=5.98
/proc/25705/stat : 25705 (aptitude) S 25704 25705 17863 34816 17863 4202496 34255 2206 16 2 580 18 0 0 20 0 2 0 29598599 255279104 29662 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312384 140368952075851 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 62324 29662 10359 1052 0 37661 0
[pid=25705/tid=25710] ppid=25704 vsize=249296 CPUtime=2.6
/proc/25705/task/25710/stat : 25710 (aptitude) R 25704 25705 17863 34816 17863 4202560 12285 2206 0 2 256 4 0 0 20 0 2 0 29598704 255279104 29662 18446744073709551615 140368983330816 140368987638168 140736694320624 140368871001832 140368985977263 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 5.98
Current children cumulated vsize (KiB) 249296

[startup+12.7002 s]
/proc/loadavg: 1.02 1.07 1.04 2/57 25711
/proc/meminfo: memFree=712148/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=294164 CPUtime=12.35
/proc/25705/stat : 25705 (aptitude) S 25704 25705 17863 34816 17863 4202496 45642 2206 16 2 1207 28 0 0 20 0 2 0 29598599 301223936 40869 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312384 140368952075851 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 73541 40869 10360 1052 0 48878 0
[pid=25705/tid=25710] ppid=25704 vsize=294164 CPUtime=8.97
/proc/25705/task/25710/stat : 25710 (aptitude) R 25704 25705 17863 34816 17863 4202560 23672 2206 0 2 883 14 0 0 20 0 2 0 29598704 301223936 40869 18446744073709551615 140368983330816 140368987638168 140736694320624 140368871001184 140368983976242 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.35
Current children cumulated vsize (KiB) 294164

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

[startup+12.8003 s]
/proc/loadavg: 1.02 1.07 1.04 2/57 25711
/proc/meminfo: memFree=712148/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=295352 CPUtime=12.44
/proc/25705/stat : 25705 (aptitude) S 25704 25705 17863 34816 17863 4202496 46111 2206 16 2 1216 28 0 0 20 0 2 0 29598599 302440448 41139 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312384 140368952075851 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 73838 41139 10360 1052 0 49175 0
[pid=25705/tid=25710] ppid=25704 vsize=295352 CPUtime=9.07
/proc/25705/task/25710/stat : 25710 (aptitude) R 25704 25705 17863 34816 17863 4202560 24141 2206 0 2 893 14 0 0 20 0 2 0 29598704 302440448 41139 18446744073709551615 140368983330816 140368987638168 140736694320624 140368870999576 140368940831102 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 295352

[startup+19.2003 s]
/proc/loadavg: 1.02 1.06 1.04 2/57 25714
/proc/meminfo: memFree=667616/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=336524 CPUtime=18.81
/proc/25705/stat : 25705 (aptitude) S 25704 25705 17863 34816 17863 4202496 56455 2206 16 2 1846 35 0 0 20 0 2 0 29598599 344600576 51461 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312384 140368952075851 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 84131 51461 10360 1052 0 59468 0
[pid=25705/tid=25710] ppid=25704 vsize=336524 CPUtime=15.43
/proc/25705/task/25710/stat : 25710 (aptitude) R 25704 25705 17863 34816 17863 4202560 34485 2206 0 2 1522 21 0 0 20 0 2 0 29598704 344600576 51461 18446744073709551615 140368983330816 140368987638168 140736694320624 140368870999576 140368984159924 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.81
Current children cumulated vsize (KiB) 336524

[startup+22.4002 s]
/proc/loadavg: 1.02 1.06 1.04 2/57 25714
/proc/meminfo: memFree=650504/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=352980 CPUtime=22
/proc/25705/stat : 25705 (aptitude) S 25704 25705 17863 34816 17863 4202496 60591 2206 16 2 2162 38 0 0 20 0 2 0 29598599 361451520 55574 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312384 140368952075851 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 88245 55574 10360 1052 0 63582 0
[pid=25705/tid=25710] ppid=25704 vsize=352980 CPUtime=18.62
/proc/25705/task/25710/stat : 25710 (aptitude) R 25704 25705 17863 34816 17863 4202560 38621 2206 0 2 1838 24 0 0 20 0 2 0 29598704 361451520 55574 18446744073709551615 140368983330816 140368987638168 140736694320624 140368870999576 140368940841337 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22
Current children cumulated vsize (KiB) 352980

[startup+23.2032 s]
/proc/loadavg: 1.02 1.06 1.04 2/57 25714
/proc/meminfo: memFree=646288/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=355752 CPUtime=22.79
/proc/25705/stat : 25705 (aptitude) S 25704 25705 17863 34816 17863 4202496 61285 2206 16 2 2241 38 0 0 20 0 2 0 29598599 364290048 56268 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694312384 140368952075851 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 88938 56268 10360 1052 0 64275 0
[pid=25705/tid=25710] ppid=25704 vsize=355752 CPUtime=19.41
/proc/25705/task/25710/stat : 25710 (aptitude) R 25704 25705 17863 34816 17863 4202560 39315 2206 0 2 1917 24 0 0 20 0 2 0 29598704 364290048 56268 18446744073709551615 140368983330816 140368987638168 140736694320624 140368870999576 140368986007065 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.79
Current children cumulated vsize (KiB) 355752

[startup+24.0003 s]
/proc/loadavg: 1.02 1.06 1.04 2/57 25714
/proc/meminfo: memFree=646288/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=356080 CPUtime=23.59
/proc/25705/stat : 25705 (aptitude) R 25704 25705 17863 34816 17863 4202496 64212 2206 16 2 2316 43 0 0 20 0 2 0 29598599 364625920 56552 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694310384 140368941033782 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 89020 56552 10409 1052 0 64350 0
[pid=25705/tid=25710] ppid=25704 vsize=356080 CPUtime=19.44
/proc/25705/task/25710/stat : 25710 (aptitude) S 25704 25705 17863 34816 17863 4202560 39373 2206 0 2 1920 24 0 0 20 0 2 0 29598704 364625920 56552 18446744073709551615 140368983330816 140368987638168 140736694320624 140368871008256 140368952074964 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.59
Current children cumulated vsize (KiB) 356080

[startup+24.2004 s]
/proc/loadavg: 1.02 1.06 1.04 2/56 25715
/proc/meminfo: memFree=765948/1022884 swapFree=0/0
[pid=25705] ppid=25704 vsize=198736 CPUtime=23.79
/proc/25705/stat : 25705 (aptitude) R 25704 25705 17863 34816 17863 4202496 64927 2705 16 2 2326 52 0 1 20 0 1 0 29598599 203505664 17419 18446744073709551615 140368983330816 140368987638168 140736694320624 140736694317736 140368941211927 0 134217728 4096 0 0 0 0 17 0 0 0 24 0 0
/proc/25705/statm: 49684 17419 1503 1052 0 33940 0
Current children cumulated CPU time (s) 23.79
Current children cumulated vsize (KiB) 198736

Child status: 0
Real time (s): 24.222
CPU time (s): 23.8335
CPU user time (s): 23.2775
CPU system time (s): 0.556034
CPU usage (%): 98.3962
Max. virtual memory (cumulated for all children) (KiB): 356080

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.2775
system time used= 0.556034
maximum resident set size= 226804
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67738
page faults= 18
swaps= 0
block input operations= 21536
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 289
involuntary context switches= 520

runsolver used 0.040002 second user time and 0.080005 second system time

The end