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/13.runsolver.aptitude aptitude -s -y --without-recommends install wmakerconf mgetty echoping apache2-common libgtkmm-2.4-1 

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.27 1.12 1.04 2/55 25086
/proc/meminfo: memFree=942100/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=3152 CPUtime=0
/proc/25086/stat : 25086 (runsolver) R 25085 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29333763 3227648 33 18446744073709551615 134512640 134586868 4292542848 4292540896 4151821360 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25086/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.186127 s]
/proc/loadavg: 1.27 1.12 1.04 2/55 25086
/proc/meminfo: memFree=942100/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=54860 CPUtime=0
/proc/25086/stat : 25086 (aptitude) D 25085 25086 17863 34816 17863 4202496 632 0 13 0 0 0 0 0 20 0 1 0 29333763 56176640 545 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167619576 140271859623865 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/25086/statm: 13715 545 448 1052 0 73 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54860

[startup+0.200466 s]
/proc/loadavg: 1.27 1.12 1.04 2/55 25086
/proc/meminfo: memFree=942100/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=54968 CPUtime=0
/proc/25086/stat : 25086 (aptitude) D 25085 25086 17863 34816 17863 4202496 1031 0 15 0 0 0 0 0 20 0 1 0 29333763 56287232 937 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167615480 140271819658496 0 134217728 4096 0 0 0 0 17 0 0 0 18 0 0
/proc/25086/statm: 13742 937 783 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.300439 s]
/proc/loadavg: 1.27 1.12 1.04 2/55 25086
/proc/meminfo: memFree=942100/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=59216 CPUtime=0
/proc/25086/stat : 25086 (aptitude) D 25085 25086 17863 34816 17863 4202496 1135 0 16 0 0 0 0 0 20 0 1 0 29333763 60637184 1039 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612696 140271859672454 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/25086/statm: 14804 1039 866 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 59216

[startup+0.700204 s]
/proc/loadavg: 1.27 1.12 1.04 2/55 25086
/proc/meminfo: memFree=942100/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=103288 CPUtime=0.29
/proc/25086/stat : 25086 (aptitude) R 25085 25086 17863 34816 17863 4202496 11286 1705 23 4 26 2 1 0 20 0 1 0 29333763 105766912 11108 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167611632 140271856654083 0 134217728 4096 0 0 0 0 17 0 0 0 35 0 0
/proc/25086/statm: 25822 11108 9896 1052 0 1159 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103288

[startup+1.5002 s]
/proc/loadavg: 1.27 1.12 1.04 2/56 25090
/proc/meminfo: memFree=898328/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=123068 CPUtime=0.64
/proc/25086/stat : 25086 (aptitude) R 25085 25086 17863 34816 17863 4202496 17663 1705 23 4 52 11 1 0 20 0 1 0 29333763 126021632 15961 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167609800 140271830569328 0 134217728 4096 0 0 0 0 17 0 0 0 80 0 0
/proc/25086/statm: 30767 15961 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.64
Current children cumulated vsize (KiB) 123068

[startup+3.10031 s]
/proc/loadavg: 1.25 1.12 1.04 2/57 25091
/proc/meminfo: memFree=815116/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=136436 CPUtime=1.8
/proc/25086/stat : 25086 (aptitude) R 25085 25086 17863 34816 17863 4202496 20769 1705 23 4 164 15 1 0 20 0 2 0 29333763 139710464 17708 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167608664 140271856511761 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 34109 17708 10244 1052 0 9446 0
[pid=25086/tid=25091] ppid=25085 vsize=136436 CPUtime=0.01
/proc/25086/task/25091/stat : 25091 (aptitude) S 25085 25086 17863 34816 17863 4202560 4 1705 0 4 0 0 1 0 20 0 2 0 29333975 139710464 17708 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749490688 140271830557396 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.8
Current children cumulated vsize (KiB) 136436
heavy processes:

[startup+6.30031 s]
/proc/loadavg: 1.25 1.12 1.04 2/57 25092
/proc/meminfo: memFree=787960/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=168960 CPUtime=4.97
/proc/25086/stat : 25086 (aptitude) S 25085 25086 17863 34816 17863 4202496 30237 2203 23 4 475 21 1 0 20 0 2 0 29333763 173015040 25945 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612128 140271830558283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 42240 25945 10359 1052 0 17577 0
[pid=25086/tid=25091] ppid=25085 vsize=168960 CPUtime=1.53
/proc/25086/task/25091/stat : 25091 (aptitude) R 25085 25086 17863 34816 17863 4202560 8282 2203 0 4 150 2 1 0 20 0 2 0 29333975 173015040 25945 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749484216 140271819314958 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.97
Current children cumulated vsize (KiB) 168960
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.21 1.12 1.03 2/57 25092
/proc/meminfo: memFree=723976/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=221540 CPUtime=11.33
/proc/25086/stat : 25086 (aptitude) S 25085 25086 17863 34816 17863 4202496 43813 2203 23 4 1105 27 1 0 20 0 2 0 29333763 226856960 39084 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612128 140271830558283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 55385 39084 10359 1052 0 30722 0
[pid=25086/tid=25091] ppid=25085 vsize=221540 CPUtime=7.89
/proc/25086/task/25091/stat : 25091 (aptitude) R 25085 25086 17863 34816 17863 4202560 21858 2203 0 4 780 8 1 0 20 0 2 0 29333975 226856960 39084 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749482008 140271864459546 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.33
Current children cumulated vsize (KiB) 221540

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

[startup+12.8004 s]
/proc/loadavg: 1.21 1.12 1.03 2/57 25092
/proc/meminfo: memFree=723976/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=222200 CPUtime=11.43
/proc/25086/stat : 25086 (aptitude) S 25085 25086 17863 34816 17863 4202496 44005 2203 23 4 1115 27 1 0 20 0 2 0 29333763 227532800 39276 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612128 140271830558283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 55550 39276 10359 1052 0 30887 0
[pid=25086/tid=25091] ppid=25085 vsize=222200 CPUtime=7.99
/proc/25086/task/25091/stat : 25091 (aptitude) R 25085 25086 17863 34816 17863 4202560 22050 2203 0 4 790 8 1 0 20 0 2 0 29333975 227532800 39276 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749484296 140271827746384 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.43
Current children cumulated vsize (KiB) 222200

[startup+19.2003 s]
/proc/loadavg: 1.19 1.11 1.03 2/57 25092
/proc/meminfo: memFree=688016/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=320696 CPUtime=17.8
/proc/25086/stat : 25086 (aptitude) S 25085 25086 17863 34816 17863 4202496 52490 2203 23 4 1749 30 1 0 20 0 2 0 29333763 328392704 47485 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612128 140271830558283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 80174 47485 10360 1052 0 55511 0
[pid=25086/tid=25091] ppid=25085 vsize=320696 CPUtime=14.36
/proc/25086/task/25091/stat : 25091 (aptitude) R 25085 25086 17863 34816 17863 4202560 30534 2203 0 4 1424 11 1 0 20 0 2 0 29333975 328392704 47485 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749484216 140271828126656 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.8
Current children cumulated vsize (KiB) 320696

[startup+22.4003 s]
/proc/loadavg: 1.18 1.11 1.03 2/57 25092
/proc/meminfo: memFree=672516/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=336800 CPUtime=20.98
/proc/25086/stat : 25086 (aptitude) S 25085 25086 17863 34816 17863 4202496 56530 2203 23 4 2065 32 1 0 20 0 2 0 29333763 344883200 51505 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612128 140271830558283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 84200 51505 10360 1052 0 59537 0
[pid=25086/tid=25091] ppid=25085 vsize=336800 CPUtime=17.54
/proc/25086/task/25091/stat : 25091 (aptitude) R 25085 25086 17863 34816 17863 4202560 34574 2203 0 4 1740 13 1 0 20 0 2 0 29333975 344883200 51505 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749482008 140271828122582 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 20.98
Current children cumulated vsize (KiB) 336800

[startup+24.0003 s]
/proc/loadavg: 1.18 1.11 1.03 2/57 25092
/proc/meminfo: memFree=667184/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=343400 CPUtime=22.57
/proc/25086/stat : 25086 (aptitude) S 25085 25086 17863 34816 17863 4202496 58187 2203 23 4 2222 34 1 0 20 0 2 0 29333763 351641600 53162 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612128 140271830558283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 85850 53162 10360 1052 0 61187 0
[pid=25086/tid=25091] ppid=25085 vsize=343400 CPUtime=19.13
/proc/25086/task/25091/stat : 25091 (aptitude) R 25085 25086 17863 34816 17863 4202560 36231 2203 0 4 1897 15 1 0 20 0 2 0 29333975 351641600 53162 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749481960 140271827727360 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.57
Current children cumulated vsize (KiB) 343400

[startup+24.8003 s]
/proc/loadavg: 1.18 1.11 1.03 3/57 25092
/proc/meminfo: memFree=662348/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=344120 CPUtime=23.37
/proc/25086/stat : 25086 (aptitude) R 25085 25086 17863 34816 17863 4202496 61242 2203 23 4 2301 35 1 0 20 0 2 0 29333763 352378880 53574 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612184 140271856710968 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 86030 53574 10409 1052 0 61360 0
[pid=25086/tid=25091] ppid=25085 vsize=344120 CPUtime=19.33
/proc/25086/task/25091/stat : 25091 (aptitude) S 25085 25086 17863 34816 17863 4202560 36422 2203 0 4 1916 16 1 0 20 0 2 0 29333975 352378880 53574 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749490688 140271830557396 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.37
Current children cumulated vsize (KiB) 344120

[startup+25.0003 s]
/proc/loadavg: 1.18 1.11 1.03 3/57 25092
/proc/meminfo: memFree=662348/1022884 swapFree=0/0
[pid=25086] ppid=25085 vsize=344120 CPUtime=23.57
/proc/25086/stat : 25086 (aptitude) R 25085 25086 17863 34816 17863 4202496 61543 2702 23 4 2312 43 2 0 20 0 2 0 29333763 352378880 53723 18446744073709551615 140271861813248 140271866120600 140735167620368 140735167612184 140271819657285 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 125 0 0
/proc/25086/statm: 86030 53723 10409 1052 0 61360 0
[pid=25086/tid=25091] ppid=25085 vsize=344120 CPUtime=19.34
/proc/25086/task/25091/stat : 25091 (aptitude) S 25085 25086 17863 34816 17863 4202560 36422 2702 0 4 1916 16 2 0 20 0 2 0 29333975 352378880 53723 18446744073709551615 140271861813248 140271866120600 140735167620368 140271749490688 140271830557396 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.57
Current children cumulated vsize (KiB) 344120

Child status: 0
Real time (s): 25.0607
CPU time (s): 23.6455
CPU user time (s): 23.1534
CPU system time (s): 0.49203
CPU usage (%): 94.3527
Max. virtual memory (cumulated for all children) (KiB): 344120

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.1534
system time used= 0.49203
maximum resident set size= 214892
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 64771
page faults= 27
swaps= 0
block input operations= 212840
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1874
involuntary context switches= 446

runsolver used 0.028001 second user time and 0.108006 second system time

The end