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/33.runsolver.aptitude aptitude -s -y --without-recommends install python-rpy-doc fbgrab pileup python2.1-gdbm gtk-engines-qtpixmap 

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.08 1.05 1.01 2/55 23198
/proc/meminfo: memFree=869468/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=3152 CPUtime=0
/proc/23198/stat : 23198 (runsolver) R 23197 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28863926 3227648 32 18446744073709551615 134512640 134586868 4292983312 4292981360 4151551024 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.186398 s]
/proc/loadavg: 1.08 1.05 1.01 2/55 23198
/proc/meminfo: memFree=869468/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=100508 CPUtime=0.17
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 10602 1707 0 0 15 2 0 0 20 0 1 0 28863926 102920192 10404 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499704560 139767110790717 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 25127 10404 9229 1052 0 1122 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 100508

[startup+0.200283 s]
/proc/loadavg: 1.08 1.05 1.01 2/55 23198
/proc/meminfo: memFree=869468/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=100508 CPUtime=0.18
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 10605 1707 0 0 16 2 0 0 20 0 1 0 28863926 102920192 10407 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499704560 139767072972520 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300269 s]
/proc/loadavg: 1.08 1.05 1.01 2/55 23198
/proc/meminfo: memFree=869468/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=111108 CPUtime=0.28
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 12362 1707 0 0 26 2 0 0 20 0 1 0 28863926 113774592 12156 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499704888 139767117522540 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 27777 12156 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700201 s]
/proc/loadavg: 1.08 1.05 1.01 2/55 23198
/proc/meminfo: memFree=869468/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=123288 CPUtime=0.68
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 17028 1707 0 0 63 5 0 0 20 0 2 0 28863926 126246912 14303 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499709080 139767110234317 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50023 s]
/proc/loadavg: 1.08 1.05 1.01 2/57 23203
/proc/meminfo: memFree=841312/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=132384 CPUtime=1.48
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 19433 1707 0 0 142 6 0 0 20 0 2 0 28863926 135561216 16703 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499703648 139767072901256 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 33096 16703 9585 1052 0 9091 0
[pid=23198/tid=23203] ppid=23197 vsize=132384 CPUtime=0
/proc/23198/task/23203/stat : 23203 (aptitude) S 23197 23198 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 28863991 135561216 16703 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006218240 139767084135124 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) 132384

[startup+3.10024 s]
/proc/loadavg: 1.08 1.05 1.01 2/57 23204
/proc/meminfo: memFree=840064/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=133792 CPUtime=3.08
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 20662 2204 0 0 294 13 1 0 20 0 2 0 28863926 137003008 16982 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499704936 139767084146266 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 33448 16982 9682 1052 0 9443 0
[pid=23198/tid=23203] ppid=23197 vsize=133792 CPUtime=0.01
/proc/23198/task/23203/stat : 23203 (aptitude) R 23197 23198 17863 34816 17863 4202560 77 2204 0 0 0 0 1 0 20 0 2 0 28863991 137003008 16982 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006218120 139767072892848 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) 133792

[startup+6.30024 s]
/proc/loadavg: 1.08 1.05 1.01 2/57 23204
/proc/meminfo: memFree=800392/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=184156 CPUtime=6.27
/proc/23198/stat : 23198 (aptitude) S 23197 23198 17863 34816 17863 4202496 33878 2204 0 0 606 20 1 0 20 0 2 0 28863926 188575744 29731 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499705056 139767084136011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 46039 29731 9700 1052 0 22034 0
[pid=23198/tid=23203] ppid=23197 vsize=184156 CPUtime=3.19
/proc/23198/task/23203/stat : 23203 (aptitude) R 23197 23198 17863 34816 17863 4202560 13292 2204 0 0 312 6 1 0 20 0 2 0 28863991 188575744 29731 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006211768 139767110214777 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 184156

[startup+12.7003 s]
/proc/loadavg: 1.06 1.05 1.00 2/57 23204
/proc/meminfo: memFree=755628/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=285348 CPUtime=12.63
/proc/23198/stat : 23198 (aptitude) S 23197 23198 17863 34816 17863 4202496 43168 2204 0 0 1238 24 1 0 20 0 2 0 28863926 292196352 38684 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499705056 139767084136011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 71337 38684 9700 1052 0 47332 0
[pid=23198/tid=23203] ppid=23197 vsize=285348 CPUtime=9.55
/proc/23198/task/23203/stat : 23203 (aptitude) R 23197 23198 17863 34816 17863 4202560 22581 2204 0 0 944 10 1 0 20 0 2 0 28863991 292196352 38684 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006209560 139767072901216 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) 285348

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

[startup+12.8003 s]
/proc/loadavg: 1.06 1.05 1.00 2/57 23204
/proc/meminfo: memFree=755628/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=286008 CPUtime=12.73
/proc/23198/stat : 23198 (aptitude) S 23197 23198 17863 34816 17863 4202496 43327 2204 0 0 1248 24 1 0 20 0 2 0 28863926 292872192 38841 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499705056 139767084136011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 71502 38841 9700 1052 0 47497 0
[pid=23198/tid=23203] ppid=23197 vsize=286008 CPUtime=9.65
/proc/23198/task/23203/stat : 23203 (aptitude) R 23197 23198 17863 34816 17863 4202560 22740 2204 0 0 954 10 1 0 20 0 2 0 28863991 292872192 38841 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006211768 139767118237066 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.73
Current children cumulated vsize (KiB) 286008

[startup+16.0002 s]
/proc/loadavg: 1.06 1.05 1.00 2/57 23204
/proc/meminfo: memFree=734052/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=309344 CPUtime=15.92
/proc/23198/stat : 23198 (aptitude) S 23197 23198 17863 34816 17863 4202496 49213 2204 0 0 1563 28 1 0 20 0 2 0 28863926 316768256 44653 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499705056 139767084136011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 77336 44653 9700 1052 0 53331 0
[pid=23198/tid=23203] ppid=23197 vsize=309344 CPUtime=12.84
/proc/23198/task/23203/stat : 23203 (aptitude) R 23197 23198 17863 34816 17863 4202560 28626 2204 0 0 1269 14 1 0 20 0 2 0 28863991 316768256 44653 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006209560 139767081704224 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 15.92
Current children cumulated vsize (KiB) 309344

[startup+17.6003 s]
/proc/loadavg: 1.06 1.05 1.00 2/57 23204
/proc/meminfo: memFree=716816/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=320988 CPUtime=17.51
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 52345 2204 0 0 1720 30 1 0 20 0 2 0 28863926 328691712 47724 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499703432 139767117962109 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 80247 47724 9748 1052 0 56235 0
[pid=23198/tid=23203] ppid=23197 vsize=320988 CPUtime=14.31
/proc/23198/task/23203/stat : 23203 (aptitude) S 23197 23198 17863 34816 17863 4202560 31543 2204 0 0 1414 16 1 0 20 0 2 0 28863991 328691712 47724 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006218240 139767084135124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.51
Current children cumulated vsize (KiB) 320988

[startup+18.0002 s]
/proc/loadavg: 1.06 1.05 1.00 2/57 23204
/proc/meminfo: memFree=716816/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=321016 CPUtime=17.91
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 54810 2204 0 0 1760 30 1 0 20 0 2 0 28863926 328720384 47702 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499705496 139767117597351 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 80254 47702 9749 1052 0 56242 0
[pid=23198/tid=23203] ppid=23197 vsize=321016 CPUtime=14.31
/proc/23198/task/23203/stat : 23203 (aptitude) S 23197 23198 17863 34816 17863 4202560 31543 2204 0 0 1414 16 1 0 20 0 2 0 28863991 328720384 47702 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006218240 139767084135124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.91
Current children cumulated vsize (KiB) 321016

[startup+18.2002 s]
/proc/loadavg: 1.06 1.05 1.00 2/57 23204
/proc/meminfo: memFree=716816/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=321016 CPUtime=18.1
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 55093 2703 0 0 1773 35 1 1 20 0 2 0 28863926 328720384 47853 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499703384 139767072901447 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 80254 47853 9749 1052 0 56242 0
[pid=23198/tid=23203] ppid=23197 vsize=321016 CPUtime=14.32
/proc/23198/task/23203/stat : 23203 (aptitude) S 23197 23198 17863 34816 17863 4202560 31543 2703 0 0 1414 16 1 1 20 0 2 0 28863991 328720384 47853 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006218240 139767084135124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.1
Current children cumulated vsize (KiB) 321016

[startup+18.3007 s]
/proc/loadavg: 1.06 1.05 1.00 2/57 23204
/proc/meminfo: memFree=716816/1022884 swapFree=0/0
[pid=23198] ppid=23197 vsize=321016 CPUtime=18.21
/proc/23198/stat : 23198 (aptitude) R 23197 23198 17863 34816 17863 4202496 55552 2703 0 0 1778 41 1 1 20 0 2 0 28863926 328720384 41786 18446744073709551615 139767115390976 139767119698328 140735499713296 140735499709560 139767073256938 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23198/statm: 80254 41786 9749 1052 0 56242 0
[pid=23198/tid=23203] ppid=23197 vsize=321016 CPUtime=14.32
/proc/23198/task/23203/stat : 23203 (aptitude) S 23197 23198 17863 34816 17863 4202560 31543 2703 0 0 1414 16 1 1 20 0 2 0 28863991 328720384 41786 18446744073709551615 139767115390976 139767119698328 140735499713296 139767006218240 139767084135124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.21
Current children cumulated vsize (KiB) 321016

Child status: 0
Real time (s): 18.3433
CPU time (s): 18.2571
CPU user time (s): 17.7971
CPU system time (s): 0.460028
CPU usage (%): 99.5304
Max. virtual memory (cumulated for all children) (KiB): 321016

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 17.7971
system time used= 0.460028
maximum resident set size= 191720
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 58413
page faults= 0
swaps= 0
block input operations= 0
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 94
involuntary context switches= 360

runsolver used 0.012 second user time and 0.076004 second system time

The end