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/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.13 1.06 0.96 2/55 21647 /proc/meminfo: memFree=909192/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=3152 CPUtime=0 /proc/21647/stat : 21647 (runsolver) R 21646 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28506023 3227648 33 18446744073709551615 134512640 134586868 4287324192 4287322240 4151911472 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.201994 s] /proc/loadavg: 1.13 1.06 0.96 2/55 21647 /proc/meminfo: memFree=909192/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=89152 CPUtime=0.19 /proc/21647/stat : 21647 (aptitude) R 21646 21647 17863 34816 17863 4202496 7869 1707 0 0 17 2 0 0 20 0 1 0 28506023 91291648 7661 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565690240 139751959103063 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 22288 7661 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+0.300277 s] /proc/loadavg: 1.13 1.06 0.96 2/55 21647 /proc/meminfo: memFree=909192/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=101864 CPUtime=0.29 /proc/21647/stat : 21647 (aptitude) R 21646 21647 17863 34816 17863 4202496 11708 1707 0 0 26 3 0 0 20 0 1 0 28506023 104308736 10755 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565689896 139751921794550 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 25466 10755 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 101864 [startup+0.40027 s] /proc/loadavg: 1.13 1.06 0.96 2/55 21647 /proc/meminfo: memFree=909192/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=101864 CPUtime=0.39 /proc/21647/stat : 21647 (aptitude) R 21646 21647 17863 34816 17863 4202496 11708 1707 0 0 35 4 0 0 20 0 1 0 28506023 104308736 10755 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565689896 139751967179491 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 25466 10755 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.39 Current children cumulated vsize (KiB) 101864 [startup+0.700203 s] /proc/loadavg: 1.13 1.06 0.96 2/55 21647 /proc/meminfo: memFree=909192/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=114224 CPUtime=0.68 /proc/21647/stat : 21647 (aptitude) R 21646 21647 17863 34816 17863 4202496 13731 1707 0 0 64 4 0 0 20 0 2 0 28506023 116965376 12104 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565691736 139751966465117 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 28556 12104 6977 1052 0 7126 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 114224 [startup+1.50023 s] /proc/loadavg: 1.13 1.06 0.96 2/57 21652 /proc/meminfo: memFree=888228/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=115472 CPUtime=1.48 /proc/21647/stat : 21647 (aptitude) R 21646 21647 17863 34816 17863 4202496 14563 2207 0 0 142 5 0 1 20 0 2 0 28506023 118243328 12360 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692488 139751966492628 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 28868 12360 7073 1052 0 7438 0 [pid=21647/tid=21652] ppid=21646 vsize=115472 CPUtime=0.01 /proc/21647/task/21652/stat : 21652 (aptitude) S 21646 21647 17863 34816 17863 4202560 6 2207 0 0 0 0 0 1 20 0 2 0 28506068 118243328 12360 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867660288 139751932998356 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) 115472 [startup+3.10024 s] /proc/loadavg: 1.13 1.06 0.96 2/57 21653 /proc/meminfo: memFree=879424/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=132104 CPUtime=3.08 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 19106 2207 0 0 298 9 0 1 20 0 2 0 28506023 135274496 16737 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 33026 16737 7129 1052 0 11596 0 [pid=21647/tid=21652] ppid=21646 vsize=132104 CPUtime=1.08 /proc/21647/task/21652/stat : 21652 (aptitude) R 21646 21647 17863 34816 17863 4202560 4464 2207 0 0 104 3 0 1 20 0 2 0 28506068 135274496 16737 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867654312 139751921764368 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) 132104 [startup+6.30024 s] /proc/loadavg: 1.12 1.06 0.96 2/57 21653 /proc/meminfo: memFree=846068/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=227276 CPUtime=6.26 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 27131 2207 0 0 613 12 0 1 20 0 2 0 28506023 232730624 24164 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 56819 24164 7129 1052 0 35389 0 [pid=21647/tid=21652] ppid=21646 vsize=227276 CPUtime=4.26 /proc/21647/task/21652/stat : 21652 (aptitude) R 21646 21647 17863 34816 17863 4202560 12488 2207 0 0 419 6 0 1 20 0 2 0 28506068 232730624 24164 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867651608 139751966938144 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) 227276 [startup+12.7002 s] /proc/loadavg: 1.11 1.06 0.96 2/57 21653 /proc/meminfo: memFree=793492/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=277584 CPUtime=12.63 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 39701 2207 0 0 1244 18 0 1 20 0 2 0 28506023 284246016 36734 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 69396 36734 7129 1052 0 47966 0 [pid=21647/tid=21652] ppid=21646 vsize=277584 CPUtime=10.63 /proc/21647/task/21652/stat : 21652 (aptitude) R 21646 21647 17863 34816 17863 4202560 25058 2207 0 0 1049 13 0 1 20 0 2 0 28506068 284246016 36734 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867651608 139751966924342 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) 277584 [startup+25.5032 s] /proc/loadavg: 1.08 1.06 0.96 2/57 21653 /proc/meminfo: memFree=689952/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=378496 CPUtime=25.37 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 64909 2207 0 0 2506 30 0 1 20 0 2 0 28506023 387579904 61920 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 94624 61920 7129 1052 0 73194 0 [pid=21647/tid=21652] ppid=21646 vsize=378496 CPUtime=23.37 /proc/21647/task/21652/stat : 21652 (aptitude) R 21646 21647 17863 34816 17863 4202560 50266 2207 0 0 2312 24 0 1 20 0 2 0 28506068 387579904 61920 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867653768 139751966996894 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) 378496 [startup+51.1002 s] /proc/loadavg: 1.06 1.05 0.96 2/57 21653 /proc/meminfo: memFree=529124/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=539404 CPUtime=50.85 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 105343 2207 4 0 5036 48 0 1 20 0 2 0 28506023 552349696 102126 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 134851 102126 7143 1052 0 113421 0 [pid=21647/tid=21652] ppid=21646 vsize=539404 CPUtime=48.84 /proc/21647/task/21652/stat : 21652 (aptitude) R 21646 21647 17863 34816 17863 4202560 90695 2207 2 0 4841 42 0 1 20 0 2 0 28506068 552349696 102126 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867651608 139751921754451 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) 539404 [startup+102.3 s] /proc/loadavg: 1.02 1.04 0.96 2/57 21653 /proc/meminfo: memFree=253596/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=818112 CPUtime=101.81 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 175006 2207 4 0 10093 87 0 1 20 0 2 0 28506023 837746688 171720 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 204528 171720 7145 1052 0 183098 0 [pid=21647/tid=21652] ppid=21646 vsize=818112 CPUtime=99.8 /proc/21647/task/21652/stat : 21652 (aptitude) R 21646 21647 17863 34816 17863 4202560 160358 2207 2 0 9898 81 0 1 20 0 2 0 28506068 837746688 171720 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867653816 139751966953052 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) 818112 [startup+162.3 s] /proc/loadavg: 1.16 1.06 0.97 2/57 21656 /proc/meminfo: memFree=9848/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=1128016 CPUtime=161.06 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 252236 2207 12 0 15980 125 0 1 20 0 2 0 28506023 1155088384 245005 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 282004 245005 7075 1052 0 260574 0 [pid=21647/tid=21652] ppid=21646 vsize=1128016 CPUtime=159.06 /proc/21647/task/21652/stat : 21652 (aptitude) R 21646 21647 17863 34816 17863 4202560 237588 2207 10 0 15785 120 0 1 20 0 2 0 28506068 1155088384 245005 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867651560 139751959078009 0 134217728 4096 0 0 0 0 -1 0 0 0 18 0 0 Current children cumulated CPU time (s) 161.06 Current children cumulated vsize (KiB) 1128016 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+167.6 s] /proc/loadavg: 1.23 1.08 0.98 1/57 21656 /proc/meminfo: memFree=9624/1022884 swapFree=0/0 [pid=21647] ppid=21646 vsize=1150992 CPUtime=165.83 /proc/21647/stat : 21647 (aptitude) S 21646 21647 17863 34816 17863 4202496 258079 2207 101 0 16454 128 0 1 20 0 2 0 28506023 1178615808 246975 18446744073709551615 139751964254208 139751968561560 140736565700464 140736565692224 139751932999243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21647/statm: 287748 246975 6818 1052 0 266318 0 [pid=21647/tid=21652] ppid=21646 vsize=1150992 CPUtime=163.82 /proc/21647/task/21652/stat : 21652 (aptitude) D 21646 21647 17863 34816 17863 4202560 243431 2207 99 0 16258 123 0 1 20 0 2 0 28506068 1178615808 246975 18446744073709551615 139751964254208 139751968561560 140736565700464 139751867654760 139751967102860 0 134217728 4096 0 0 0 0 -1 0 0 0 59 0 0 Current children cumulated CPU time (s) 165.83 Current children cumulated vsize (KiB) 1150992 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): 167.801 CPU time (s): 165.986 CPU user time (s): 164.634 CPU system time (s): 1.35208 CPU usage (%): 98.9189 Max. virtual memory (cumulated for all children) (KiB): 1150992 getrusage(RUSAGE_CHILDREN,...) data: user time used= 164.634 system time used= 1.35208 maximum resident set size= 989808 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 260374 page faults= 104 swaps= 0 block input operations= 6712 block output operations= 48 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 517 involuntary context switches= 3510 runsolver used 0.272017 second user time and 0.500031 second system time The end