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/89.runsolver.aptitude aptitude -s -y --without-recommends install libmail-imapclient-perl smarty jigdo-file rpm cl-binary-types 

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.26 1.16 1.04 2/55 24160
/proc/meminfo: memFree=810544/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=3152 CPUtime=0
/proc/24160/stat : 24160 (runsolver) R 24159 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29128579 3227648 33 18446744073709551615 134512640 134586868 4290790272 4290788320 4151518256 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.147155 s]
/proc/loadavg: 1.26 1.16 1.04 2/55 24160
/proc/meminfo: memFree=810544/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=100508 CPUtime=0.13
/proc/24160/stat : 24160 (aptitude) R 24159 24160 17863 34816 17863 4202496 10588 1709 0 0 10 3 0 0 20 0 1 0 29128579 102920192 10389 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352000 139979870761488 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 25127 10389 9214 1052 0 1122 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 100508

[startup+0.200284 s]
/proc/loadavg: 1.26 1.16 1.04 2/55 24160
/proc/meminfo: memFree=810544/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=100508 CPUtime=0.19
/proc/24160/stat : 24160 (aptitude) R 24159 24160 17863 34816 17863 4202496 10606 1709 0 0 16 3 0 0 20 0 1 0 29128579 102920192 10407 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352000 139979870869161 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 100508

[startup+0.300272 s]
/proc/loadavg: 1.26 1.16 1.04 2/55 24160
/proc/meminfo: memFree=810544/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=111108 CPUtime=0.28
/proc/24160/stat : 24160 (aptitude) R 24159 24160 17863 34816 17863 4202496 12488 1709 0 0 25 3 0 0 20 0 1 0 29128579 113774592 12281 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352328 139979878159980 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 27777 12281 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700199 s]
/proc/loadavg: 1.26 1.16 1.04 2/55 24160
/proc/meminfo: memFree=810544/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=123288 CPUtime=0.68
/proc/24160/stat : 24160 (aptitude) R 24159 24160 17863 34816 17863 4202496 17029 1709 0 0 62 6 0 0 20 0 2 0 29128579 126246912 14303 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579356520 139979871429026 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.26 1.16 1.04 2/57 24165
/proc/meminfo: memFree=782264/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=132424 CPUtime=1.48
/proc/24160/stat : 24160 (aptitude) R 24159 24160 17863 34816 17863 4202496 19445 1709 0 0 140 8 0 0 20 0 2 0 29128579 135602176 16714 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579351088 139979870862432 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 33106 16714 9585 1052 0 9101 0
[pid=24160/tid=24165] ppid=24159 vsize=132424 CPUtime=0
/proc/24160/task/24165/stat : 24165 (aptitude) S 24159 24160 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29128644 135602176 16714 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766855680 139979844772564 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) 132424

[startup+3.10025 s]
/proc/loadavg: 1.24 1.16 1.04 2/57 24166
/proc/meminfo: memFree=781140/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=133836 CPUtime=3.07
/proc/24160/stat : 24160 (aptitude) R 24159 24160 17863 34816 17863 4202496 20618 2212 0 0 293 14 0 0 20 0 2 0 29128579 137048064 16951 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579347552 139979870856236 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 33459 16951 9644 1052 0 9454 0
[pid=24160/tid=24165] ppid=24159 vsize=133836 CPUtime=0
/proc/24160/task/24165/stat : 24165 (aptitude) S 24159 24160 17863 34816 17863 4202560 6 2212 0 0 0 0 0 0 20 0 2 0 29128644 137048064 16951 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766855680 139979844772564 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 133836

[startup+6.30024 s]
/proc/loadavg: 1.24 1.16 1.04 2/57 24166
/proc/meminfo: memFree=737376/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=180300 CPUtime=6.25
/proc/24160/stat : 24160 (aptitude) S 24159 24160 17863 34816 17863 4202496 33200 2212 0 0 609 16 0 0 20 0 2 0 29128579 184627200 28784 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352496 139979844773451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 45075 28784 9700 1052 0 21070 0
[pid=24160/tid=24165] ppid=24159 vsize=180300 CPUtime=3.15
/proc/24160/task/24165/stat : 24165 (aptitude) R 24159 24160 17863 34816 17863 4202560 12582 2212 0 0 312 3 0 0 20 0 2 0 29128644 184627200 28784 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766849208 139979878731608 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 180300

[startup+12.7002 s]
/proc/loadavg: 1.22 1.15 1.04 2/57 24166
/proc/meminfo: memFree=681948/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=302432 CPUtime=12.62
/proc/24160/stat : 24160 (aptitude) S 24159 24160 17863 34816 17863 4202496 47875 2212 0 0 1238 24 0 0 20 0 2 0 29128579 309690368 42918 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352496 139979844773451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 75608 42918 9700 1052 0 51603 0
[pid=24160/tid=24165] ppid=24159 vsize=302432 CPUtime=9.51
/proc/24160/task/24165/stat : 24165 (aptitude) R 24159 24160 17863 34816 17863 4202560 27256 2212 0 0 941 10 0 0 20 0 2 0 29128644 309690368 42918 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766849112 139979833519781 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 302432

[startup+25.5003 s]
/proc/loadavg: 1.17 1.14 1.04 2/57 24166
/proc/meminfo: memFree=579648/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=400856 CPUtime=25.36
/proc/24160/stat : 24160 (aptitude) S 24159 24160 17863 34816 17863 4202496 72554 2212 0 0 2501 35 0 0 20 0 2 0 29128579 410476544 67520 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352496 139979844773451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 100214 67520 9700 1052 0 76209 0
[pid=24160/tid=24165] ppid=24159 vsize=400856 CPUtime=22.26
/proc/24160/task/24165/stat : 24165 (aptitude) R 24159 24160 17863 34816 17863 4202560 51935 2212 0 0 2204 22 0 0 20 0 2 0 29128644 410476544 67520 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766847000 139979876673842 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 400856

[startup+51.1003 s]
/proc/loadavg: 1.11 1.13 1.04 2/57 24166
/proc/meminfo: memFree=368228/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=616124 CPUtime=50.85
/proc/24160/stat : 24160 (aptitude) S 24159 24160 17863 34816 17863 4202496 126401 2212 0 0 5024 61 0 0 20 0 2 0 29128579 630910976 121292 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352496 139979844773451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 154031 121292 9716 1052 0 130026 0
[pid=24160/tid=24165] ppid=24159 vsize=616124 CPUtime=47.73
/proc/24160/task/24165/stat : 24165 (aptitude) R 24159 24160 17863 34816 17863 4202560 105776 2212 0 0 4726 47 0 0 20 0 2 0 29128644 630910976 121292 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766847352 139979878229787 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 616124

[startup+102.3 s]
/proc/loadavg: 1.25 1.16 1.05 2/57 24166
/proc/meminfo: memFree=10188/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=1102952 CPUtime=100.11
/proc/24160/stat : 24160 (aptitude) S 24159 24160 17863 34816 17863 4202496 248137 2212 137 0 9892 119 0 0 20 0 2 0 29128579 1129422848 242881 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352496 139979844773451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 275738 242881 9646 1052 0 251733 0
[pid=24160/tid=24165] ppid=24159 vsize=1102952 CPUtime=97
/proc/24160/task/24165/stat : 24165 (aptitude) R 24159 24160 17863 34816 17863 4202560 227512 2212 137 0 9594 106 0 0 20 0 2 0 29128644 1129422848 242881 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766849112 139979878239325 0 134217728 4096 0 0 0 0 -1 0 0 0 139 0 0
Current children cumulated CPU time (s) 100.11
Current children cumulated vsize (KiB) 1102952



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+107.6 s]
/proc/loadavg: 1.23 1.15 1.05 2/57 24166
/proc/meminfo: memFree=9988/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=1151396 CPUtime=105.19
/proc/24160/stat : 24160 (aptitude) S 24159 24160 17863 34816 17863 4202496 260272 2212 161 0 10391 128 0 0 20 0 2 0 29128579 1179029504 247224 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352496 139979844773451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 287849 247224 9372 1052 0 263844 0
[pid=24160/tid=24165] ppid=24159 vsize=1151396 CPUtime=102.07
/proc/24160/task/24165/stat : 24165 (aptitude) R 24159 24160 17863 34816 17863 4202560 239639 2212 157 0 10093 114 0 0 20 0 2 0 29128644 1179029504 247224 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766847048 139979833524140 0 134217728 4096 0 0 0 0 -1 0 0 0 147 0 0
Current children cumulated CPU time (s) 105.19
Current children cumulated vsize (KiB) 1151396

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

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

[startup+107.6 s]
/proc/loadavg: 1.23 1.15 1.05 2/57 24166
/proc/meminfo: memFree=9988/1022884 swapFree=0/0
[pid=24160] ppid=24159 vsize=1151396 CPUtime=105.19
/proc/24160/stat : 24160 (aptitude) S 24159 24160 17863 34816 17863 4202496 260272 2212 161 0 10391 128 0 0 20 0 2 0 29128579 1179029504 247224 18446744073709551615 139979876028416 139979880335768 140733579360736 140733579352496 139979844773451 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24160/statm: 287849 247224 9372 1052 0 263844 0
[pid=24160/tid=24165] ppid=24159 vsize=1151396 CPUtime=102.07
/proc/24160/task/24165/stat : 24165 (aptitude) R 24159 24160 17863 34816 17863 4202560 239639 2212 157 0 10093 114 0 0 20 0 2 0 29128644 1179029504 247224 18446744073709551615 139979876028416 139979880335768 140733579360736 139979766847048 139979833524140 0 134217728 4096 0 0 0 0 -1 0 0 0 147 0 0
Current children cumulated CPU time (s) 105.19
Current children cumulated vsize (KiB) 1151396

Child ended because it received signal 15 (SIGTERM)
Real time (s): 107.725
CPU time (s): 105.331
CPU user time (s): 103.959
CPU system time (s): 1.37208
CPU usage (%): 97.7773
Max. virtual memory (cumulated for all children) (KiB): 1151396

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 103.958
system time used= 1.37208
maximum resident set size= 990840
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262583
page faults= 161
swaps= 0
block input operations= 3472
block output operations= 104
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 471
involuntary context switches= 2520

runsolver used 0.17201 second user time and 0.32402 second system time

The end