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-sid/logs/81.runsolver.aptitude aptitude -s -y --without-recommends install tinyca pike7.4-pexts-bzip2 libpam0g xbel-utils pydb 

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.36 1.12 1.07 2/55 26173
/proc/meminfo: memFree=959976/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=3152 CPUtime=0
/proc/26173/stat : 26173 (runsolver) R 26172 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29749515 3227648 32 18446744073709551615 134512640 134586868 4290952192 4290950240 4151845936 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26173/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.17894 s]
/proc/loadavg: 1.36 1.12 1.07 2/55 26173
/proc/meminfo: memFree=959976/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=33024 CPUtime=0
/proc/26173/stat : 26173 (aptitude) D 26172 26173 17863 34816 17863 4202496 157 0 18 0 0 0 0 0 20 0 1 0 29749515 33816576 86 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785284824 139763447227939 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/26173/statm: 8256 86 55 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 33024

[startup+0.200369 s]
/proc/loadavg: 1.36 1.12 1.07 2/55 26173
/proc/meminfo: memFree=959976/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=33024 CPUtime=0
/proc/26173/stat : 26173 (aptitude) D 26172 26173 17863 34816 17863 4202496 161 0 19 0 0 0 0 0 20 0 1 0 29749515 33816576 90 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785285464 139763447222839 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/26173/statm: 8256 90 57 1052 0 38 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 33024

[startup+0.30037 s]
/proc/loadavg: 1.36 1.12 1.07 2/55 26173
/proc/meminfo: memFree=959976/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=54836 CPUtime=0
/proc/26173/stat : 26173 (aptitude) D 26172 26173 17863 34816 17863 4202496 792 0 32 0 0 0 0 0 20 0 1 0 29749515 56152064 718 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785288008 139763406602368 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/26173/statm: 13709 718 582 1052 0 73 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54836

[startup+0.700307 s]
/proc/loadavg: 1.36 1.12 1.07 2/55 26173
/proc/meminfo: memFree=959976/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=103288 CPUtime=0.02
/proc/26173/stat : 26173 (aptitude) D 26172 26173 17863 34816 17863 4202496 2463 1706 67 4 1 1 0 0 20 0 1 0 29749515 105766912 2331 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785279872 139763444418458 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/26173/statm: 25822 2331 1118 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.50035 s]
/proc/loadavg: 1.36 1.12 1.07 2/56 26177
/proc/meminfo: memFree=949800/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=103288 CPUtime=0.03
/proc/26173/stat : 26173 (aptitude) D 26172 26173 17863 34816 17863 4202496 6509 1706 201 4 1 2 0 0 20 0 1 0 29749515 105766912 6511 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785279872 139763444216088 0 134217728 4096 0 0 0 0 17 0 0 0 140 0 0
/proc/26173/statm: 25822 6511 5298 1052 0 1159 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 103288

[startup+3.1002 s]
/proc/loadavg: 1.36 1.12 1.07 2/56 26177
/proc/meminfo: memFree=948436/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=123068 CPUtime=0.65
/proc/26173/stat : 26173 (aptitude) R 26172 26173 17863 34816 17863 4202496 17403 1706 282 4 54 11 0 0 20 0 1 0 29749515 126021632 15962 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785277832 139763406908959 0 134217728 4096 0 0 0 0 17 0 0 0 240 0 0
/proc/26173/statm: 30767 15962 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.65
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30025 s]
/proc/loadavg: 1.41 1.13 1.08 2/57 26179
/proc/meminfo: memFree=800488/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=137820 CPUtime=3.34
/proc/26173/stat : 26173 (aptitude) R 26172 26173 17863 34816 17863 4202496 21704 2202 289 6 311 22 0 1 20 0 2 0 29749515 141127680 17932 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785275104 139763406879097 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 287 0 0
/proc/26173/statm: 34455 17932 10303 1052 0 9792 0
[pid=26173/tid=26178] ppid=26172 vsize=137820 CPUtime=0.01
/proc/26173/task/26178/stat : 26178 (aptitude) S 26172 26173 17863 34816 17863 4202560 5 2202 1 6 0 0 0 1 20 0 2 0 29749885 141127680 17932 18446744073709551615 139763449368576 139763453675928 140733785288400 139763337046016 139763418112724 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 3.34
Current children cumulated vsize (KiB) 137820
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.38 1.13 1.08 2/57 26179
/proc/meminfo: memFree=730684/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=277340 CPUtime=9.71
/proc/26173/stat : 26173 (aptitude) S 26172 26173 17863 34816 17863 4202496 41035 2202 289 6 940 30 0 1 20 0 2 0 29749515 283996160 36657 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785280160 139763418113611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 287 0 0
/proc/26173/statm: 69335 36657 10359 1052 0 44672 0
[pid=26173/tid=26178] ppid=26172 vsize=277340 CPUtime=6.2
/proc/26173/task/26178/stat : 26178 (aptitude) R 26172 26173 17863 34816 17863 4202560 19329 2202 1 6 612 7 0 1 20 0 2 0 29749885 283996160 36657 18446744073709551615 139763449368576 139763453675928 140733785288400 139763337037336 139763406878816 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 9.71
Current children cumulated vsize (KiB) 277340
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.29 1.12 1.07 2/57 26179
/proc/meminfo: memFree=642520/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=361032 CPUtime=22.45
/proc/26173/stat : 26173 (aptitude) S 26172 26173 17863 34816 17863 4202496 62322 2202 289 6 2204 40 0 1 20 0 2 0 29749515 369696768 57578 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785280160 139763418113611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 287 0 0
/proc/26173/statm: 90258 57578 10360 1052 0 65595 0
[pid=26173/tid=26178] ppid=26172 vsize=361032 CPUtime=18.93
/proc/26173/task/26178/stat : 26178 (aptitude) R 26172 26173 17863 34816 17863 4202560 40616 2202 1 6 1875 17 0 1 20 0 2 0 29749885 369696768 57578 18446744073709551615 139763449368576 139763453675928 140733785288400 139763337037336 139763451998988 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 22.45
Current children cumulated vsize (KiB) 361032

[startup+51.1003 s]
/proc/loadavg: 1.19 1.11 1.07 2/57 26179
/proc/meminfo: memFree=523356/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=480652 CPUtime=47.93
/proc/26173/stat : 26173 (aptitude) S 26172 26173 17863 34816 17863 4202496 92300 2202 289 6 4736 56 0 1 20 0 2 0 29749515 492187648 87480 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785280160 139763418113611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 287 0 0
/proc/26173/statm: 120163 87480 10360 1052 0 95500 0
[pid=26173/tid=26178] ppid=26172 vsize=480652 CPUtime=44.41
/proc/26173/task/26178/stat : 26178 (aptitude) R 26172 26173 17863 34816 17863 4202560 70594 2202 1 6 4407 33 0 1 20 0 2 0 29749885 492187648 87480 18446744073709551615 139763449368576 139763453675928 140733785288400 139763337037336 139763407520960 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 47.93
Current children cumulated vsize (KiB) 480652

[startup+102.3 s]
/proc/loadavg: 1.13 1.11 1.07 2/57 26179
/proc/meminfo: memFree=256632/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=744528 CPUtime=98.87
/proc/26173/stat : 26173 (aptitude) S 26172 26173 17863 34816 17863 4202496 158689 2202 294 6 9790 96 0 1 20 0 2 0 29749515 762396672 153422 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785280160 139763418113611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 287 0 0
/proc/26173/statm: 186132 153422 10374 1052 0 161469 0
[pid=26173/tid=26178] ppid=26172 vsize=744528 CPUtime=95.35
/proc/26173/task/26178/stat : 26178 (aptitude) R 26172 26173 17863 34816 17863 4202560 136979 2202 4 6 9460 74 0 1 20 0 2 0 29749885 762396672 153422 18446744073709551615 139763449368576 139763453675928 140733785288400 139763337040152 139763451579485 0 134217728 4096 0 0 0 0 -1 0 0 0 4 0 0
Current children cumulated CPU time (s) 98.87
Current children cumulated vsize (KiB) 744528



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+158.3 s]
/proc/loadavg: 1.17 1.12 1.08 2/57 26179
/proc/meminfo: memFree=10152/1022884 swapFree=0/0
[pid=26173] ppid=26172 vsize=1151068 CPUtime=153.35
/proc/26173/stat : 26173 (aptitude) S 26172 26173 17863 34816 17863 4202496 260393 2202 355 6 15186 148 0 1 20 0 2 0 29749515 1178693632 244457 18446744073709551615 139763449368576 139763453675928 140733785288400 140733785280160 139763418113611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 287 0 0
/proc/26173/statm: 287767 244457 10369 1052 0 263104 0
[pid=26173/tid=26178] ppid=26172 vsize=1151068 CPUtime=149.82
/proc/26173/task/26178/stat : 26178 (aptitude) R 26172 26173 17863 34816 17863 4202560 238671 2202 62 6 14856 125 0 1 20 0 2 0 29749885 1178693632 244457 18446744073709551615 139763449368576 139763453675928 140733785288400 139763337037512 139763452001498 0 134217728 4096 0 0 0 0 -1 0 0 0 88 0 0
Current children cumulated CPU time (s) 153.35
Current children cumulated vsize (KiB) 1151068

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): 158.405
CPU time (s): 153.454
CPU user time (s): 151.893
CPU system time (s): 1.5601
CPU usage (%): 96.8745
Max. virtual memory (cumulated for all children) (KiB): 1151068

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 151.893
system time used= 1.5601
maximum resident set size= 981496
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262629
page faults= 361
swaps= 0
block input operations= 261808
block output operations= 88
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2909
involuntary context switches= 3370

runsolver used 0.188011 second user time and 0.552034 second system time

The end