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/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.22 1.15 1.09 2/55 26514
/proc/meminfo: memFree=905012/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=3152 CPUtime=0
/proc/26514/stat : 26514 (runsolver) R 26513 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29847961 3227648 33 18446744073709551615 134512640 134586868 4293162304 4293160352 4151841840 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26514/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.14633 s]
/proc/loadavg: 1.22 1.15 1.09 2/55 26514
/proc/meminfo: memFree=905012/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=10112 CPUtime=0
/proc/26514/stat : 26514 (aptitude) D 26513 26514 17863 34816 17863 4202496 125 0 4 0 0 0 0 0 20 0 1 0 29847961 10354688 46 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742638408 140374245008851 0 0 0 0 0 0 0 17 0 0 0 13 0 0
/proc/26514/statm: 2528 46 34 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 10112

[startup+0.200276 s]
/proc/loadavg: 1.22 1.15 1.09 2/55 26514
/proc/meminfo: memFree=905012/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=23840 CPUtime=0
/proc/26514/stat : 26514 (aptitude) D 26513 26514 17863 34816 17863 4202496 143 0 15 0 0 0 0 0 20 0 1 0 29847961 24412160 70 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742638520 140374244949940 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/26514/statm: 5960 70 45 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300353 s]
/proc/loadavg: 1.22 1.15 1.09 2/55 26514
/proc/meminfo: memFree=905012/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=38696 CPUtime=0
/proc/26514/stat : 26514 (aptitude) D 26513 26514 17863 34816 17863 4202496 168 0 21 0 0 0 0 0 20 0 1 0 29847961 39624704 97 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742637784 140374245008118 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/26514/statm: 9674 97 61 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 38696

[startup+0.70031 s]
/proc/loadavg: 1.22 1.15 1.09 2/55 26514
/proc/meminfo: memFree=905012/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=63380 CPUtime=0.01
/proc/26514/stat : 26514 (aptitude) D 26513 26514 17863 34816 17863 4202496 1143 0 59 0 1 0 0 0 20 0 1 0 29847961 64901120 1077 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742637576 140374204994711 0 134217728 4096 0 0 0 0 17 0 0 0 67 0 0
/proc/26514/statm: 15845 1077 898 1052 0 108 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 63380

[startup+1.50037 s]
/proc/loadavg: 1.22 1.15 1.09 1/56 26518
/proc/meminfo: memFree=893588/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=103288 CPUtime=0.02
/proc/26514/stat : 26514 (aptitude) D 26513 26514 17863 34816 17863 4202496 3354 1705 147 4 2 0 0 0 20 0 1 0 29847961 105766912 3302 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742632928 140374242199450 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/26514/statm: 25822 3302 2090 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+3.10021 s]
/proc/loadavg: 1.22 1.15 1.09 1/56 26518
/proc/meminfo: memFree=891108/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=123068 CPUtime=0.56
/proc/26514/stat : 26514 (aptitude) D 26513 26514 17863 34816 17863 4202496 17392 1705 287 4 49 7 0 0 20 0 1 0 29847961 126021632 15956 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742630888 140374215905648 0 134217728 4096 0 0 0 0 17 0 0 0 246 0 0
/proc/26514/statm: 30767 15956 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.56
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30025 s]
/proc/loadavg: 1.20 1.15 1.09 1/57 26519
/proc/meminfo: memFree=742920/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=137836 CPUtime=3.06
/proc/26514/stat : 26514 (aptitude) R 26513 26514 17863 34816 17863 4202496 21719 2206 301 5 284 22 0 0 20 0 2 0 29847961 141144064 17955 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742628160 140374250204461 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 34459 17955 10303 1052 0 9796 0
[pid=26514/tid=26519] ppid=26513 vsize=137836 CPUtime=0
/proc/26514/task/26519/stat : 26519 (aptitude) S 26513 26514 17863 34816 17863 4202560 6 2206 0 5 0 0 0 0 20 0 2 0 29848354 141144064 17955 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134827008 140374215893716 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 137836
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.19 1.15 1.09 2/57 26520
/proc/meminfo: memFree=681168/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=269224 CPUtime=9.44
/proc/26514/stat : 26514 (aptitude) S 26513 26514 17863 34816 17863 4202496 38690 2206 301 5 913 31 0 0 20 0 2 0 29847961 275685376 34650 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633216 140374215894603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 67306 34650 10359 1052 0 42643 0
[pid=26514/tid=26519] ppid=26513 vsize=269224 CPUtime=5.94
/proc/26514/task/26519/stat : 26519 (aptitude) R 26513 26514 17863 34816 17863 4202560 16970 2206 0 5 586 8 0 0 20 0 2 0 29848354 275685376 34650 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134817736 140374204649878 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.44
Current children cumulated vsize (KiB) 269224
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.14 1.14 1.09 2/57 26520
/proc/meminfo: memFree=580728/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=364744 CPUtime=22.17
/proc/26514/stat : 26514 (aptitude) S 26513 26514 17863 34816 17863 4202496 62857 2206 301 5 2176 41 0 0 20 0 2 0 29847961 373497856 58489 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633216 140374215894603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 91186 58489 10359 1052 0 66523 0
[pid=26514/tid=26519] ppid=26513 vsize=364744 CPUtime=18.68
/proc/26514/task/26519/stat : 26519 (aptitude) R 26513 26514 17863 34816 17863 4202560 41137 2206 0 5 1849 19 0 0 20 0 2 0 29848354 373497856 58489 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134818328 140374247738992 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.17
Current children cumulated vsize (KiB) 364744

[startup+51.1003 s]
/proc/loadavg: 1.09 1.13 1.09 2/57 26520
/proc/meminfo: memFree=426720/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=519680 CPUtime=47.65
/proc/26514/stat : 26514 (aptitude) S 26513 26514 17863 34816 17863 4202496 101902 2206 301 5 4702 63 0 0 20 0 2 0 29847961 532152320 97171 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633216 140374215894603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 129920 97171 10374 1052 0 105257 0
[pid=26514/tid=26519] ppid=26513 vsize=519680 CPUtime=44.15
/proc/26514/task/26519/stat : 26519 (aptitude) R 26513 26514 17863 34816 17863 4202560 80176 2206 0 5 4375 40 0 0 20 0 2 0 29848354 532152320 97171 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134818280 140374247916501 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 47.65
Current children cumulated vsize (KiB) 519680

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

[startup+51.2003 s]
/proc/loadavg: 1.09 1.13 1.09 2/57 26520
/proc/meminfo: memFree=426720/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=520340 CPUtime=47.74
/proc/26514/stat : 26514 (aptitude) S 26513 26514 17863 34816 17863 4202496 102068 2206 301 5 4711 63 0 0 20 0 2 0 29847961 532828160 97337 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633216 140374215894603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 130085 97337 10374 1052 0 105422 0
[pid=26514/tid=26519] ppid=26513 vsize=520340 CPUtime=44.26
/proc/26514/task/26519/stat : 26519 (aptitude) R 26513 26514 17863 34816 17863 4202560 80342 2206 0 5 4385 41 0 0 20 0 2 0 29848354 532828160 97337 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134818376 140374204649781 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 47.74
Current children cumulated vsize (KiB) 520340

[startup+57.6002 s]
/proc/loadavg: 1.09 1.13 1.09 2/57 26520
/proc/meminfo: memFree=393116/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=553484 CPUtime=54.12
/proc/26514/stat : 26514 (aptitude) S 26513 26514 17863 34816 17863 4202496 110382 2206 301 5 5343 69 0 0 20 0 2 0 29847961 566767616 105622 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633216 140374215894603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 138371 105622 10374 1052 0 113708 0
[pid=26514/tid=26519] ppid=26513 vsize=553484 CPUtime=50.62
/proc/26514/task/26519/stat : 26519 (aptitude) R 26513 26514 17863 34816 17863 4202560 88656 2206 0 5 5016 46 0 0 20 0 2 0 29848354 566767616 105622 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134821256 140374204660039 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 54.12
Current children cumulated vsize (KiB) 553484

[startup+64.0002 s]
/proc/loadavg: 1.08 1.12 1.09 2/57 26520
/proc/meminfo: memFree=359140/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=585900 CPUtime=60.49
/proc/26514/stat : 26514 (aptitude) S 26513 26514 17863 34816 17863 4202496 118508 2206 301 5 5974 75 0 0 20 0 2 0 29847961 599961600 113748 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633216 140374215894603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 146475 113748 10374 1052 0 121812 0
[pid=26514/tid=26519] ppid=26513 vsize=585900 CPUtime=56.99
/proc/26514/task/26519/stat : 26519 (aptitude) R 26513 26514 17863 34816 17863 4202560 96782 2206 0 5 5647 52 0 0 20 0 2 0 29848354 599961600 113748 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134818328 140374249976448 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 60.49
Current children cumulated vsize (KiB) 585900

[startup+65.6002 s]
/proc/loadavg: 1.07 1.12 1.09 2/57 26520
/proc/meminfo: memFree=353932/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=593196 CPUtime=62.08
/proc/26514/stat : 26514 (aptitude) S 26513 26514 17863 34816 17863 4202496 120330 2206 301 5 6131 77 0 0 20 0 2 0 29847961 607432704 115570 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633216 140374215894603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/26514/statm: 148299 115570 10374 1052 0 123636 0
[pid=26514/tid=26519] ppid=26513 vsize=593196 CPUtime=58.58
/proc/26514/task/26519/stat : 26519 (aptitude) R 26513 26514 17863 34816 17863 4202560 98604 2206 0 5 5804 54 0 0 20 0 2 0 29848354 607432704 115570 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134818328 140374204731085 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 62.08
Current children cumulated vsize (KiB) 593196

[startup+67.2033 s]
/proc/loadavg: 1.07 1.12 1.09 2/57 26520
/proc/meminfo: memFree=347112/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=595816 CPUtime=63.58
/proc/26514/stat : 26514 (aptitude) R 26513 26514 17863 34816 17863 4202496 121187 2206 308 5 6280 78 0 0 20 0 2 0 29847961 610115584 116374 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742631592 140374204640886 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 324 0 0
/proc/26514/statm: 148954 116374 10421 1052 0 124284 0
[pid=26514/tid=26519] ppid=26513 vsize=595816 CPUtime=59.09
/proc/26514/task/26519/stat : 26519 (aptitude) S 26513 26514 17863 34816 17863 4202560 99219 2206 0 5 5854 55 0 0 20 0 2 0 29848354 610115584 116374 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134827008 140374215893716 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 63.58
Current children cumulated vsize (KiB) 595816

[startup+67.6002 s]
/proc/loadavg: 1.07 1.12 1.09 2/57 26520
/proc/meminfo: memFree=347112/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=595816 CPUtime=63.98
/proc/26514/stat : 26514 (aptitude) R 26513 26514 17863 34816 17863 4202496 123802 2206 308 5 6319 79 0 0 20 0 2 0 29847961 610115584 116437 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742633160 140374242047288 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 324 0 0
/proc/26514/statm: 148954 116437 10422 1052 0 124284 0
[pid=26514/tid=26519] ppid=26513 vsize=595816 CPUtime=59.09
/proc/26514/task/26519/stat : 26519 (aptitude) S 26513 26514 17863 34816 17863 4202560 99219 2206 0 5 5854 55 0 0 20 0 2 0 29848354 610115584 116437 18446744073709551615 140374247149568 140374251456920 140734742641456 140374134827008 140374215893716 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 63.98
Current children cumulated vsize (KiB) 595816

[startup+68.0012 s]
/proc/loadavg: 1.07 1.12 1.09 2/57 26520
/proc/meminfo: memFree=347112/1022884 swapFree=0/0
[pid=26514] ppid=26513 vsize=363420 CPUtime=64.38
/proc/26514/stat : 26514 (aptitude) R 26513 26514 17863 34816 17863 4202496 124586 2705 308 5 6335 101 0 2 20 0 1 0 29847961 372142080 40924 18446744073709551615 140374247149568 140374251456920 140734742641456 140734742641016 140374205015530 0 134217728 4096 0 0 0 0 17 0 0 0 324 0 0
/proc/26514/statm: 90855 40924 1521 1052 0 75111 0
Current children cumulated CPU time (s) 64.38
Current children cumulated vsize (KiB) 363420

Child status: 0
Real time (s): 68.066
CPU time (s): 64.44
CPU user time (s): 63.364
CPU system time (s): 1.07607
CPU usage (%): 94.6729
Max. virtual memory (cumulated for all children) (KiB): 595816

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 63.364
system time used= 1.07607
maximum resident set size= 466340
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 127355
page faults= 316
swaps= 0
block input operations= 265720
block output operations= 168
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2622
involuntary context switches= 1137

runsolver used 0.072004 second user time and 0.248015 second system time

The end