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/150.runsolver.aptitude aptitude -s -y --without-recommends remove grep portmap libncurses5-dev kopete kiconedit 

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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.03 1.04 1.06 2/55 26931
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=33024 CPUtime=0
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 180 0 0 0 0 0 0 0 20 0 1 0 29933747 33816576 90 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917524968 140186769289687 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 8256 90 57 1052 0 38 0

[startup+0.163525 s]
/proc/loadavg: 1.03 1.04 1.06 2/55 26931
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=103288 CPUtime=0.15
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 11285 1707 0 0 13 2 0 0 20 0 1 0 29933747 105766912 11087 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917519168 140186766836540 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 25822 11087 9875 1052 0 1159 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 103288

[startup+0.200285 s]
/proc/loadavg: 1.03 1.04 1.06 2/55 26931
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=103288 CPUtime=0.19
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 11298 1707 0 0 17 2 0 0 20 0 1 0 29933747 105766912 11100 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917519168 140186766277102 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 25822 11100 9888 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300271 s]
/proc/loadavg: 1.03 1.04 1.06 2/55 26931
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=103288 CPUtime=0.29
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 11307 1707 0 0 27 2 0 0 20 0 1 0 29933747 105766912 11109 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917519168 140186766835957 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 25822 11109 9897 1052 0 1159 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103288

[startup+0.700201 s]
/proc/loadavg: 1.03 1.04 1.06 2/55 26931
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=123068 CPUtime=0.68
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 17687 1707 0 0 64 4 0 0 20 0 1 0 29933747 126021632 15965 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917517336 140186774360855 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.03 1.04 1.06 2/57 26936
/proc/meminfo: memFree=801972/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=135856 CPUtime=1.48
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 20626 1707 0 0 143 5 0 0 20 0 2 0 29933747 139116544 17544 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917516232 140186728945760 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 33964 17544 10227 1052 0 9301 0
[pid=26931/tid=26936] ppid=26930 vsize=135856 CPUtime=0
/proc/26931/task/26936/stat : 26936 (aptitude) S 26930 26931 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 29933824 139116544 17544 18446744073709551615 140186771435520 140186775742872 140736917527904 140186659112960 140186740179668 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) 135856

[startup+3.10025 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26936
/proc/meminfo: memFree=800980/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=143248 CPUtime=3.07
/proc/26931/stat : 26931 (aptitude) S 26930 26931 17863 34816 17863 4202496 22583 1707 0 0 302 5 0 0 20 0 2 0 29933747 146685952 19500 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917519664 140186740180555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 35812 19500 10320 1052 0 11149 0
[pid=26931/tid=26936] ppid=26930 vsize=143248 CPUtime=0.27
/proc/26931/task/26936/stat : 26936 (aptitude) R 26930 26931 17863 34816 17863 4202560 1799 1707 0 0 27 0 0 0 20 0 2 0 29933824 146685952 19500 18446744073709551615 140186771435520 140186775742872 140736917527904 140186659104552 140186773063857 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) 143248

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

[startup+3.20031 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26936
/proc/meminfo: memFree=800980/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=143644 CPUtime=3.17
/proc/26931/stat : 26931 (aptitude) S 26930 26931 17863 34816 17863 4202496 22683 1707 0 0 312 5 0 0 20 0 2 0 29933747 147091456 19600 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917519664 140186740180555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 35911 19600 10320 1052 0 11248 0
[pid=26931/tid=26936] ppid=26930 vsize=143644 CPUtime=0.37
/proc/26931/task/26936/stat : 26936 (aptitude) R 26930 26931 17863 34816 17863 4202560 1899 1707 0 0 37 0 0 0 20 0 2 0 29933824 147091456 19600 18446744073709551615 140186771435520 140186775742872 140736917527904 140186659107208 140186766836476 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.17
Current children cumulated vsize (KiB) 143644

[startup+4.00025 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26936
/proc/meminfo: memFree=793540/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=144304 CPUtime=3.97
/proc/26931/stat : 26931 (aptitude) S 26930 26931 17863 34816 17863 4202496 22836 1707 0 0 392 5 0 0 20 0 2 0 29933747 147767296 19753 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917519664 140186740180555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 36076 19753 10321 1052 0 11413 0
[pid=26931/tid=26936] ppid=26930 vsize=144304 CPUtime=1.16
/proc/26931/task/26936/stat : 26936 (aptitude) R 26930 26931 17863 34816 17863 4202560 2051 1707 0 0 116 0 0 0 20 0 2 0 29933824 147767296 19753 18446744073709551615 140186771435520 140186775742872 140736917527904 140186659102728 140186773646429 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.97
Current children cumulated vsize (KiB) 144304

[startup+4.80024 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26936
/proc/meminfo: memFree=789696/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=155420 CPUtime=4.76
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 25676 1707 0 0 470 6 0 0 20 0 2 0 29933747 159150080 22591 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917520208 140186774054463 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 38855 22591 10369 1052 0 14185 0
[pid=26931/tid=26936] ppid=26930 vsize=155420 CPUtime=1.93
/proc/26931/task/26936/stat : 26936 (aptitude) S 26930 26931 17863 34816 17863 4202560 4842 1707 0 0 193 0 0 0 20 0 2 0 29933824 159150080 22591 18446744073709551615 140186771435520 140186775742872 140736917527904 140186659112960 140186740179668 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) 155420

[startup+5.00025 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26936
/proc/meminfo: memFree=789696/1022884 swapFree=0/0
[pid=26931] ppid=26930 vsize=155420 CPUtime=4.96
/proc/26931/stat : 26931 (aptitude) R 26930 26931 17863 34816 17863 4202496 25677 1707 0 0 490 6 0 0 20 0 2 0 29933747 159150080 22592 18446744073709551615 140186771435520 140186775742872 140736917527904 140736917519976 140186766328057 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26931/statm: 38855 22592 10370 1052 0 14185 0
[pid=26931/tid=26936] ppid=26930 vsize=155420 CPUtime=1.93
/proc/26931/task/26936/stat : 26936 (aptitude) S 26930 26931 17863 34816 17863 4202560 4842 1707 0 0 193 0 0 0 20 0 2 0 29933824 159150080 22592 18446744073709551615 140186771435520 140186775742872 140736917527904 140186659112960 140186740179668 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.96
Current children cumulated vsize (KiB) 155420

Child status: 255
Real time (s): 5.02781
CPU time (s): 5.00831
CPU user time (s): 4.91631
CPU system time (s): 0.092005
CPU usage (%): 99.6121
Max. virtual memory (cumulated for all children) (KiB): 155420

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.91631
system time used= 0.092005
maximum resident set size= 90436
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 27465
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 57
involuntary context switches= 133

runsolver used 0.008 second user time and 0.020001 second system time

The end