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/93.runsolver.aptitude aptitude -s -y --without-recommends install libccid wmrack librrd0 xbindkeys freeradius-mysql 

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.23 1.14 1.05 2/55 24204
/proc/meminfo: memFree=961824/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=3152 CPUtime=0
/proc/24204/stat : 24204 (runsolver) R 24203 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29152568 3227648 33 18446744073709551615 134512640 134586868 4286882416 4286880464 4151731248 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24204/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.124025 s]
/proc/loadavg: 1.23 1.14 1.05 2/55 24204
/proc/meminfo: memFree=961824/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=28716 CPUtime=0
/proc/24204/stat : 24204 (aptitude) D 24203 24204 17863 34816 17863 4202496 155 0 11 0 0 0 0 0 20 0 1 0 29152568 29405184 78 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095568376 140164090787363 0 0 0 0 0 0 0 17 0 0 0 11 0 0
/proc/24204/statm: 7179 78 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.200379 s]
/proc/loadavg: 1.23 1.14 1.05 2/55 24204
/proc/meminfo: memFree=961824/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=40832 CPUtime=0
/proc/24204/stat : 24204 (aptitude) D 24203 24204 17863 34816 17863 4202496 177 0 16 0 0 0 0 0 20 0 1 0 29152568 41811968 101 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095568184 140164090787363 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/24204/statm: 10208 101 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.300364 s]
/proc/loadavg: 1.23 1.14 1.05 2/55 24204
/proc/meminfo: memFree=961824/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=54968 CPUtime=0.01
/proc/24204/stat : 24204 (aptitude) D 24203 24204 17863 34816 17863 4202496 1072 0 25 0 1 0 0 0 20 0 1 0 29152568 56287232 988 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095566920 140164061684080 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/24204/statm: 13742 988 824 1052 0 106 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 54968

[startup+0.700306 s]
/proc/loadavg: 1.23 1.14 1.05 2/55 24204
/proc/meminfo: memFree=961824/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=100508 CPUtime=0.06
/proc/24204/stat : 24204 (aptitude) D 24203 24204 17863 34816 17863 4202496 7414 1705 78 4 4 2 0 0 20 0 1 0 29152568 102920192 7294 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095563024 140164087768890 0 134217728 4096 0 0 0 0 17 0 0 0 61 0 0
/proc/24204/statm: 25127 7294 6119 1052 0 1122 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 100508

[startup+1.50021 s]
/proc/loadavg: 1.23 1.14 1.05 2/56 24208
/proc/meminfo: memFree=943208/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=119772 CPUtime=0.54
/proc/24204/stat : 24204 (aptitude) D 24203 24204 17863 34816 17863 4202496 16413 1705 90 4 48 6 0 0 20 0 1 0 29152568 122646528 14782 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095561192 140164061684080 0 134217728 4096 0 0 0 0 17 0 0 0 91 0 0
/proc/24204/statm: 29943 14782 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.54
Current children cumulated vsize (KiB) 119772

[startup+3.10025 s]
/proc/loadavg: 1.23 1.14 1.05 2/57 24209
/proc/meminfo: memFree=850820/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=132516 CPUtime=1.78
/proc/24204/stat : 24204 (aptitude) R 24203 24204 17863 34816 17863 4202496 19372 1705 90 4 168 10 0 0 20 0 2 0 29152568 135696384 16732 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095559560 140164093658256 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 128 0 0
/proc/24204/statm: 33129 16732 9585 1052 0 9124 0
[pid=24204/tid=24209] ppid=24203 vsize=132516 CPUtime=0
/proc/24204/task/24209/stat : 24209 (aptitude) S 24203 24204 17863 34816 17863 4202560 4 1705 0 4 0 0 0 0 20 0 2 0 29152767 135696384 16732 18446744073709551615 140164092928000 140164097235352 140737095571760 140163983755264 140164061672148 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.78
Current children cumulated vsize (KiB) 132516
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.21 1.14 1.05 2/57 24210
/proc/meminfo: memFree=816844/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=169984 CPUtime=4.91
/proc/24204/stat : 24204 (aptitude) S 24203 24204 17863 34816 17863 4202496 30442 2202 91 6 473 18 0 0 20 0 2 0 29152568 174063616 26194 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095563520 140164061673035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 130 0 0
/proc/24204/statm: 42496 26194 9700 1052 0 18491 0
[pid=24204/tid=24209] ppid=24203 vsize=169984 CPUtime=1.79
/proc/24204/task/24209/stat : 24209 (aptitude) R 24203 24204 17863 34816 17863 4202560 9944 2202 0 6 176 3 0 0 20 0 2 0 29152767 174063616 26194 18446744073709551615 140164092928000 140164097235352 140737095571760 140163983748744 140164050438471 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.91
Current children cumulated vsize (KiB) 169984
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.19 1.14 1.05 2/57 24210
/proc/meminfo: memFree=718760/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=257360 CPUtime=11.28
/proc/24204/stat : 24204 (aptitude) S 24203 24204 17863 34816 17863 4202496 53013 2202 91 6 1100 28 0 0 20 0 2 0 29152568 263536640 48059 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095563520 140164061673035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 130 0 0
/proc/24204/statm: 64340 48059 9700 1052 0 40335 0
[pid=24204/tid=24209] ppid=24203 vsize=257360 CPUtime=8.15
/proc/24204/task/24209/stat : 24209 (aptitude) R 24203 24204 17863 34816 17863 4202560 32515 2202 0 6 803 12 0 0 20 0 2 0 29152767 263536640 48059 18446744073709551615 140164092928000 140164097235352 140737095571760 140163983748920 140164095756867 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) 257360

[startup+25.5003 s]
/proc/loadavg: 1.15 1.13 1.05 2/57 24210
/proc/meminfo: memFree=556320/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=484852 CPUtime=24.02
/proc/24204/stat : 24204 (aptitude) S 24203 24204 17863 34816 17863 4202496 93479 2202 91 6 2360 42 0 0 20 0 2 0 29152568 496488448 88520 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095563520 140164061673035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 130 0 0
/proc/24204/statm: 121213 88520 9716 1052 0 97208 0
[pid=24204/tid=24209] ppid=24203 vsize=484852 CPUtime=20.89
/proc/24204/task/24209/stat : 24209 (aptitude) R 24203 24204 17863 34816 17863 4202560 72974 2202 0 6 2063 26 0 0 20 0 2 0 29152767 496488448 88520 18446744073709551615 140164092928000 140164097235352 140737095571760 140163983749400 140164050438521 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) 484852

[startup+51.1003 s]
/proc/loadavg: 1.10 1.12 1.05 2/57 24210
/proc/meminfo: memFree=257480/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=787172 CPUtime=49.5
/proc/24204/stat : 24204 (aptitude) S 24203 24204 17863 34816 17863 4202496 168922 2202 91 6 4875 75 0 0 20 0 2 0 29152568 806064128 163963 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095563520 140164061673035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 130 0 0
/proc/24204/statm: 196793 163963 9716 1052 0 172788 0
[pid=24204/tid=24209] ppid=24203 vsize=787172 CPUtime=46.37
/proc/24204/task/24209/stat : 24209 (aptitude) R 24203 24204 17863 34816 17863 4202560 148417 2202 0 6 4577 60 0 0 20 0 2 0 29152767 806064128 163963 18446744073709551615 140164092928000 140164097235352 140737095571760 140163983748536 140164095624710 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 49.5
Current children cumulated vsize (KiB) 787172

[startup+102.3 s]
/proc/loadavg: 1.04 1.10 1.04 2/57 24210
/proc/meminfo: memFree=17652/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=1020096 CPUtime=100.47
/proc/24204/stat : 24204 (aptitude) S 24203 24204 17863 34816 17863 4202496 227220 2202 91 6 9939 108 0 0 20 0 2 0 29152568 1044578304 222261 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095563520 140164061673035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 130 0 0
/proc/24204/statm: 255024 222261 9716 1052 0 231019 0
[pid=24204/tid=24209] ppid=24203 vsize=1020096 CPUtime=97.34
/proc/24204/task/24209/stat : 24209 (aptitude) R 24203 24204 17863 34816 17863 4202560 206715 2202 0 6 9641 93 0 0 20 0 2 0 29152767 1044578304 222261 18446744073709551615 140164092928000 140164097235352 140737095571760 140163983749400 140164088328816 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 100.47
Current children cumulated vsize (KiB) 1020096



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+123.503 s]
/proc/loadavg: 1.09 1.10 1.05 3/57 24210
/proc/meminfo: memFree=9432/1022884 swapFree=0/0
[pid=24204] ppid=24203 vsize=1151980 CPUtime=120.44
/proc/24204/stat : 24204 (aptitude) S 24203 24204 17863 34816 17863 4202496 259962 2202 154 6 11916 128 0 0 20 0 2 0 29152568 1179627520 243509 18446744073709551615 140164092928000 140164097235352 140737095571760 140737095563520 140164061673035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 130 0 0
/proc/24204/statm: 287995 243509 9708 1052 0 263990 0
[pid=24204/tid=24209] ppid=24203 vsize=1151980 CPUtime=117.31
/proc/24204/task/24209/stat : 24209 (aptitude) R 24203 24204 17863 34816 17863 4202560 239446 2202 57 6 11617 114 0 0 20 0 2 0 29152767 1179627520 243509 18446744073709551615 140164092928000 140164097235352 140737095571760 140163983746936 140164050509567 0 134217728 4096 0 0 0 0 -1 0 0 0 77 0 0
Current children cumulated CPU time (s) 120.44
Current children cumulated vsize (KiB) 1151980

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

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

Child ended because it received signal 15 (SIGTERM)
Real time (s): 123.628
CPU time (s): 120.532
CPU user time (s): 119.187
CPU system time (s): 1.34408
CPU usage (%): 97.4956
Max. virtual memory (cumulated for all children) (KiB): 1151980

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 119.187
system time used= 1.34408
maximum resident set size= 981460
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262164
page faults= 160
swaps= 0
block input operations= 186808
block output operations= 80
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2032
involuntary context switches= 2758

runsolver used 0.288018 second user time and 0.288018 second system time

The end