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/94.runsolver.aptitude aptitude -s -y --without-recommends install blas-dev xgsmlib librmail-ruby-doc koffice-dev xconq-doc 

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.09 1.10 1.05 2/55 24213
/proc/meminfo: memFree=949464/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=3152 CPUtime=0
/proc/24213/stat : 24213 (runsolver) R 24212 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29165143 3227648 32 18446744073709551615 134512640 134586868 4287199712 4287197760 4151972912 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24213/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.128131 s]
/proc/loadavg: 1.09 1.10 1.05 2/55 24213
/proc/meminfo: memFree=949464/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=10112 CPUtime=0
/proc/24213/stat : 24213 (aptitude) D 24212 24213 17863 34816 17863 4202496 124 0 3 0 0 0 0 0 20 0 1 0 29165143 10354688 45 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108940872 140288209569235 0 0 0 0 0 0 0 17 0 0 0 11 0 0
/proc/24213/statm: 2528 45 34 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 10112

[startup+0.200423 s]
/proc/loadavg: 1.09 1.10 1.05 2/55 24213
/proc/meminfo: memFree=949464/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=30864 CPUtime=0
/proc/24213/stat : 24213 (aptitude) D 24212 24213 17863 34816 17863 4202496 159 0 11 0 0 0 0 0 20 0 1 0 29165143 31604736 81 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108940536 140288209568534 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/24213/statm: 7716 81 52 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 30864

[startup+0.300402 s]
/proc/loadavg: 1.09 1.10 1.05 2/55 24213
/proc/meminfo: memFree=949464/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=46508 CPUtime=0
/proc/24213/stat : 24213 (aptitude) D 24212 24213 17863 34816 17863 4202496 184 0 17 0 0 0 0 0 20 0 1 0 29165143 47624192 108 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108939784 140288209568534 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/24213/statm: 11627 108 67 1052 0 66 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 46508

[startup+0.700338 s]
/proc/loadavg: 1.09 1.10 1.05 2/55 24213
/proc/meminfo: memFree=949464/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=100508 CPUtime=0.03
/proc/24213/stat : 24213 (aptitude) D 24212 24213 17863 34816 17863 4202496 5777 1705 32 2 1 1 1 0 20 0 1 0 29165143 102920192 5610 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108935392 140288206557464 0 134217728 4096 0 0 0 0 17 0 0 0 61 0 0
/proc/24213/statm: 25127 5610 4436 1052 0 1122 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 100508

[startup+1.50021 s]
/proc/loadavg: 1.09 1.10 1.05 2/56 24217
/proc/meminfo: memFree=932336/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=119772 CPUtime=0.53
/proc/24213/stat : 24213 (aptitude) R 24212 24213 17863 34816 17863 4202496 16464 1705 37 2 46 6 1 0 20 0 1 0 29165143 122646528 14779 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108933352 140288180466032 0 134217728 4096 0 0 0 0 17 0 0 0 92 0 0
/proc/24213/statm: 29943 14779 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.53
Current children cumulated vsize (KiB) 119772

[startup+3.10027 s]
/proc/loadavg: 1.08 1.10 1.04 2/57 24218
/proc/meminfo: memFree=849124/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=132552 CPUtime=1.77
/proc/24213/stat : 24213 (aptitude) R 24212 24213 17863 34816 17863 4202496 19433 1705 37 2 165 11 1 0 20 0 2 0 29165143 135733248 16741 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108930792 140288214707216 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 127 0 0
/proc/24213/statm: 33138 16741 9585 1052 0 9133 0
[pid=24213/tid=24218] ppid=24212 vsize=132552 CPUtime=0.01
/proc/24213/task/24218/stat : 24218 (aptitude) S 24212 24213 17863 34816 17863 4202560 4 1705 0 2 0 0 1 0 20 0 2 0 29165342 135733248 16741 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102537216 140288180454100 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.77
Current children cumulated vsize (KiB) 132552
heavy processes:

[startup+6.30026 s]
/proc/loadavg: 1.08 1.10 1.04 2/57 24219
/proc/meminfo: memFree=820604/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=223924 CPUtime=4.92
/proc/24213/stat : 24213 (aptitude) S 24212 24213 17863 34816 17863 4202496 27018 2202 37 3 474 17 1 0 20 0 2 0 29165143 229298176 23306 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108935680 140288180454987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 129 0 0
/proc/24213/statm: 55981 23306 9699 1052 0 31976 0
[pid=24213/tid=24218] ppid=24212 vsize=223924 CPUtime=1.79
/proc/24213/task/24218/stat : 24218 (aptitude) R 24212 24213 17863 34816 17863 4202560 6432 2202 0 3 176 2 1 0 20 0 2 0 29165342 229298176 23306 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102528584 140288214294782 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.92
Current children cumulated vsize (KiB) 223924
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.07 1.10 1.04 2/57 24219
/proc/meminfo: memFree=752652/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=288908 CPUtime=11.28
/proc/24213/stat : 24213 (aptitude) S 24212 24213 17863 34816 17863 4202496 43917 2202 37 3 1101 26 1 0 20 0 2 0 29165143 295841792 39523 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108935680 140288180454987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 129 0 0
/proc/24213/statm: 72227 39523 9700 1052 0 48222 0
[pid=24213/tid=24218] ppid=24212 vsize=288908 CPUtime=8.15
/proc/24213/task/24218/stat : 24218 (aptitude) R 24212 24213 17863 34816 17863 4202560 23331 2202 0 3 804 10 1 0 20 0 2 0 29165342 295841792 39523 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102528536 140288212539056 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.28
Current children cumulated vsize (KiB) 288908

[startup+25.5003 s]
/proc/loadavg: 1.06 1.10 1.04 2/57 24219
/proc/meminfo: memFree=673416/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=365264 CPUtime=24.02
/proc/24213/stat : 24213 (aptitude) S 24212 24213 17863 34816 17863 4202496 63143 2202 37 3 2361 40 1 0 20 0 2 0 29165143 374030336 58600 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108935680 140288180454987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 129 0 0
/proc/24213/statm: 91316 58600 9700 1052 0 67311 0
[pid=24213/tid=24218] ppid=24212 vsize=365264 CPUtime=20.89
/proc/24213/task/24218/stat : 24218 (aptitude) R 24212 24213 17863 34816 17863 4202560 42557 2202 0 3 2064 24 1 0 20 0 2 0 29165342 374030336 58600 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102528536 140288213338289 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 24.02
Current children cumulated vsize (KiB) 365264

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

[startup+25.6003 s]
/proc/loadavg: 1.06 1.10 1.04 2/57 24219
/proc/meminfo: memFree=673416/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=365528 CPUtime=24.12
/proc/24213/stat : 24213 (aptitude) S 24212 24213 17863 34816 17863 4202496 63228 2202 37 3 2371 40 1 0 20 0 2 0 29165143 374300672 58685 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108935680 140288180454987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 129 0 0
/proc/24213/statm: 91382 58685 9700 1052 0 67377 0
[pid=24213/tid=24218] ppid=24212 vsize=365528 CPUtime=20.99
/proc/24213/task/24218/stat : 24218 (aptitude) R 24212 24213 17863 34816 17863 4202560 42642 2202 0 3 2074 24 1 0 20 0 2 0 29165342 374300672 58685 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102528888 140288214452538 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 24.12
Current children cumulated vsize (KiB) 365528

[startup+28.8003 s]
/proc/loadavg: 1.05 1.09 1.04 2/57 24219
/proc/meminfo: memFree=643780/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=394480 CPUtime=27.3
/proc/24213/stat : 24213 (aptitude) S 24212 24213 17863 34816 17863 4202496 70450 2202 37 3 2685 44 1 0 20 0 2 0 29165143 403947520 65903 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108935680 140288180454987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 129 0 0
/proc/24213/statm: 98620 65903 9700 1052 0 74615 0
[pid=24213/tid=24218] ppid=24212 vsize=394480 CPUtime=24.18
/proc/24213/task/24218/stat : 24218 (aptitude) R 24212 24213 17863 34816 17863 4202560 49864 2202 0 3 2388 29 1 0 20 0 2 0 29165342 403947520 65903 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102528536 140288214356344 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 27.3
Current children cumulated vsize (KiB) 394480

[startup+30.4003 s]
/proc/loadavg: 1.05 1.09 1.04 2/57 24219
/proc/meminfo: memFree=636216/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=404052 CPUtime=28.8
/proc/24213/stat : 24213 (aptitude) R 24212 24213 17863 34816 17863 4202496 73055 2202 50 3 2833 46 1 0 20 0 2 0 29165143 413749248 68460 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108934056 140288169220192 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 137 0 0
/proc/24213/statm: 101013 68460 9748 1052 0 77001 0
[pid=24213/tid=24218] ppid=24212 vsize=404052 CPUtime=25.64
/proc/24213/task/24218/stat : 24218 (aptitude) S 24212 24213 17863 34816 17863 4202560 52259 2202 1 3 2532 31 1 0 20 0 2 0 29165342 413749248 68460 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102537216 140288180454100 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 28.8
Current children cumulated vsize (KiB) 404052

[startup+31.2003 s]
/proc/loadavg: 1.05 1.09 1.04 2/57 24219
/proc/meminfo: memFree=631504/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=404112 CPUtime=29.6
/proc/24213/stat : 24213 (aptitude) R 24212 24213 17863 34816 17863 4202496 75632 2202 50 3 2913 46 1 0 20 0 2 0 29165143 413810688 68537 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108935736 140288206607672 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 137 0 0
/proc/24213/statm: 101028 68537 9749 1052 0 77016 0
[pid=24213/tid=24218] ppid=24212 vsize=404112 CPUtime=25.64
/proc/24213/task/24218/stat : 24218 (aptitude) S 24212 24213 17863 34816 17863 4202560 52259 2202 1 3 2532 31 1 0 20 0 2 0 29165342 413810688 68537 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102537216 140288180454100 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 29.6
Current children cumulated vsize (KiB) 404112

[startup+31.4002 s]
/proc/loadavg: 1.05 1.09 1.04 2/57 24219
/proc/meminfo: memFree=631504/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=404112 CPUtime=29.8
/proc/24213/stat : 24213 (aptitude) R 24212 24213 17863 34816 17863 4202496 75944 2702 50 3 2923 55 1 1 20 0 2 0 29165143 413810688 68443 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108936184 140288213443450 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 137 0 0
/proc/24213/statm: 101028 68443 9749 1052 0 77016 0
[pid=24213/tid=24218] ppid=24212 vsize=404112 CPUtime=25.65
/proc/24213/task/24218/stat : 24218 (aptitude) S 24212 24213 17863 34816 17863 4202560 52259 2702 1 3 2532 31 1 1 20 0 2 0 29165342 413810688 68443 18446744073709551615 140288211709952 140288216017304 140734108943920 140288102537216 140288180454100 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 29.8
Current children cumulated vsize (KiB) 404112

[startup+31.5003 s]
/proc/loadavg: 1.05 1.09 1.04 2/57 24219
/proc/meminfo: memFree=631504/1022884 swapFree=0/0
[pid=24213] ppid=24212 vsize=321588 CPUtime=29.87
/proc/24213/stat : 24213 (aptitude) D 24212 24213 17863 34816 17863 4202496 76395 2702 55 3 2927 58 1 1 20 0 1 0 29165143 329306112 47854 18446744073709551615 140288211709952 140288216017304 140734108943920 140734108941232 140288212435312 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/24213/statm: 80397 47854 1506 1052 0 64653 0
Current children cumulated CPU time (s) 29.87
Current children cumulated vsize (KiB) 321588

Child status: 0
Real time (s): 31.5944
CPU time (s): 29.9379
CPU user time (s): 29.2938
CPU system time (s): 0.64404
CPU usage (%): 94.757
Max. virtual memory (cumulated for all children) (KiB): 404112

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 29.2938
system time used= 0.64404
maximum resident set size= 274772
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 79156
page faults= 70
swaps= 0
block input operations= 166480
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1610
involuntary context switches= 571

runsolver used 0.020001 second user time and 0.140008 second system time

The end