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/15.runsolver.aptitude aptitude -s -y --without-recommends install gql-shell libarchive-tar-perl harden-servers xara-gtk-byte libgnome2-doc 

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.05 1.06 1.02 2/55 23028
/proc/meminfo: memFree=869768/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=54860 CPUtime=0
/proc/23028/stat : 23028 (aptitude) R 23027 23028 17863 34816 17863 4202496 587 0 0 0 0 0 0 0 20 0 1 0 28778312 56176640 487 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250982344 140123625031558 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 13715 487 399 1052 0 73 0

[startup+0.177352 s]
/proc/loadavg: 1.05 1.06 1.02 2/55 23028
/proc/meminfo: memFree=869768/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=100508 CPUtime=0.16
/proc/23028/stat : 23028 (aptitude) R 23027 23028 17863 34816 17863 4202496 10599 1708 0 0 14 2 0 0 20 0 1 0 28778312 102920192 10400 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974400 140123622629371 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 25127 10400 9225 1052 0 1122 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 100508

[startup+0.200286 s]
/proc/loadavg: 1.05 1.06 1.02 2/55 23028
/proc/meminfo: memFree=869768/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=100508 CPUtime=0.19
/proc/23028/stat : 23028 (aptitude) R 23027 23028 17863 34816 17863 4202496 10606 1708 0 0 17 2 0 0 20 0 1 0 28778312 102920192 10407 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974400 140123622070077 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 100508

[startup+0.300261 s]
/proc/loadavg: 1.05 1.06 1.02 2/55 23028
/proc/meminfo: memFree=869768/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=104484 CPUtime=0.28
/proc/23028/stat : 23028 (aptitude) R 23027 23028 17863 34816 17863 4202496 11336 1708 0 0 26 2 0 0 20 0 1 0 28778312 106991616 11129 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974792 140123629377621 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 26121 11129 9300 1052 0 2116 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 104484

[startup+0.700202 s]
/proc/loadavg: 1.05 1.06 1.02 2/55 23028
/proc/meminfo: memFree=869768/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=123288 CPUtime=0.68
/proc/23028/stat : 23028 (aptitude) R 23027 23028 17863 34816 17863 4202496 17029 1708 0 0 62 6 0 0 20 0 2 0 28778312 126246912 14303 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250978920 140123622071776 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50023 s]
/proc/loadavg: 1.05 1.06 1.02 2/57 23033
/proc/meminfo: memFree=841612/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=132404 CPUtime=1.47
/proc/23028/stat : 23028 (aptitude) R 23027 23028 17863 34816 17863 4202496 19437 1708 0 0 140 7 0 0 20 0 2 0 28778312 135581696 16707 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250973488 140123584739655 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 33101 16707 9585 1052 0 9096 0
[pid=23028/tid=23033] ppid=23027 vsize=132404 CPUtime=0
/proc/23028/task/23033/stat : 23033 (aptitude) S 23027 23028 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 28778378 135581696 16707 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518056448 140123595973332 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.10025 s]
/proc/loadavg: 1.05 1.06 1.02 2/57 23033
/proc/meminfo: memFree=840612/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=133908 CPUtime=3.08
/proc/23028/stat : 23028 (aptitude) R 23027 23028 17863 34816 17863 4202496 20618 2210 0 0 294 13 0 1 20 0 2 0 28778312 137121792 16947 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250969840 140123628865346 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 33477 16947 9644 1052 0 9472 0
[pid=23028/tid=23033] ppid=23027 vsize=133908 CPUtime=0.01
/proc/23028/task/23033/stat : 23033 (aptitude) S 23027 23028 17863 34816 17863 4202560 6 2210 0 0 0 0 0 1 20 0 2 0 28778378 137121792 16947 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518056448 140123595973332 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 133908

[startup+6.30025 s]
/proc/loadavg: 1.05 1.06 1.02 2/57 23034
/proc/meminfo: memFree=797468/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=245392 CPUtime=6.26
/proc/23028/stat : 23028 (aptitude) S 23027 23028 17863 34816 17863 4202496 33126 2210 0 0 608 17 0 1 20 0 2 0 28778312 251281408 28683 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974896 140123595974219 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 61348 28683 9700 1052 0 37343 0
[pid=23028/tid=23033] ppid=23027 vsize=245392 CPUtime=3.12
/proc/23028/task/23033/stat : 23033 (aptitude) R 23027 23028 17863 34816 17863 4202560 12507 2210 0 0 307 4 0 1 20 0 2 0 28778378 251281408 28683 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518050104 140123622629669 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 245392

[startup+12.7002 s]
/proc/loadavg: 1.04 1.06 1.01 2/57 23034
/proc/meminfo: memFree=754812/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=297984 CPUtime=12.63
/proc/23028/stat : 23028 (aptitude) S 23027 23028 17863 34816 17863 4202496 46835 2210 0 0 1240 22 0 1 20 0 2 0 28778312 305135616 41829 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974896 140123595974219 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 74496 41829 9701 1052 0 50491 0
[pid=23028/tid=23033] ppid=23027 vsize=297984 CPUtime=9.49
/proc/23028/task/23033/stat : 23033 (aptitude) R 23027 23028 17863 34816 17863 4202560 26216 2210 0 0 939 9 0 1 20 0 2 0 28778378 305135616 41829 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518053096 140123629989193 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 297984

[startup+25.5002 s]
/proc/loadavg: 1.03 1.06 1.01 2/57 23034
/proc/meminfo: memFree=650528/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=388900 CPUtime=25.37
/proc/23028/stat : 23028 (aptitude) S 23027 23028 17863 34816 17863 4202496 69593 2210 0 0 2502 34 0 1 20 0 2 0 28778312 398233600 64524 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974896 140123595974219 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 97225 64524 9701 1052 0 73220 0
[pid=23028/tid=23033] ppid=23027 vsize=388900 CPUtime=22.22
/proc/23028/task/23033/stat : 23033 (aptitude) R 23027 23028 17863 34816 17863 4202560 48974 2210 0 0 2200 21 0 1 20 0 2 0 28778378 398233600 64524 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518049976 140123622133936 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 388900

[startup+51.1003 s]
/proc/loadavg: 1.02 1.05 1.01 2/57 23034
/proc/meminfo: memFree=500612/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=539716 CPUtime=50.85
/proc/23028/stat : 23028 (aptitude) S 23027 23028 17863 34816 17863 4202496 107311 2210 0 0 5032 52 0 1 20 0 2 0 28778312 552669184 102174 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974896 140123595974219 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 134929 102174 9715 1052 0 110924 0
[pid=23028/tid=23033] ppid=23027 vsize=539716 CPUtime=47.71
/proc/23028/task/23033/stat : 23033 (aptitude) R 23027 23028 17863 34816 17863 4202560 86686 2210 0 0 4731 39 0 1 20 0 2 0 28778378 552669184 102174 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518050104 140123629937261 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) 539716

[startup+102.3 s]
/proc/loadavg: 1.01 1.04 1.01 2/57 23034
/proc/meminfo: memFree=18252/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=1019068 CPUtime=101.8
/proc/23028/stat : 23028 (aptitude) S 23027 23028 17863 34816 17863 4202496 227102 2210 0 0 10071 108 0 1 20 0 2 0 28778312 1043525632 221961 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974896 140123595974219 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 254767 221961 9716 1052 0 230762 0
[pid=23028/tid=23033] ppid=23027 vsize=1019068 CPUtime=98.65
/proc/23028/task/23033/stat : 23033 (aptitude) R 23027 23028 17863 34816 17863 4202560 206477 2210 0 0 9769 95 0 1 20 0 2 0 28778378 1043525632 221961 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518050584 140123593162392 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 101.8
Current children cumulated vsize (KiB) 1019068



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+116.3 s]
/proc/loadavg: 1.16 1.07 1.02 2/57 23034
/proc/meminfo: memFree=8184/1022884 swapFree=0/0
[pid=23028] ppid=23027 vsize=1152256 CPUtime=114.16
/proc/23028/stat : 23028 (aptitude) S 23027 23028 17863 34816 17863 4202496 260488 2210 132 0 11279 136 0 1 20 0 2 0 28778312 1179910144 247114 18446744073709551615 140123627229184 140123631536536 140736250983136 140736250974896 140123595974219 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23028/statm: 288064 247114 9050 1052 0 264059 0
[pid=23028/tid=23033] ppid=23027 vsize=1152256 CPUtime=111.02
/proc/23028/task/23033/stat : 23033 (aptitude) R 23027 23028 17863 34816 17863 4202560 239855 2210 127 0 10978 123 0 1 20 0 2 0 28778378 1179910144 247114 18446744073709551615 140123627229184 140123631536536 140736250983136 140123518049880 140123629870949 0 134217728 4096 0 0 0 0 -1 0 0 0 130 0 0
Current children cumulated CPU time (s) 114.16
Current children cumulated vsize (KiB) 1152256

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): 116.409
CPU time (s): 114.275
CPU user time (s): 112.839
CPU system time (s): 1.43609
CPU usage (%): 98.1668
Max. virtual memory (cumulated for all children) (KiB): 1152256

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 112.839
system time used= 1.43609
maximum resident set size= 988772
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262777
page faults= 132
swaps= 0
block input operations= 5216
block output operations= 112
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 462
involuntary context switches= 2522

runsolver used 0.196012 second user time and 0.352022 second system time

The end