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/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.23 1.09 1.02 2/55 23864 /proc/meminfo: memFree=966172/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=3152 CPUtime=0 /proc/23864/stat : 23864 (runsolver) R 23863 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29081161 3227648 32 18446744073709551615 134512640 134586868 4289302000 4289300048 4152103984 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/23864/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.183986 s] /proc/loadavg: 1.23 1.09 1.02 2/55 23864 /proc/meminfo: memFree=966172/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=33024 CPUtime=0 /proc/23864/stat : 23864 (aptitude) D 23863 23864 17863 34816 17863 4202496 162 0 13 0 0 0 0 0 20 0 1 0 29081161 33816576 86 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761218136 140330085717539 0 0 0 0 0 0 0 17 0 0 0 17 0 0 /proc/23864/statm: 8256 86 55 1052 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 33024 [startup+0.200387 s] /proc/loadavg: 1.23 1.09 1.02 2/55 23864 /proc/meminfo: memFree=966172/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=36128 CPUtime=0 /proc/23864/stat : 23864 (aptitude) R 23863 23864 17863 34816 17863 4202496 168 0 14 0 0 0 0 0 20 0 1 0 29081161 36995072 92 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761218136 140330085717382 0 0 0 0 0 0 0 17 0 0 0 18 0 0 /proc/23864/statm: 9032 92 58 1052 0 39 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 36128 [startup+0.300326 s] /proc/loadavg: 1.23 1.09 1.02 2/55 23864 /proc/meminfo: memFree=966172/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=54968 CPUtime=0 /proc/23864/stat : 23864 (aptitude) D 23863 23864 17863 34816 17863 4202496 1028 0 25 0 0 0 0 0 20 0 1 0 29081161 56287232 944 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761216872 140330056614256 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0 /proc/23864/statm: 13742 944 789 1052 0 106 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 54968 [startup+0.700288 s] /proc/loadavg: 1.23 1.09 1.02 2/55 23864 /proc/meminfo: memFree=966172/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=100508 CPUtime=0 /proc/23864/stat : 23864 (aptitude) D 23863 23864 17863 34816 17863 4202496 2424 1706 38 4 0 0 0 0 20 0 1 0 29081161 102920192 2261 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213184 140330082908058 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0 /proc/23864/statm: 25127 2261 1086 1052 0 1122 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 100508 [startup+1.50026 s] /proc/loadavg: 1.21 1.09 1.02 1/56 23868 /proc/meminfo: memFree=958228/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=100508 CPUtime=0.01 /proc/23864/stat : 23864 (aptitude) D 23863 23864 17863 34816 17863 4202496 4217 1706 177 4 1 0 0 0 20 0 1 0 29081161 102920192 4193 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213184 140330082908058 0 134217728 4096 0 0 0 0 17 0 0 0 143 0 0 /proc/23864/statm: 25127 4193 3018 1052 0 1122 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 100508 [startup+3.10024 s] /proc/loadavg: 1.21 1.09 1.02 1/56 23868 /proc/meminfo: memFree=955624/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=119772 CPUtime=0.57 /proc/23864/stat : 23864 (aptitude) D 23863 23864 17863 34816 17863 4202496 16205 1706 303 4 43 14 0 0 20 0 1 0 29081161 122646528 14784 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761211144 140330056614256 0 134217728 4096 0 0 0 0 17 0 0 0 247 0 0 /proc/23864/statm: 29943 14784 9317 1052 0 5938 0 Current children cumulated CPU time (s) 0.57 Current children cumulated vsize (KiB) 119772 heavy processes: [startup+6.30025 s] /proc/loadavg: 1.21 1.09 1.02 2/57 23870 /proc/meminfo: memFree=841660/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=141736 CPUtime=3.42 /proc/23864/stat : 23864 (aptitude) S 23863 23864 17863 34816 17863 4202496 22576 2201 303 6 317 24 1 0 20 0 2 0 29081161 145137664 19148 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213472 140330056603211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0 /proc/23864/statm: 35434 19148 9697 1052 0 11429 0 [pid=23864/tid=23869] ppid=23863 vsize=141736 CPUtime=0.29 /proc/23864/task/23869/stat : 23869 (aptitude) R 23863 23864 17863 34816 17863 4202560 2282 2201 0 6 28 0 1 0 20 0 2 0 29081513 145137664 19148 18446744073709551615 140330087858176 140330092165528 140733761221712 140329978678968 140330045368416 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.42 Current children cumulated vsize (KiB) 141736 heavy processes: [startup+12.7002 s] /proc/loadavg: 1.18 1.09 1.01 2/57 23870 /proc/meminfo: memFree=778172/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=266384 CPUtime=9.79 /proc/23864/stat : 23864 (aptitude) S 23863 23864 17863 34816 17863 4202496 38155 2201 303 6 948 30 1 0 20 0 2 0 29081161 272777216 33937 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213472 140330056603211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0 /proc/23864/statm: 66596 33937 9700 1052 0 42591 0 [pid=23864/tid=23869] ppid=23863 vsize=266384 CPUtime=6.66 /proc/23864/task/23869/stat : 23869 (aptitude) R 23863 23864 17863 34816 17863 4202560 17859 2201 0 6 660 5 1 0 20 0 2 0 29081513 272777216 33937 18446744073709551615 140330087858176 140330092165528 140733761221712 140329978676760 140330089486513 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 9.79 Current children cumulated vsize (KiB) 266384 heavy processes: [startup+25.5003 s] /proc/loadavg: 1.15 1.08 1.01 2/57 23870 /proc/meminfo: memFree=684428/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=357176 CPUtime=22.53 /proc/23864/stat : 23864 (aptitude) S 23863 23864 17863 34816 17863 4202496 60922 2201 303 6 2214 38 1 0 20 0 2 0 29081161 365748224 56599 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213472 140330056603211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0 /proc/23864/statm: 89294 56599 9700 1052 0 65289 0 [pid=23864/tid=23869] ppid=23863 vsize=357176 CPUtime=19.4 /proc/23864/task/23869/stat : 23869 (aptitude) R 23863 23864 17863 34816 17863 4202560 40626 2201 0 6 1925 14 1 0 20 0 2 0 29081513 365748224 56599 18446744073709551615 140330087858176 140330092165528 140733761221712 140329978679688 140330045358419 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 22.53 Current children cumulated vsize (KiB) 357176 [startup+51.1003 s] /proc/loadavg: 1.10 1.08 1.01 2/57 23870 /proc/meminfo: memFree=534636/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=508924 CPUtime=48.02 /proc/23864/stat : 23864 (aptitude) S 23863 23864 17863 34816 17863 4202496 99302 2201 303 6 4743 58 1 0 20 0 2 0 29081161 521138176 94566 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213472 140330056603211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0 /proc/23864/statm: 127231 94566 9714 1052 0 103226 0 [pid=23864/tid=23869] ppid=23863 vsize=508924 CPUtime=44.88 /proc/23864/task/23869/stat : 23869 (aptitude) R 23863 23864 17863 34816 17863 4202560 78999 2201 0 6 4453 34 1 0 20 0 2 0 29081513 521138176 94566 18446744073709551615 140330087858176 140330092165528 140733761221712 140329978676808 140330045358537 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 48.02 Current children cumulated vsize (KiB) 508924 [startup+102.3 s] /proc/loadavg: 1.04 1.06 1.01 2/57 23870 /proc/meminfo: memFree=172556/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=867192 CPUtime=98.97 /proc/23864/stat : 23864 (aptitude) S 23863 23864 17863 34816 17863 4202496 188759 2201 303 6 9792 104 1 0 20 0 2 0 29081161 888004608 183946 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213472 140330056603211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0 /proc/23864/statm: 216798 183946 9716 1052 0 192793 0 [pid=23864/tid=23869] ppid=23863 vsize=867192 CPUtime=95.84 /proc/23864/task/23869/stat : 23869 (aptitude) R 23863 23864 17863 34816 17863 4202560 168456 2201 0 6 9503 80 1 0 20 0 2 0 29081513 888004608 183946 18446744073709551615 140330087858176 140330092165528 140733761221712 140329978676760 140330090087130 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 98.97 Current children cumulated vsize (KiB) 867192 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+140.2 s] /proc/loadavg: 1.17 1.08 1.01 2/57 23870 /proc/meminfo: memFree=9528/1022884 swapFree=0/0 [pid=23864] ppid=23863 vsize=1150996 CPUtime=135.68 /proc/23864/stat : 23864 (aptitude) S 23863 23864 17863 34816 17863 4202496 259821 2201 345 6 13414 153 1 0 20 0 2 0 29081161 1178619904 245083 18446744073709551615 140330087858176 140330092165528 140733761221712 140733761213472 140330056603211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 280 0 0 /proc/23864/statm: 287749 245083 9672 1052 0 263744 0 [pid=23864/tid=23869] ppid=23863 vsize=1150996 CPUtime=132.54 /proc/23864/task/23869/stat : 23869 (aptitude) R 23863 23864 17863 34816 17863 4202560 239518 2201 42 6 13124 129 1 0 20 0 2 0 29081513 1178619904 245083 18446744073709551615 140330087858176 140330092165528 140733761221712 140329978676760 140330082681969 0 134217728 4096 0 0 0 0 -1 0 0 0 64 0 0 Current children cumulated CPU time (s) 135.68 Current children cumulated vsize (KiB) 1150996 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): 140.31 CPU time (s): 135.788 CPU user time (s): 134.172 CPU system time (s): 1.6161 CPU usage (%): 96.7774 Max. virtual memory (cumulated for all children) (KiB): 1150996 getrusage(RUSAGE_CHILDREN,...) data: user time used= 134.172 system time used= 1.6161 maximum resident set size= 982332 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 262041 page faults= 352 swaps= 0 block input operations= 191464 block output operations= 136 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2267 involuntary context switches= 2894 runsolver used 0.184011 second user time and 0.472029 second system time The end