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/45.runsolver.aptitude aptitude -s -y --without-recommends install ftpgrab libtag1-doc libparams-validate-perl dovecot-common python-tclink 

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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.21 1.08 1.01 2/55 23309
/proc/meminfo: memFree=870240/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=54860 CPUtime=0
/proc/23309/stat : 23309 (aptitude) R 23308 23309 17863 34816 17863 4202496 587 0 0 0 0 0 0 0 20 0 1 0 28901028 56176640 486 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239423896 140728168157311 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 13715 486 398 1052 0 73 0

[startup+0.16979 s]
/proc/loadavg: 1.21 1.08 1.01 2/55 23309
/proc/meminfo: memFree=870240/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=100508 CPUtime=0.15
/proc/23309/stat : 23309 (aptitude) R 23308 23309 17863 34816 17863 4202496 10600 1707 0 0 13 2 0 0 20 0 1 0 28901028 102920192 10400 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239415952 140728165201812 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 25127 10400 9225 1052 0 1122 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 100508

[startup+0.200286 s]
/proc/loadavg: 1.21 1.08 1.01 2/55 23309
/proc/meminfo: memFree=870240/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=100508 CPUtime=0.18
/proc/23309/stat : 23309 (aptitude) R 23308 23309 17863 34816 17863 4202496 10607 1707 0 0 16 2 0 0 20 0 1 0 28901028 102920192 10407 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239415952 140728165756477 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300274 s]
/proc/loadavg: 1.21 1.08 1.01 2/55 23309
/proc/meminfo: memFree=870240/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=104484 CPUtime=0.28
/proc/23309/stat : 23309 (aptitude) R 23308 23309 17863 34816 17863 4202496 11221 1707 0 0 26 2 0 0 20 0 1 0 28901028 106991616 11013 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416344 140728172505198 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 26121 11013 9300 1052 0 2116 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 104484

[startup+0.700205 s]
/proc/loadavg: 1.21 1.08 1.01 2/55 23309
/proc/meminfo: memFree=870240/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=123288 CPUtime=0.68
/proc/23309/stat : 23309 (aptitude) R 23308 23309 17863 34816 17863 4202496 17029 1707 0 0 62 6 0 0 20 0 2 0 28901028 126246912 14303 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239420472 140728165199309 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/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.19 1.07 1.01 2/57 23314
/proc/meminfo: memFree=841960/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=132404 CPUtime=1.47
/proc/23309/stat : 23309 (aptitude) R 23308 23309 17863 34816 17863 4202496 19436 1707 0 0 141 6 0 0 20 0 2 0 28901028 135581696 16706 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239415040 140728171985234 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 33101 16706 9585 1052 0 9096 0
[pid=23309/tid=23314] ppid=23308 vsize=132404 CPUtime=0
/proc/23309/task/23314/stat : 23314 (aptitude) S 23308 23309 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 28901094 135581696 16706 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061184000 140728139100884 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 132404

[startup+3.10024 s]
/proc/loadavg: 1.19 1.07 1.01 2/57 23315
/proc/meminfo: memFree=840712/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=133912 CPUtime=3.07
/proc/23309/stat : 23309 (aptitude) R 23308 23309 17863 34816 17863 4202496 20606 2207 0 0 295 12 0 0 20 0 2 0 28901028 137125888 16943 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239411504 140728173329072 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 33478 16943 9644 1052 0 9473 0
[pid=23309/tid=23314] ppid=23308 vsize=133912 CPUtime=0
/proc/23309/task/23314/stat : 23314 (aptitude) S 23308 23309 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 28901094 137125888 16943 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061184000 140728139100884 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) 133912

[startup+6.30025 s]
/proc/loadavg: 1.19 1.07 1.01 2/57 23315
/proc/meminfo: memFree=797816/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=245284 CPUtime=6.25
/proc/23309/stat : 23309 (aptitude) S 23308 23309 17863 34816 17863 4202496 33132 2207 0 0 606 19 0 0 20 0 2 0 28901028 251170816 28657 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416448 140728139101771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 61321 28657 9700 1052 0 37316 0
[pid=23309/tid=23314] ppid=23308 vsize=245284 CPUtime=3.13
/proc/23309/task/23314/stat : 23314 (aptitude) R 23308 23309 17863 34816 17863 4202560 12525 2207 0 0 307 6 0 0 20 0 2 0 28901094 251170816 28657 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061175272 140728127857019 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) 245284

[startup+12.7003 s]
/proc/loadavg: 1.16 1.07 1.01 2/57 23315
/proc/meminfo: memFree=743752/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=299808 CPUtime=12.62
/proc/23309/stat : 23309 (aptitude) S 23308 23309 17863 34816 17863 4202496 47278 2207 0 0 1238 24 0 0 20 0 2 0 28901028 307003392 42291 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416448 140728139101771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 74952 42291 9700 1052 0 50947 0
[pid=23309/tid=23314] ppid=23308 vsize=299808 CPUtime=9.5
/proc/23309/task/23314/stat : 23314 (aptitude) R 23308 23309 17863 34816 17863 4202560 26671 2207 0 0 938 12 0 0 20 0 2 0 28901094 307003392 42291 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061177528 140728173003034 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) 299808

[startup+25.5003 s]
/proc/loadavg: 1.14 1.07 1.01 2/57 23315
/proc/meminfo: memFree=647032/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=393208 CPUtime=25.36
/proc/23309/stat : 23309 (aptitude) S 23308 23309 17863 34816 17863 4202496 70641 2207 0 0 2495 41 0 0 20 0 2 0 28901028 402644992 65584 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416448 140728139101771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 98302 65584 9700 1052 0 74297 0
[pid=23309/tid=23314] ppid=23308 vsize=393208 CPUtime=22.24
/proc/23309/task/23314/stat : 23314 (aptitude) R 23308 23309 17863 34816 17863 4202560 50034 2207 0 0 2195 29 0 0 20 0 2 0 28901094 402644992 65584 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061175320 140728172567645 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) 393208

[startup+51.1003 s]
/proc/loadavg: 1.09 1.06 1.01 2/57 23315
/proc/meminfo: memFree=471944/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=570332 CPUtime=50.84
/proc/23309/stat : 23309 (aptitude) S 23308 23309 17863 34816 17863 4202496 114959 2207 0 0 5017 67 0 0 20 0 2 0 28901028 584019968 109842 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416448 140728139101771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 142583 109842 9716 1052 0 118578 0
[pid=23309/tid=23314] ppid=23308 vsize=570332 CPUtime=47.71
/proc/23309/task/23314/stat : 23314 (aptitude) R 23308 23309 17863 34816 17863 4202560 94346 2207 0 0 4717 54 0 0 20 0 2 0 28901094 584019968 109842 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061178024 140728127938464 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.84
Current children cumulated vsize (KiB) 570332

[startup+102.3 s]
/proc/loadavg: 1.03 1.05 1.00 2/57 23315
/proc/meminfo: memFree=147560/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=891032 CPUtime=101.8
/proc/23309/stat : 23309 (aptitude) S 23308 23309 17863 34816 17863 4202496 195022 2207 0 0 10066 114 0 0 20 0 2 0 28901028 912416768 189905 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416448 140728139101771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23309/statm: 222758 189905 9716 1052 0 198753 0
[pid=23309/tid=23314] ppid=23308 vsize=891032 CPUtime=98.67
/proc/23309/task/23314/stat : 23314 (aptitude) R 23308 23309 17863 34816 17863 4202560 174409 2207 0 0 9765 102 0 0 20 0 2 0 28901094 912416768 189905 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061178024 140728127866916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 101.8
Current children cumulated vsize (KiB) 891032



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+152.1 s]
/proc/loadavg: 1.28 1.10 1.02 3/57 23315
/proc/meminfo: memFree=9988/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=1151352 CPUtime=147.56
/proc/23309/stat : 23309 (aptitude) S 23308 23309 17863 34816 17863 4202496 260983 2207 441 0 14589 167 0 0 20 0 2 0 28901028 1178984448 246656 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416448 140728139101771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/23309/statm: 287838 246656 9369 1052 0 263833 0
[pid=23309/tid=23314] ppid=23308 vsize=1151352 CPUtime=144.42
/proc/23309/task/23314/stat : 23314 (aptitude) R 23308 23309 17863 34816 17863 4202560 240361 2207 437 0 14288 154 0 0 20 0 2 0 28901094 1178984448 246640 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061175496 140728173064574 0 134217728 4096 0 0 0 0 -1 0 0 0 353 0 0
Current children cumulated CPU time (s) 147.56
Current children cumulated vsize (KiB) 1151352

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

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

[startup+152.1 s]
/proc/loadavg: 1.28 1.10 1.02 3/57 23315
/proc/meminfo: memFree=9988/1022884 swapFree=0/0
[pid=23309] ppid=23308 vsize=1151352 CPUtime=147.56
/proc/23309/stat : 23309 (aptitude) S 23308 23309 17863 34816 17863 4202496 260983 2207 441 0 14589 167 0 0 20 0 2 0 28901028 1178984448 246656 18446744073709551615 140728170356736 140728174664088 140733239424688 140733239416448 140728139101771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/23309/statm: 287838 246656 9369 1052 0 263833 0
[pid=23309/tid=23314] ppid=23308 vsize=1151352 CPUtime=144.42
/proc/23309/task/23314/stat : 23314 (aptitude) R 23308 23309 17863 34816 17863 4202560 240361 2207 437 0 14288 154 0 0 20 0 2 0 28901094 1178984448 246640 18446744073709551615 140728170356736 140728174664088 140733239424688 140728061175496 140728173064574 0 134217728 4096 0 0 0 0 -1 0 0 0 353 0 0
Current children cumulated CPU time (s) 147.56
Current children cumulated vsize (KiB) 1151352

Child ended because it received signal 15 (SIGTERM)
Real time (s): 152.232
CPU time (s): 147.661
CPU user time (s): 145.909
CPU system time (s): 1.75211
CPU usage (%): 96.9977
Max. virtual memory (cumulated for all children) (KiB): 1151352

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 145.909
system time used= 1.75211
maximum resident set size= 988436
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263202
page faults= 442
swaps= 0
block input operations= 16832
block output operations= 72
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 850
involuntary context switches= 3194

runsolver used 0.228014 second user time and 0.48403 second system time

The end