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/65.runsolver.aptitude aptitude -s -y --without-recommends install wordtrans-web fireflier-client-kde libnss-lwres asterisk-dev phpgroupware-nntp 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.21 1.10 1.05 2/55 25797 /proc/meminfo: memFree=832388/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=3152 CPUtime=0 /proc/25797/stat : 25797 (runsolver) R 25796 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29630807 3227648 33 18446744073709551615 134512640 134586868 4292959920 4292957968 4151579696 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.169715 s] /proc/loadavg: 1.21 1.10 1.05 2/55 25797 /proc/meminfo: memFree=832388/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=103288 CPUtime=0.15 /proc/25797/stat : 25797 (aptitude) R 25796 25797 17863 34816 17863 4202496 11289 1709 0 0 13 2 0 0 20 0 1 0 29630807 105766912 11091 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477353600 139770256441574 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 25822 11091 9879 1052 0 1159 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 103288 [startup+0.200287 s] /proc/loadavg: 1.21 1.10 1.05 2/55 25797 /proc/meminfo: memFree=832388/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=103288 CPUtime=0.19 /proc/25797/stat : 25797 (aptitude) R 25796 25797 17863 34816 17863 4202496 11299 1709 0 0 16 3 0 0 20 0 1 0 29630807 105766912 11101 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477353600 139770256438760 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 25822 11101 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 103288 [startup+0.300264 s] /proc/loadavg: 1.21 1.10 1.05 2/55 25797 /proc/meminfo: memFree=832388/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=103432 CPUtime=0.29 /proc/25797/stat : 25797 (aptitude) R 25796 25797 17863 34816 17863 4202496 11426 1709 0 0 26 3 0 0 20 0 1 0 29630807 105914368 11220 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477352112 139770256451554 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 25858 11220 9956 1052 0 1195 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 103432 [startup+0.700205 s] /proc/loadavg: 1.21 1.10 1.05 2/55 25797 /proc/meminfo: memFree=832388/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=123068 CPUtime=0.68 /proc/25797/stat : 25797 (aptitude) R 25796 25797 17863 34816 17863 4202496 17687 1709 0 0 62 6 0 0 20 0 1 0 29630807 126021632 15965 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477351768 139770256498828 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 30767 15965 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123068 [startup+1.50031 s] /proc/loadavg: 1.21 1.10 1.05 2/57 25802 /proc/meminfo: memFree=812416/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=136108 CPUtime=1.48 /proc/25797/stat : 25797 (aptitude) R 25796 25797 17863 34816 17863 4202496 20655 1709 0 0 141 7 0 0 20 0 2 0 29630807 139374592 17574 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477353608 139770256320968 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 34027 17574 10207 1052 0 9364 0 [pid=25797/tid=25802] ppid=25796 vsize=136108 CPUtime=0 /proc/25797/task/25802/stat : 25802 (aptitude) S 25796 25797 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29630884 139374592 17574 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149275648 139770230342356 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) 136108 [startup+3.10024 s] /proc/loadavg: 1.21 1.10 1.05 2/57 25802 /proc/meminfo: memFree=802124/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=137888 CPUtime=3.07 /proc/25797/stat : 25797 (aptitude) R 25796 25797 17863 34816 17863 4202496 22028 2207 0 0 291 16 0 0 20 0 2 0 29630807 141197312 17966 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477349040 139770230333873 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 34472 17966 10303 1052 0 9809 0 [pid=25797/tid=25802] ppid=25796 vsize=137888 CPUtime=0 /proc/25797/task/25802/stat : 25802 (aptitude) S 25796 25797 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 29630884 141197312 17966 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149275648 139770230342356 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) 137888 [startup+6.30024 s] /proc/loadavg: 1.19 1.10 1.05 2/57 25803 /proc/meminfo: memFree=778564/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=231176 CPUtime=6.25 /proc/25797/stat : 25797 (aptitude) S 25796 25797 17863 34816 17863 4202496 29458 2207 0 0 607 18 0 0 20 0 2 0 29630807 236724224 25136 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477354096 139770230343243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 57794 25136 10358 1052 0 33131 0 [pid=25797/tid=25802] ppid=25796 vsize=231176 CPUtime=2.79 /proc/25797/task/25802/stat : 25802 (aptitude) R 25796 25797 17863 34816 17863 4202560 7423 2207 0 0 277 2 0 0 20 0 2 0 29630884 236724224 25136 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149269304 139770264340794 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) 231176 [startup+12.7002 s] /proc/loadavg: 1.17 1.09 1.05 2/57 25803 /proc/meminfo: memFree=728096/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=280180 CPUtime=12.62 /proc/25797/stat : 25797 (aptitude) S 25796 25797 17863 34816 17863 4202496 41876 2207 0 0 1235 27 0 0 20 0 2 0 29630807 286904320 37380 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477354096 139770230343243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 70045 37380 10359 1052 0 45382 0 [pid=25797/tid=25802] ppid=25796 vsize=280180 CPUtime=9.16 /proc/25797/task/25802/stat : 25802 (aptitude) R 25796 25797 17863 34816 17863 4202560 19841 2207 0 0 905 11 0 0 20 0 2 0 29630884 286904320 37380 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149269304 139770263799528 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) 280180 [startup+25.5003 s] /proc/loadavg: 1.13 1.09 1.04 2/57 25803 /proc/meminfo: memFree=621704/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=383748 CPUtime=25.36 /proc/25797/stat : 25797 (aptitude) S 25796 25797 17863 34816 17863 4202496 68004 2207 0 0 2495 41 0 0 20 0 2 0 29630807 392957952 63239 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477354096 139770230343243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 95937 63239 10359 1052 0 71274 0 [pid=25797/tid=25802] ppid=25796 vsize=383748 CPUtime=21.9 /proc/25797/task/25802/stat : 25802 (aptitude) R 25796 25797 17863 34816 17863 4202560 45969 2207 0 0 2165 25 0 0 20 0 2 0 29630884 392957952 63239 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149266968 139770263809117 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) 383748 [startup+51.1003 s] /proc/loadavg: 1.09 1.08 1.04 2/57 25803 /proc/meminfo: memFree=438432/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=568532 CPUtime=50.84 /proc/25797/stat : 25797 (aptitude) S 25796 25797 17863 34816 17863 4202496 114209 2207 0 0 5020 64 0 0 20 0 2 0 29630807 582176768 109393 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477354096 139770230343243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 142133 109393 10373 1052 0 117470 0 [pid=25797/tid=25802] ppid=25796 vsize=568532 CPUtime=47.38 /proc/25797/task/25802/stat : 25802 (aptitude) R 25796 25797 17863 34816 17863 4202560 92167 2207 0 0 4690 48 0 0 20 0 2 0 29630884 582176768 109393 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149267048 139770264244529 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) 568532 [startup+102.3 s] /proc/loadavg: 1.04 1.07 1.04 2/57 25803 /proc/meminfo: memFree=129920/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=873312 CPUtime=101.81 /proc/25797/stat : 25797 (aptitude) S 25796 25797 17863 34816 17863 4202496 190967 2207 0 0 10075 106 0 0 20 0 2 0 29630807 894271488 185480 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477354096 139770230343243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 218328 185480 10374 1052 0 193665 0 [pid=25797/tid=25802] ppid=25796 vsize=873312 CPUtime=98.35 /proc/25797/task/25802/stat : 25802 (aptitude) R 25796 25797 17863 34816 17863 4202560 168925 2207 0 0 9745 90 0 0 20 0 2 0 29630884 894271488 185480 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149267048 139770264160316 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.81 Current children cumulated vsize (KiB) 873312 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+151.8 s] /proc/loadavg: 1.25 1.12 1.05 2/57 25803 /proc/meminfo: memFree=8964/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=1151596 CPUtime=149.27 /proc/25797/stat : 25797 (aptitude) S 25796 25797 17863 34816 17863 4202496 260725 2207 138 0 14783 144 0 0 20 0 2 0 29630807 1179234304 246504 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477354096 139770230343243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 287899 246504 10241 1052 0 263236 0 [pid=25797/tid=25802] ppid=25796 vsize=1151596 CPUtime=145.8 /proc/25797/task/25802/stat : 25802 (aptitude) R 25796 25797 17863 34816 17863 4202560 238683 2207 138 0 14452 128 0 0 20 0 2 0 29630884 1179234304 246504 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149266968 139770230339142 0 134217728 4096 0 0 0 0 -1 0 0 0 148 0 0 Current children cumulated CPU time (s) 149.27 Current children cumulated vsize (KiB) 1151596 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+151.8 s] /proc/loadavg: 1.25 1.12 1.05 2/57 25803 /proc/meminfo: memFree=8964/1022884 swapFree=0/0 [pid=25797] ppid=25796 vsize=1151596 CPUtime=149.27 /proc/25797/stat : 25797 (aptitude) S 25796 25797 17863 34816 17863 4202496 260725 2207 138 0 14783 144 0 0 20 0 2 0 29630807 1179234304 246504 18446744073709551615 139770261598208 139770265905560 140733477362336 140733477354096 139770230343243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25797/statm: 287899 246504 10241 1052 0 263236 0 [pid=25797/tid=25802] ppid=25796 vsize=1151596 CPUtime=145.8 /proc/25797/task/25802/stat : 25802 (aptitude) R 25796 25797 17863 34816 17863 4202560 238683 2207 138 0 14452 128 0 0 20 0 2 0 29630884 1179234304 246504 18446744073709551615 139770261598208 139770265905560 140733477362336 139770149266968 139770230339142 0 134217728 4096 0 0 0 0 -1 0 0 0 148 0 0 Current children cumulated CPU time (s) 149.27 Current children cumulated vsize (KiB) 1151596 Child ended because it received signal 15 (SIGTERM) Real time (s): 151.947 CPU time (s): 149.401 CPU user time (s): 147.881 CPU system time (s): 1.52009 CPU usage (%): 98.3247 Max. virtual memory (cumulated for all children) (KiB): 1151596 getrusage(RUSAGE_CHILDREN,...) data: user time used= 147.881 system time used= 1.52009 maximum resident set size= 986244 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 262989 page faults= 139 swaps= 0 block input operations= 5728 block output operations= 64 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 528 involuntary context switches= 3213 runsolver used 0.268016 second user time and 0.436027 second system time The end