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/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.00 1.03 0.99 2/55 21802 /proc/meminfo: memFree=907464/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=3152 CPUtime=0 /proc/21802/stat : 21802 (runsolver) R 21801 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28563065 3227648 32 18446744073709551615 134512640 134586868 4290510192 4290508240 4151374896 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.15052 s] /proc/loadavg: 1.00 1.03 0.99 2/55 21802 /proc/meminfo: memFree=907464/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=89152 CPUtime=0.13 /proc/21802/stat : 21802 (aptitude) R 21801 21802 17863 34816 17863 4202496 7775 1708 0 0 11 2 0 0 20 0 1 0 28563065 91291648 7573 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031671936 140228260102801 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 22288 7573 6663 1052 0 858 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 89152 [startup+0.200289 s] /proc/loadavg: 1.00 1.03 0.99 2/55 21802 /proc/meminfo: memFree=907464/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=89152 CPUtime=0.18 /proc/21802/stat : 21802 (aptitude) R 21801 21802 17863 34816 17863 4202496 7871 1708 0 0 16 2 0 0 20 0 1 0 28563065 91291648 7661 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031670448 140228260113000 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 22288 7661 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 89152 [startup+0.300288 s] /proc/loadavg: 1.00 1.03 0.99 2/55 21802 /proc/meminfo: memFree=907464/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=101864 CPUtime=0.28 /proc/21802/stat : 21802 (aptitude) R 21801 21802 17863 34816 17863 4202496 11710 1708 0 0 24 4 0 0 20 0 1 0 28563065 104308736 10755 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031670104 140228222799296 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 25466 10755 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 101864 [startup+0.700211 s] /proc/loadavg: 1.00 1.03 0.99 2/55 21802 /proc/meminfo: memFree=907464/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=110244 CPUtime=0.68 /proc/21802/stat : 21802 (aptitude) R 21801 21802 17863 34816 17863 4202496 12603 1708 0 0 61 7 0 0 20 0 2 0 28563065 112889856 10975 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672712 140228222769248 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 27561 10975 6961 1052 0 6131 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 110244 [startup+1.50024 s] /proc/loadavg: 1.00 1.03 0.99 2/57 21807 /proc/meminfo: memFree=886624/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=115420 CPUtime=1.48 /proc/21802/stat : 21802 (aptitude) R 21801 21802 17863 34816 17863 4202496 14564 2206 0 0 137 10 1 0 20 0 2 0 28563065 118190080 12363 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672696 140228267460379 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 28855 12363 7073 1052 0 7425 0 [pid=21802/tid=21807] ppid=21801 vsize=115420 CPUtime=0.01 /proc/21802/task/21807/stat : 21807 (aptitude) S 21801 21802 17863 34816 17863 4202560 6 2206 0 0 0 0 1 0 20 0 2 0 28563109 118190080 12363 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168665088 140228234003156 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) 115420 [startup+3.10023 s] /proc/loadavg: 1.00 1.03 0.99 2/57 21808 /proc/meminfo: memFree=878564/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=137596 CPUtime=3.08 /proc/21802/stat : 21802 (aptitude) S 21801 21802 17863 34816 17863 4202496 21087 2206 0 0 295 12 1 0 20 0 2 0 28563065 140898304 18127 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672432 140228234004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 34399 18127 7129 1052 0 12969 0 [pid=21802/tid=21807] ppid=21801 vsize=137596 CPUtime=1.1 /proc/21802/task/21807/stat : 21807 (aptitude) R 21801 21802 17863 34816 17863 4202560 6447 2206 0 0 107 2 1 0 20 0 2 0 28563109 140898304 18127 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168656408 140228222769504 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) 137596 [startup+6.30025 s] /proc/loadavg: 1.00 1.03 0.99 2/57 21808 /proc/meminfo: memFree=833304/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=241332 CPUtime=6.26 /proc/21802/stat : 21802 (aptitude) S 21801 21802 17863 34816 17863 4202496 30612 2206 0 0 609 16 1 0 20 0 2 0 28563065 247123968 27650 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672432 140228234004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 60333 27650 7129 1052 0 38903 0 [pid=21802/tid=21807] ppid=21801 vsize=241332 CPUtime=4.29 /proc/21802/task/21807/stat : 21807 (aptitude) R 21801 21802 17863 34816 17863 4202560 15971 2206 0 0 422 6 1 0 20 0 2 0 28563109 247123968 27650 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168658664 140228268060975 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) 241332 [startup+12.7003 s] /proc/loadavg: 1.00 1.03 0.99 2/57 21808 /proc/meminfo: memFree=745636/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=324164 CPUtime=12.63 /proc/21802/stat : 21802 (aptitude) S 21801 21802 17863 34816 17863 4202496 51316 2206 0 0 1238 24 1 0 20 0 2 0 28563065 331943936 48348 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672432 140228234004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 81041 48348 7129 1052 0 59611 0 [pid=21802/tid=21807] ppid=21801 vsize=324164 CPUtime=10.65 /proc/21802/task/21807/stat : 21807 (aptitude) R 21801 21802 17863 34816 17863 4202560 36675 2206 0 0 1051 13 1 0 20 0 2 0 28563109 331943936 48348 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168653896 140228222769248 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) 324164 [startup+25.5003 s] /proc/loadavg: 1.00 1.03 0.99 2/57 21808 /proc/meminfo: memFree=663920/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=403364 CPUtime=25.37 /proc/21802/stat : 21802 (aptitude) S 21801 21802 17863 34816 17863 4202496 71129 2206 0 0 2502 34 1 0 20 0 2 0 28563065 413044736 68132 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672432 140228234004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 100841 68132 7129 1052 0 79411 0 [pid=21802/tid=21807] ppid=21801 vsize=403364 CPUtime=23.39 /proc/21802/task/21807/stat : 21807 (aptitude) R 21801 21802 17863 34816 17863 4202560 56488 2206 0 0 2315 23 1 0 20 0 2 0 28563109 413044736 68132 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168658616 140228222769197 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) 403364 [startup+51.1003 s] /proc/loadavg: 1.07 1.04 1.00 2/57 21808 /proc/meminfo: memFree=538184/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=529572 CPUtime=50.85 /proc/21802/stat : 21802 (aptitude) S 21801 21802 17863 34816 17863 4202496 102866 2206 0 0 5033 51 1 0 20 0 2 0 28563065 542281728 99641 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672432 140228234004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 132393 99641 7143 1052 0 110963 0 [pid=21802/tid=21807] ppid=21801 vsize=529572 CPUtime=48.87 /proc/21802/task/21807/stat : 21807 (aptitude) R 21801 21802 17863 34816 17863 4202560 88218 2206 0 0 4846 40 1 0 20 0 2 0 28563109 542281728 99641 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168656360 140228222769248 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) 529572 [startup+102.3 s] /proc/loadavg: 1.03 1.03 1.00 2/57 21808 /proc/meminfo: memFree=279272/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=786200 CPUtime=101.82 /proc/21802/stat : 21802 (aptitude) S 21801 21802 17863 34816 17863 4202496 166985 2206 0 0 10102 79 1 0 20 0 2 0 28563065 805068800 163705 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672432 140228234004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21802/statm: 196550 163705 7145 1052 0 175120 0 [pid=21802/tid=21807] ppid=21801 vsize=786200 CPUtime=99.84 /proc/21802/task/21807/stat : 21807 (aptitude) R 21801 21802 17863 34816 17863 4202560 152337 2206 0 0 9915 68 1 0 20 0 2 0 28563109 805068800 163705 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168656408 140228268121345 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.82 Current children cumulated vsize (KiB) 786200 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+155.1 s] /proc/loadavg: 1.44 1.14 1.03 1/57 22031 /proc/meminfo: memFree=9408/1022884 swapFree=0/0 [pid=21802] ppid=21801 vsize=1151188 CPUtime=141.57 /proc/21802/stat : 21802 (aptitude) S 21801 21802 17863 34816 17863 4202496 267704 2206 1549 0 14008 148 1 0 20 0 2 0 28563065 1178816512 227474 18446744073709551615 140228265259008 140228269566360 140734031680672 140734031672432 140228234004043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/21802/statm: 287797 227474 2008 1052 0 266367 0 [pid=21802/tid=21807] ppid=21801 vsize=1151320 CPUtime=139.58 /proc/21802/task/21807/stat : 21807 (aptitude) R 21801 21802 17863 34816 17863 4202560 253068 2206 1550 0 13820 137 1 0 20 0 2 0 28563109 1178951680 227487 18446744073709551615 140228265259008 140228269566360 140734031680672 140228168656408 140228267894604 0 134217728 4096 0 0 0 0 -1 0 0 0 977 0 0 Current children cumulated CPU time (s) 141.57 Current children cumulated vsize (KiB) 1151188 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): 155.399 CPU time (s): 141.721 CPU user time (s): 140.165 CPU system time (s): 1.5561 CPU usage (%): 91.1979 Max. virtual memory (cumulated for all children) (KiB): 1151188 getrusage(RUSAGE_CHILDREN,...) data: user time used= 140.165 system time used= 1.5561 maximum resident set size= 928392 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 270094 page faults= 1553 swaps= 0 block input operations= 100680 block output operations= 64 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1986 involuntary context switches= 8178 runsolver used 0.136008 second user time and 0.588036 second system time The end