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/logs/79.runsolver.aptitude aptitude -s -y --without-recommends install avrp elib libzip-ocaml liblip1 imaze-sounds 

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.12 1.08 1.01 2/55 23846
/proc/meminfo: memFree=962796/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=3152 CPUtime=0
/proc/23846/stat : 23846 (runsolver) R 23845 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29066803 3227648 32 18446744073709551615 134512640 134586868 4291946176 4291944224 4151858224 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23846/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.143093 s]
/proc/loadavg: 1.12 1.08 1.01 2/55 23846
/proc/meminfo: memFree=962796/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=12328 CPUtime=0
/proc/23846/stat : 23846 (aptitude) D 23845 23846 17863 34816 17863 4202496 130 0 5 0 0 0 0 0 20 0 1 0 29066803 12623872 51 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720611960 139790440302115 0 0 0 0 0 0 0 17 0 0 0 13 0 0
/proc/23846/statm: 3082 51 36 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.200383 s]
/proc/loadavg: 1.12 1.08 1.01 2/55 23846
/proc/meminfo: memFree=962796/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=25980 CPUtime=0
/proc/23846/stat : 23846 (aptitude) D 23845 23846 17863 34816 17863 4202496 151 0 10 0 0 0 0 0 20 0 1 0 29066803 26603520 73 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720611720 139790440301334 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23846/statm: 6495 73 48 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 25980

[startup+0.30038 s]
/proc/loadavg: 1.12 1.08 1.01 2/55 23846
/proc/meminfo: memFree=962796/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=48572 CPUtime=0
/proc/23846/stat : 23846 (aptitude) D 23845 23846 17863 34816 17863 4202496 188 0 19 0 0 0 0 0 20 0 1 0 29066803 49737728 112 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720610872 139790440301278 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/23846/statm: 12143 112 68 1052 0 66 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 48572

[startup+0.700296 s]
/proc/loadavg: 1.12 1.08 1.01 2/55 23846
/proc/meminfo: memFree=962796/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=100508 CPUtime=0.01
/proc/23846/stat : 23846 (aptitude) D 23845 23846 17863 34816 17863 4202496 2421 1706 44 4 0 1 0 0 20 0 1 0 29066803 102920192 2265 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720606528 139790437492634 0 134217728 4096 0 0 0 0 17 0 0 0 65 0 0
/proc/23846/statm: 25127 2265 1090 1052 0 1122 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 100508

[startup+1.50033 s]
/proc/loadavg: 1.12 1.08 1.01 1/56 23850
/proc/meminfo: memFree=954348/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=100508 CPUtime=0.03
/proc/23846/stat : 23846 (aptitude) D 23845 23846 17863 34816 17863 4202496 5455 1706 187 4 1 2 0 0 20 0 1 0 29066803 102920192 5442 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720606528 139790437492634 0 134217728 4096 0 0 0 0 17 0 0 0 143 0 0
/proc/23846/statm: 25127 5442 4267 1052 0 1122 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 100508

[startup+3.1002 s]
/proc/loadavg: 1.12 1.08 1.01 2/56 23850
/proc/meminfo: memFree=941824/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=119772 CPUtime=0.66
/proc/23846/stat : 23846 (aptitude) R 23845 23846 17863 34816 17863 4202496 16269 1706 242 4 54 12 0 0 20 0 1 0 29066803 122646528 14787 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720604488 139790399983135 0 134217728 4096 0 0 0 0 17 0 0 0 240 0 0
/proc/23846/statm: 29943 14787 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.66
Current children cumulated vsize (KiB) 119772
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.11 1.07 1.01 2/57 23852
/proc/meminfo: memFree=841004/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=146704 CPUtime=3.7
/proc/23846/stat : 23846 (aptitude) S 23845 23846 17863 34816 17863 4202496 23924 2202 242 6 350 20 0 0 20 0 2 0 29066803 150224896 20409 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720606816 139790411187787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 36676 20409 9698 1052 0 12671 0
[pid=23846/tid=23851] ppid=23845 vsize=146704 CPUtime=0.55
/proc/23846/task/23851/stat : 23851 (aptitude) R 23845 23846 17863 34816 17863 4202560 3549 2202 0 6 53 2 0 0 20 0 2 0 29067125 150224896 20409 18446744073709551615 139790442442752 139790446750104 140734720615056 139790333261688 139790399943031 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.7
Current children cumulated vsize (KiB) 146704
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.10 1.07 1.01 2/57 23852
/proc/meminfo: memFree=773300/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=271876 CPUtime=10.07
/proc/23846/stat : 23846 (aptitude) S 23845 23846 17863 34816 17863 4202496 39781 2202 242 6 981 26 0 0 20 0 2 0 29066803 278401024 35289 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720606816 139790411187787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 67969 35289 9700 1052 0 43964 0
[pid=23846/tid=23851] ppid=23845 vsize=271876 CPUtime=6.92
/proc/23846/task/23851/stat : 23851 (aptitude) R 23845 23846 17863 34816 17863 4202560 19405 2202 0 6 684 8 0 0 20 0 2 0 29067125 278401024 35289 18446744073709551615 139790442442752 139790446750104 140734720615056 139790333261336 139790445150438 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.07
Current children cumulated vsize (KiB) 271876
heavy processes:

[startup+25.5002 s]
/proc/loadavg: 1.08 1.07 1.01 2/57 23852
/proc/meminfo: memFree=666536/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=374556 CPUtime=22.8
/proc/23846/stat : 23846 (aptitude) S 23845 23846 17863 34816 17863 4202496 65444 2202 242 6 2244 36 0 0 20 0 2 0 29066803 383545344 60921 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720606816 139790411187787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 93639 60921 9701 1052 0 69634 0
[pid=23846/tid=23851] ppid=23845 vsize=374556 CPUtime=19.65
/proc/23846/task/23851/stat : 23851 (aptitude) R 23845 23846 17863 34816 17863 4202560 45068 2202 0 6 1947 18 0 0 20 0 2 0 29067125 383545344 60921 18446744073709551615 139790442442752 139790446750104 140734720615056 139790333263720 139790445178499 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.8
Current children cumulated vsize (KiB) 374556

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

[startup+25.6003 s]
/proc/loadavg: 1.08 1.07 1.01 2/57 23852
/proc/meminfo: memFree=666536/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=375220 CPUtime=22.9
/proc/23846/stat : 23846 (aptitude) S 23845 23846 17863 34816 17863 4202496 65605 2202 242 6 2254 36 0 0 20 0 2 0 29066803 384225280 61082 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720606816 139790411187787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 93805 61082 9701 1052 0 69800 0
[pid=23846/tid=23851] ppid=23845 vsize=375220 CPUtime=19.75
/proc/23846/task/23851/stat : 23851 (aptitude) R 23845 23846 17863 34816 17863 4202560 45229 2202 0 6 1957 18 0 0 20 0 2 0 29067125 384225280 61082 18446744073709551615 139790442442752 139790446750104 140734720615056 139790333264488 139790445269597 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.9
Current children cumulated vsize (KiB) 375220

[startup+27.2002 s]
/proc/loadavg: 1.08 1.07 1.01 2/57 23852
/proc/meminfo: memFree=659840/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=385092 CPUtime=24.5
/proc/23846/stat : 23846 (aptitude) S 23845 23846 17863 34816 17863 4202496 68079 2202 242 6 2412 38 0 0 20 0 2 0 29066803 394334208 63556 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720606816 139790411187787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 96273 63556 9701 1052 0 72268 0
[pid=23846/tid=23851] ppid=23845 vsize=385092 CPUtime=21.35
/proc/23846/task/23851/stat : 23851 (aptitude) R 23845 23846 17863 34816 17863 4202560 47703 2202 0 6 2115 20 0 0 20 0 2 0 29067125 394334208 63556 18446744073709551615 139790442442752 139790446750104 140734720615056 139790333264600 139790408748012 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 24.5
Current children cumulated vsize (KiB) 385092

[startup+28.0002 s]
/proc/loadavg: 1.08 1.07 1.01 2/57 23852
/proc/meminfo: memFree=652772/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=389432 CPUtime=25.29
/proc/23846/stat : 23846 (aptitude) R 23845 23846 17863 34816 17863 4202496 69386 2202 242 6 2491 38 0 0 20 0 2 0 29066803 398778368 64807 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720605192 139790445045016 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 97358 64807 9750 1052 0 73346 0
[pid=23846/tid=23851] ppid=23845 vsize=389432 CPUtime=22.08
/proc/23846/task/23851/stat : 23851 (aptitude) S 23845 23846 17863 34816 17863 4202560 48796 2202 0 6 2188 20 0 0 20 0 2 0 29067125 398778368 64807 18446744073709551615 139790442442752 139790446750104 140734720615056 139790333270016 139790411186900 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.29
Current children cumulated vsize (KiB) 389432

[startup+28.8002 s]
/proc/loadavg: 1.08 1.07 1.01 2/57 23852
/proc/meminfo: memFree=649548/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=389472 CPUtime=26.1
/proc/23846/stat : 23846 (aptitude) R 23845 23846 17863 34816 17863 4202496 71970 2701 242 6 2564 44 1 1 20 0 2 0 29066803 398819328 64894 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720605144 139790400286789 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 97368 64894 9751 1052 0 73356 0
[pid=23846/tid=23851] ppid=23845 vsize=389472 CPUtime=22.1
/proc/23846/task/23851/stat : 23851 (aptitude) S 23845 23846 17863 34816 17863 4202560 48796 2701 0 6 2188 20 1 1 20 0 2 0 29067125 398819328 64894 18446744073709551615 139790442442752 139790446750104 140734720615056 139790333270016 139790411186900 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 26.1
Current children cumulated vsize (KiB) 389472

[startup+29.0003 s]
/proc/loadavg: 1.08 1.07 1.01 2/57 23852
/proc/meminfo: memFree=649548/1022884 swapFree=0/0
[pid=23846] ppid=23845 vsize=180716 CPUtime=26.3
/proc/23846/stat : 23846 (aptitude) R 23845 23846 17863 34816 17863 4202496 72667 2701 242 6 2572 56 1 1 20 0 1 0 29066803 185053184 10596 18446744073709551615 139790442442752 139790446750104 140734720615056 140734720614616 139790400308714 0 134217728 4096 0 0 0 0 17 0 0 0 252 0 0
/proc/23846/statm: 45179 10596 1509 1052 0 29435 0
Current children cumulated CPU time (s) 26.3
Current children cumulated vsize (KiB) 180716

Child status: 0
Real time (s): 29.0105
CPU time (s): 26.3256
CPU user time (s): 25.7456
CPU system time (s): 0.580036
CPU usage (%): 90.7453
Max. virtual memory (cumulated for all children) (KiB): 389472

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 25.7456
system time used= 0.580036
maximum resident set size= 260056
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 75435
page faults= 248
swaps= 0
block input operations= 183928
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2017
involuntary context switches= 504

runsolver used 0.144009 second user time and 0 second system time

The end