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/62.runsolver.aptitude aptitude -s -y --without-recommends install kernel-image-2.4.27-speakup drupal jftpgw libvibrant6 records-common 

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.08 1.06 1.01 2/55 23685
/proc/meminfo: memFree=869320/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=54860 CPUtime=0
/proc/23685/stat : 23685 (aptitude) R 23684 23685 17863 34816 17863 4202496 585 0 0 0 0 0 0 0 20 0 1 0 28977372 56176640 485 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745275688 139736743061382 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 13715 485 398 1052 0 73 0

[startup+0.175438 s]
/proc/loadavg: 1.08 1.06 1.01 2/55 23685
/proc/meminfo: memFree=869320/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=100508 CPUtime=0.16
/proc/23685/stat : 23685 (aptitude) R 23684 23685 17863 34816 17863 4202496 10600 1709 0 0 14 2 0 0 20 0 1 0 28977372 102920192 10399 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745267744 139736740099659 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 25127 10399 9225 1052 0 1122 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 100508

[startup+0.200285 s]
/proc/loadavg: 1.08 1.06 1.01 2/55 23685
/proc/meminfo: memFree=869320/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=100508 CPUtime=0.18
/proc/23685/stat : 23685 (aptitude) R 23684 23685 17863 34816 17863 4202496 10607 1709 0 0 16 2 0 0 20 0 1 0 28977372 102920192 10406 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745267744 139736740102685 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 25127 10406 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300266 s]
/proc/loadavg: 1.08 1.06 1.01 2/55 23685
/proc/meminfo: memFree=869320/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=111108 CPUtime=0.28
/proc/23685/stat : 23685 (aptitude) R 23684 23685 17863 34816 17863 4202496 12094 1709 0 0 26 2 0 0 20 0 1 0 28977372 113774592 11885 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745268072 139736747390547 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 27777 11885 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700201 s]
/proc/loadavg: 1.08 1.06 1.01 2/55 23685
/proc/meminfo: memFree=869320/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=123288 CPUtime=0.68
/proc/23685/stat : 23685 (aptitude) R 23684 23685 17863 34816 17863 4202496 17029 1709 0 0 62 6 0 0 20 0 2 0 28977372 126246912 14302 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745272264 139736702840512 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 30822 14302 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.08 1.06 1.01 2/57 23690
/proc/meminfo: memFree=841164/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=132424 CPUtime=1.48
/proc/23685/stat : 23685 (aptitude) R 23684 23685 17863 34816 17863 4202496 19441 1709 0 0 141 7 0 0 20 0 2 0 28977372 135602176 16710 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745266832 139736746887095 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 33106 16710 9585 1052 0 9101 0
[pid=23685/tid=23690] ppid=23684 vsize=132424 CPUtime=0
/proc/23685/task/23690/stat : 23690 (aptitude) S 23684 23685 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 28977438 135602176 16710 18446744073709551615 139736745259008 139736749566360 140736745276480 139736636086272 139736714003156 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.08 1.06 1.01 2/58 23691
/proc/meminfo: memFree=840164/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=133832 CPUtime=3.07
/proc/23685/stat : 23685 (aptitude) R 23684 23685 17863 34816 17863 4202496 20629 2206 0 0 296 11 0 0 20 0 2 0 28977372 137043968 16953 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745263184 139736702769188 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 33458 16953 9644 1052 0 9453 0
[pid=23685/tid=23690] ppid=23684 vsize=133832 CPUtime=0
/proc/23685/task/23690/stat : 23690 (aptitude) S 23684 23685 17863 34816 17863 4202560 6 2206 0 0 0 0 0 0 20 0 2 0 28977438 137043968 16953 18446744073709551615 139736745259008 139736749566360 140736745276480 139736636086272 139736714003156 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) 133832

[startup+6.30024 s]
/proc/loadavg: 1.08 1.06 1.01 2/57 23691
/proc/meminfo: memFree=796764/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=245452 CPUtime=6.25
/proc/23685/stat : 23685 (aptitude) S 23684 23685 17863 34816 17863 4202496 33122 2206 0 0 609 16 0 0 20 0 2 0 28977372 251342848 28700 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745268240 139736714004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 61363 28700 9700 1052 0 37358 0
[pid=23685/tid=23690] ppid=23684 vsize=245452 CPUtime=3.12
/proc/23685/task/23690/stat : 23690 (aptitude) R 23684 23685 17863 34816 17863 4202560 12492 2206 0 0 308 4 0 0 20 0 2 0 28977438 251342848 28700 18446744073709551615 139736745259008 139736749566360 140736745276480 139736636077592 139736747855696 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) 245452

[startup+12.7002 s]
/proc/loadavg: 1.07 1.06 1.01 2/57 23691
/proc/meminfo: memFree=742204/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=300772 CPUtime=12.62
/proc/23685/stat : 23685 (aptitude) S 23684 23685 17863 34816 17863 4202496 47492 2206 0 0 1238 24 0 0 20 0 2 0 28977372 307990528 42532 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745268240 139736714004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 75193 42532 9700 1052 0 51188 0
[pid=23685/tid=23690] ppid=23684 vsize=300772 CPUtime=9.5
/proc/23685/task/23690/stat : 23690 (aptitude) R 23684 23685 17863 34816 17863 4202560 26862 2206 0 0 938 12 0 0 20 0 2 0 28977438 307990528 42532 18446744073709551615 139736745259008 139736749566360 140736745276480 139736636077592 139736740082809 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) 300772

[startup+25.5003 s]
/proc/loadavg: 1.05 1.06 1.01 2/57 23691
/proc/meminfo: memFree=639532/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=399704 CPUtime=25.36
/proc/23685/stat : 23685 (aptitude) S 23684 23685 17863 34816 17863 4202496 72259 2206 0 0 2500 36 0 0 20 0 2 0 28977372 409296896 67226 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745268240 139736714004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 99926 67226 9700 1052 0 75921 0
[pid=23685/tid=23690] ppid=23684 vsize=399704 CPUtime=22.24
/proc/23685/task/23690/stat : 23690 (aptitude) R 23684 23685 17863 34816 17863 4202560 51629 2206 0 0 2199 25 0 0 20 0 2 0 28977438 409296896 67226 18446744073709551615 139736745259008 139736749566360 140736745276480 139736636080520 139736747872688 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) 399704

[startup+51.1003 s]
/proc/loadavg: 1.03 1.05 1.00 2/57 23691
/proc/meminfo: memFree=415836/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=627864 CPUtime=50.85
/proc/23685/stat : 23685 (aptitude) S 23684 23685 17863 34816 17863 4202496 129325 2206 0 0 5021 64 0 0 20 0 2 0 28977372 642932736 124222 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745268240 139736714004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 156966 124222 9716 1052 0 132961 0
[pid=23685/tid=23690] ppid=23684 vsize=627864 CPUtime=47.72
/proc/23685/task/23690/stat : 23690 (aptitude) R 23684 23685 17863 34816 17863 4202560 108689 2206 0 0 4720 52 0 0 20 0 2 0 28977438 642932736 124222 18446744073709551615 139736745259008 139736749566360 140736745276480 139736636077944 139736748061652 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) 627864



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+98.9002 s]
/proc/loadavg: 1.23 1.09 1.02 2/57 23699
/proc/meminfo: memFree=9644/1022884 swapFree=0/0
[pid=23685] ppid=23684 vsize=1151300 CPUtime=95.76
/proc/23685/stat : 23685 (aptitude) S 23684 23685 17863 34816 17863 4202496 260552 2206 355 0 9431 145 0 0 20 0 2 0 28977372 1178931200 245573 18446744073709551615 139736745259008 139736749566360 140736745276480 140736745268240 139736714004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23685/statm: 287825 245573 8901 1052 0 263820 0
[pid=23685/tid=23690] ppid=23684 vsize=1151300 CPUtime=92.62
/proc/23685/task/23690/stat : 23690 (aptitude) R 23684 23685 17863 34816 17863 4202560 239905 2206 350 0 9129 133 0 0 20 0 2 0 28977438 1178931200 245573 18446744073709551615 139736745259008 139736749566360 140736745276480 139736636078088 139736711184752 0 134217728 4096 0 0 0 0 -1 0 0 0 237 0 0
Current children cumulated CPU time (s) 95.76
Current children cumulated vsize (KiB) 1151300

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): 99.0271
CPU time (s): 95.898
CPU user time (s): 94.3619
CPU system time (s): 1.5361
CPU usage (%): 96.8401
Max. virtual memory (cumulated for all children) (KiB): 1151300

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 94.3619
system time used= 1.5361
maximum resident set size= 985568
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262845
page faults= 355
swaps= 0
block input operations= 13288
block output operations= 64
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 647
involuntary context switches= 2380

runsolver used 0.104006 second user time and 0.356022 second system time

The end