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/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.07 1.07 1.02 2/55 23010
/proc/meminfo: memFree=964512/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=3152 CPUtime=0
/proc/23010/stat : 23010 (runsolver) R 23009 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28776511 3227648 32 18446744073709551615 134512640 134586868 4293250384 4293248432 4151559216 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23010/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.120165 s]
/proc/loadavg: 1.07 1.07 1.02 2/55 23010
/proc/meminfo: memFree=964512/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=12328 CPUtime=0
/proc/23010/stat : 23010 (aptitude) D 23009 23010 17863 34816 17863 4202496 129 0 5 0 0 0 0 0 20 0 1 0 28776511 12623872 51 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426271592 139633763374627 0 0 0 0 0 0 0 17 0 0 0 11 0 0
/proc/23010/statm: 3082 51 36 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.200312 s]
/proc/loadavg: 1.07 1.07 1.02 2/55 23010
/proc/meminfo: memFree=964512/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=33024 CPUtime=0
/proc/23010/stat : 23010 (aptitude) D 23009 23010 17863 34816 17863 4202496 162 0 13 0 0 0 0 0 20 0 1 0 28776511 33816576 86 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426271112 139633763374627 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23010/statm: 8256 86 55 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 33024

[startup+0.300298 s]
/proc/loadavg: 1.07 1.07 1.02 2/55 23010
/proc/meminfo: memFree=964512/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=54968 CPUtime=0
/proc/23010/stat : 23010 (aptitude) D 23009 23010 17863 34816 17863 4202496 983 0 25 0 0 0 0 0 20 0 1 0 28776511 56287232 900 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426271624 139633723360512 0 134217728 0 0 0 0 0 17 0 0 0 28 0 0
/proc/23010/statm: 13742 900 748 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700258 s]
/proc/loadavg: 1.07 1.07 1.02 2/55 23010
/proc/meminfo: memFree=964512/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=100508 CPUtime=0.01
/proc/23010/stat : 23010 (aptitude) D 23009 23010 17863 34816 17863 4202496 2382 1706 40 4 0 1 0 0 20 0 1 0 28776511 102920192 2224 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426266160 139633760565146 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/23010/statm: 25127 2224 1049 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.07 1.07 1.02 1/56 23014
/proc/meminfo: memFree=956320/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=100508 CPUtime=0.02
/proc/23010/stat : 23010 (aptitude) D 23009 23010 17863 34816 17863 4202496 4033 1706 156 4 0 2 0 0 20 0 1 0 28776511 102920192 3991 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426266160 139633760565146 0 134217728 4096 0 0 0 0 17 0 0 0 141 0 0
/proc/23010/statm: 25127 3991 2816 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+3.1002 s]
/proc/loadavg: 1.07 1.07 1.02 2/56 23014
/proc/meminfo: memFree=954212/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=119772 CPUtime=0.59
/proc/23010/stat : 23010 (aptitude) R 23009 23010 17863 34816 17863 4202496 16236 1706 269 4 50 9 0 0 20 0 1 0 28776511 122646528 14784 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426264120 139633760415905 0 134217728 4096 0 0 0 0 17 0 0 0 244 0 0
/proc/23010/statm: 29943 14784 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.59
Current children cumulated vsize (KiB) 119772
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.06 1.07 1.02 2/57 23016
/proc/meminfo: memFree=840372/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=140784 CPUtime=3.4
/proc/23010/stat : 23010 (aptitude) S 23009 23010 17863 34816 17863 4202496 22356 2202 269 6 319 20 0 1 20 0 2 0 28776511 144162816 18894 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426266448 139633734260299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0
/proc/23010/statm: 35196 18894 9697 1052 0 11191 0
[pid=23010/tid=23015] ppid=23009 vsize=140784 CPUtime=0.25
/proc/23010/task/23015/stat : 23015 (aptitude) R 23009 23010 17863 34816 17863 4202560 2043 2202 0 6 23 1 0 1 20 0 2 0 28776863 144162816 18894 18446744073709551615 139633765515264 139633769822616 140737426274688 139633656336056 139633734250929 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.4
Current children cumulated vsize (KiB) 140784
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.06 1.07 1.02 2/57 23016
/proc/meminfo: memFree=776884/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=267964 CPUtime=9.77
/proc/23010/stat : 23010 (aptitude) S 23009 23010 17863 34816 17863 4202496 38624 2202 269 6 947 29 0 1 20 0 2 0 28776511 274395136 34324 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426266448 139633734260299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0
/proc/23010/statm: 66991 34324 9700 1052 0 42986 0
[pid=23010/tid=23015] ppid=23009 vsize=267964 CPUtime=6.62
/proc/23010/task/23015/stat : 23015 (aptitude) R 23009 23010 17863 34816 17863 4202560 18309 2202 0 6 651 10 0 1 20 0 2 0 28776863 274395136 34324 18446744073709551615 139633765515264 139633769822616 140737426274688 139633656333800 139633766160690 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.77
Current children cumulated vsize (KiB) 267964
heavy processes:

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

[startup+12.8035 s]
/proc/loadavg: 1.06 1.07 1.02 2/57 23016
/proc/meminfo: memFree=770932/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=268756 CPUtime=9.87
/proc/23010/stat : 23010 (aptitude) S 23009 23010 17863 34816 17863 4202496 38833 2202 269 6 956 30 0 1 20 0 2 0 28776511 275206144 34533 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426266448 139633734260299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0
/proc/23010/statm: 67189 34533 9700 1052 0 43184 0
[pid=23010/tid=23015] ppid=23009 vsize=268756 CPUtime=6.71
/proc/23010/task/23015/stat : 23015 (aptitude) R 23009 23010 17863 34816 17863 4202560 18518 2202 0 6 660 10 0 1 20 0 2 0 28776863 275206144 34533 18446744073709551615 139633765515264 139633769822616 140737426274688 139633656333848 139633767143585 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.87
Current children cumulated vsize (KiB) 268756

[startup+13.6002 s]
/proc/loadavg: 1.06 1.07 1.02 2/57 23016
/proc/meminfo: memFree=766716/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=275356 CPUtime=10.66
/proc/23010/stat : 23010 (aptitude) S 23009 23010 17863 34816 17863 4202496 40455 2202 269 6 1035 30 0 1 20 0 2 0 28776511 281964544 36153 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426266448 139633734260299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0
/proc/23010/statm: 68839 36153 9700 1052 0 44834 0
[pid=23010/tid=23015] ppid=23009 vsize=275356 CPUtime=7.51
/proc/23010/task/23015/stat : 23015 (aptitude) R 23009 23010 17863 34816 17863 4202560 20140 2202 0 6 739 11 0 1 20 0 2 0 28776863 281964544 36153 18446744073709551615 139633765515264 139633769822616 140737426274688 139633656336008 139633768257856 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.66
Current children cumulated vsize (KiB) 275356

[startup+14.0002 s]
/proc/loadavg: 1.06 1.07 1.02 2/57 23016
/proc/meminfo: memFree=766716/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=276468 CPUtime=11.06
/proc/23010/stat : 23010 (aptitude) R 23009 23010 17863 34816 17863 4202496 41554 2202 269 6 1075 30 0 1 20 0 2 0 28776511 283103232 36628 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426264776 139633760915168 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0
/proc/23010/statm: 69117 36628 9749 1052 0 45105 0
[pid=23010/tid=23015] ppid=23009 vsize=276468 CPUtime=7.68
/proc/23010/task/23015/stat : 23015 (aptitude) S 23009 23010 17863 34816 17863 4202560 20438 2202 0 6 756 11 0 1 20 0 2 0 28776863 283103232 36628 18446744073709551615 139633765515264 139633769822616 140737426274688 139633656342528 139633734259412 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.06
Current children cumulated vsize (KiB) 276468

[startup+14.4032 s]
/proc/loadavg: 1.06 1.07 1.02 2/57 23016
/proc/meminfo: memFree=761500/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=276468 CPUtime=11.47
/proc/23010/stat : 23010 (aptitude) R 23009 23010 17863 34816 17863 4202496 43788 2703 269 6 1106 39 0 2 20 0 2 0 28776511 283103232 36800 18446744073709551615 139633765515264 139633769822616 140737426274688 140737426265848 139633723359301 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0
/proc/23010/statm: 69117 36800 9749 1052 0 45105 0
[pid=23010/tid=23015] ppid=23009 vsize=276468 CPUtime=7.69
/proc/23010/task/23015/stat : 23015 (aptitude) S 23009 23010 17863 34816 17863 4202560 20438 2703 0 6 756 11 0 2 20 0 2 0 28776863 283103232 36800 18446744073709551615 139633765515264 139633769822616 140737426274688 139633656342528 139633734259412 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.47
Current children cumulated vsize (KiB) 276468

[startup+14.5003 s]
/proc/loadavg: 1.06 1.07 1.02 2/57 23016
/proc/meminfo: memFree=761500/1022884 swapFree=0/0
[pid=23010] ppid=23009 vsize=0 CPUtime=11.56
/proc/23010/stat : 23010 (aptitude) R 23009 23010 17863 34816 17863 4202500 44338 2703 269 6 1110 44 0 2 20 0 1 0 28776511 0 0 18446744073709551615 0 0 0 0 0 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0
/proc/23010/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.56
Current children cumulated vsize (KiB) 0

Child status: 0
Real time (s): 14.5005
CPU time (s): 11.5767
CPU user time (s): 11.1127
CPU system time (s): 0.464029
CPU usage (%): 79.8369
Max. virtual memory (cumulated for all children) (KiB): 276468

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.1127
system time used= 0.464029
maximum resident set size= 147260
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 47041
page faults= 275
swaps= 0
block input operations= 188736
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1987
involuntary context switches= 247

runsolver used 0.020001 second user time and 0.060003 second system time

The end