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


[startup+0 s]
/proc/loadavg: 1.01 1.05 1.02 2/55 25293
/proc/meminfo: memFree=832420/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=54860 CPUtime=0
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 609 0 0 0 0 0 0 0 20 0 1 0 29461514 56176640 509 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241698376 140634283124674 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 13715 509 417 1052 0 73 0

[startup+0.13023 s]
/proc/loadavg: 1.01 1.05 1.02 2/55 25293
/proc/meminfo: memFree=832420/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=103288 CPUtime=0.11
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 11234 1708 0 0 9 2 0 0 20 0 1 0 29461514 105766912 11035 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690432 140634280155725 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 25822 11035 9824 1052 0 1159 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 103288

[startup+0.200276 s]
/proc/loadavg: 1.01 1.05 1.02 2/55 25293
/proc/meminfo: memFree=832420/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=103288 CPUtime=0.18
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 11299 1708 0 0 16 2 0 0 20 0 1 0 29461514 105766912 11100 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690432 140634280713789 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 25822 11100 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300258 s]
/proc/loadavg: 1.01 1.05 1.02 2/55 25293
/proc/meminfo: memFree=832420/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=103432 CPUtime=0.28
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 11426 1708 0 0 26 2 0 0 20 0 1 0 29461514 105914368 11219 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241688944 140634280167394 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 25858 11219 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700199 s]
/proc/loadavg: 1.01 1.05 1.02 2/55 25293
/proc/meminfo: memFree=832420/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=123068 CPUtime=0.68
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 17688 1708 0 0 63 5 0 0 20 0 1 0 29461514 126021632 15964 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241688600 140634242854439 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25293/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.01 1.05 1.02 2/57 25298
/proc/meminfo: memFree=812448/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=136044 CPUtime=1.48
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 20639 1708 0 0 140 8 0 0 20 0 2 0 29461514 139309056 17558 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690440 140634287515979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 34011 17558 10207 1052 0 9348 0
[pid=25293/tid=25298] ppid=25292 vsize=136044 CPUtime=0
/proc/25293/task/25298/stat : 25298 (aptitude) S 25292 25293 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29461592 139309056 17558 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172991488 140634254058196 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) 136044

[startup+3.10024 s]
/proc/loadavg: 1.01 1.05 1.02 2/57 25298
/proc/meminfo: memFree=802156/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=137804 CPUtime=3.08
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 21989 2206 0 0 295 12 1 0 20 0 2 0 29461514 141111296 17934 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241685872 140634254049568 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 34451 17934 10303 1052 0 9788 0
[pid=25293/tid=25298] ppid=25292 vsize=137804 CPUtime=0.01
/proc/25293/task/25298/stat : 25298 (aptitude) S 25292 25293 17863 34816 17863 4202560 6 2206 0 0 0 0 1 0 20 0 2 0 29461592 141111296 17934 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172991488 140634254058196 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 137804

[startup+6.30024 s]
/proc/loadavg: 1.01 1.05 1.02 2/57 25299
/proc/meminfo: memFree=759996/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=251520 CPUtime=6.26
/proc/25293/stat : 25293 (aptitude) S 25292 25293 17863 34816 17863 4202496 34838 2206 0 0 606 19 1 0 20 0 2 0 29461514 257556480 30223 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690928 140634254059083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 62880 30223 10359 1052 0 38217 0
[pid=25293/tid=25298] ppid=25292 vsize=251520 CPUtime=2.86
/proc/25293/task/25298/stat : 25298 (aptitude) R 25292 25293 17863 34816 17863 4202560 12848 2206 0 0 278 7 1 0 20 0 2 0 29461592 257556480 30223 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172985064 140634287960346 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 251520

[startup+12.7002 s]
/proc/loadavg: 1.01 1.05 1.02 2/57 25299
/proc/meminfo: memFree=711760/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=296780 CPUtime=12.63
/proc/25293/stat : 25293 (aptitude) S 25292 25293 17863 34816 17863 4202496 46323 2206 0 0 1238 24 1 0 20 0 2 0 29461514 303902720 41499 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690928 140634254059083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 74195 41499 10360 1052 0 49532 0
[pid=25293/tid=25298] ppid=25292 vsize=296780 CPUtime=9.23
/proc/25293/task/25298/stat : 25298 (aptitude) R 25292 25293 17863 34816 17863 4202560 24333 2206 0 0 910 12 1 0 20 0 2 0 29461592 303902720 41499 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172982856 140634287960558 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) 296780

[startup+25.5003 s]
/proc/loadavg: 1.00 1.04 1.02 2/57 25299
/proc/meminfo: memFree=633020/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=371516 CPUtime=25.37
/proc/25293/stat : 25293 (aptitude) S 25292 25293 17863 34816 17863 4202496 65254 2206 0 0 2502 34 1 0 20 0 2 0 29461514 380432384 60208 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690928 140634254059083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 92879 60208 10360 1052 0 68216 0
[pid=25293/tid=25298] ppid=25292 vsize=371516 CPUtime=21.97
/proc/25293/task/25298/stat : 25298 (aptitude) R 25292 25293 17863 34816 17863 4202560 43264 2206 0 0 2174 22 1 0 20 0 2 0 29461592 380432384 60208 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172982808 140634243466451 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 371516

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

[startup+25.6003 s]
/proc/loadavg: 1.00 1.04 1.02 2/57 25299
/proc/meminfo: memFree=633020/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=371780 CPUtime=25.47
/proc/25293/stat : 25293 (aptitude) S 25292 25293 17863 34816 17863 4202496 65331 2206 0 0 2512 34 1 0 20 0 2 0 29461514 380702720 60285 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690928 140634254059083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 92945 60285 10360 1052 0 68282 0
[pid=25293/tid=25298] ppid=25292 vsize=371780 CPUtime=22.07
/proc/25293/task/25298/stat : 25298 (aptitude) R 25292 25293 17863 34816 17863 4202560 43341 2206 0 0 2184 22 1 0 20 0 2 0 29461592 380702720 60285 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172982808 140634288184536 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 371780

[startup+27.2002 s]
/proc/loadavg: 1.00 1.04 1.02 2/57 25299
/proc/meminfo: memFree=626200/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=382828 CPUtime=27.06
/proc/25293/stat : 25293 (aptitude) S 25292 25293 17863 34816 17863 4202496 68090 2206 0 0 2669 36 1 0 20 0 2 0 29461514 392015872 63021 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241690928 140634254059083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 95707 63021 10361 1052 0 71044 0
[pid=25293/tid=25298] ppid=25292 vsize=382828 CPUtime=23.66
/proc/25293/task/25298/stat : 25298 (aptitude) R 25292 25293 17863 34816 17863 4202560 46100 2206 0 0 2341 24 1 0 20 0 2 0 29461592 392015872 63021 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172982808 140634288029153 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 27.06
Current children cumulated vsize (KiB) 382828

[startup+28.0002 s]
/proc/loadavg: 1.00 1.04 1.02 2/57 25299
/proc/meminfo: memFree=620248/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=384220 CPUtime=27.85
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 68685 2206 0 0 2748 36 1 0 20 0 2 0 29461514 393441280 63559 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241689304 140634242805360 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 96055 63559 10409 1052 0 71385 0
[pid=25293/tid=25298] ppid=25292 vsize=384220 CPUtime=24.03
/proc/25293/task/25298/stat : 25298 (aptitude) S 25292 25293 17863 34816 17863 4202560 46461 2206 0 0 2378 24 1 0 20 0 2 0 29461592 393441280 63559 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172991488 140634254058196 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 27.85
Current children cumulated vsize (KiB) 384220

[startup+28.4002 s]
/proc/loadavg: 1.00 1.04 1.02 2/57 25299
/proc/meminfo: memFree=620248/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=384220 CPUtime=28.26
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 71347 2206 0 0 2786 39 1 0 20 0 2 0 29461514 393441280 63601 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241688928 140634243017014 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 96055 63601 10410 1052 0 71385 0
[pid=25293/tid=25298] ppid=25292 vsize=384220 CPUtime=24.03
/proc/25293/task/25298/stat : 25298 (aptitude) S 25292 25293 17863 34816 17863 4202560 46461 2206 0 0 2378 24 1 0 20 0 2 0 29461592 393441280 63601 18446744073709551615 140634285314048 140634289621400 140737241699168 140634172991488 140634254058196 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 28.26
Current children cumulated vsize (KiB) 384220

[startup+28.6003 s]
/proc/loadavg: 1.00 1.04 1.02 2/56 25300
/proc/meminfo: memFree=675924/1022884 swapFree=0/0
[pid=25293] ppid=25292 vsize=330044 CPUtime=28.45
/proc/25293/stat : 25293 (aptitude) R 25292 25293 17863 34816 17863 4202496 72053 2704 0 0 2794 50 1 0 20 0 1 0 29461514 337965056 45096 18446744073709551615 140634285314048 140634289621400 140737241699168 140737241696216 140634243180010 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25293/statm: 82511 45096 10413 1052 0 57841 0
Current children cumulated CPU time (s) 28.45
Current children cumulated vsize (KiB) 330044

Child status: 0
Real time (s): 28.6523
CPU time (s): 28.5218
CPU user time (s): 27.9657
CPU system time (s): 0.556034
CPU usage (%): 99.5446
Max. virtual memory (cumulated for all children) (KiB): 384220

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 27.9657
system time used= 0.556034
maximum resident set size= 255012
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 74869
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= 111
involuntary context switches= 546

runsolver used 0.080005 second user time and 0.060003 second system time

The end