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/97.runsolver.aptitude aptitude -s -y --without-recommends install mimedefang openthreads-doc alsa-modules-2.4-686-smp kde-i18n-cy libkeynote0 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.16 1.06 1.01 2/55 22169 /proc/meminfo: memFree=976408/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=3152 CPUtime=0 /proc/22169/stat : 22169 (runsolver) R 22168 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28650718 3227648 32 18446744073709551615 134512640 134586868 4288096944 4288094992 4151575600 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22169/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.174033 s] /proc/loadavg: 1.16 1.06 1.01 2/55 22169 /proc/meminfo: memFree=976408/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=33024 CPUtime=0 /proc/22169/stat : 22169 (aptitude) D 22168 22169 17863 34816 17863 4202496 159 0 16 0 0 0 0 0 20 0 1 0 28650718 33816576 86 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668155912 139982161425955 0 0 0 0 0 0 0 17 0 0 0 15 0 0 /proc/22169/statm: 8256 86 55 1052 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 33024 [startup+0.200411 s] /proc/loadavg: 1.16 1.06 1.01 2/55 22169 /proc/meminfo: memFree=976408/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=36128 CPUtime=0 /proc/22169/stat : 22169 (aptitude) D 22168 22169 17863 34816 17863 4202496 165 0 17 0 0 0 0 0 20 0 1 0 28650718 36995072 92 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668155912 139982161425798 0 0 0 0 0 0 0 17 0 0 0 18 0 0 /proc/22169/statm: 9032 92 58 1052 0 39 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 36128 [startup+0.300234 s] /proc/loadavg: 1.16 1.06 1.01 2/55 22169 /proc/meminfo: memFree=976408/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=54860 CPUtime=0 /proc/22169/stat : 22169 (aptitude) R 22168 22169 17863 34816 17863 4202496 586 0 32 0 0 0 0 0 20 0 1 0 28650718 56176640 518 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668158696 139982161376236 0 0 0 0 0 0 0 17 0 0 0 29 0 0 /proc/22169/statm: 13715 518 423 1052 0 73 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 54860 [startup+0.700284 s] /proc/loadavg: 1.16 1.06 1.01 2/55 22169 /proc/meminfo: memFree=976408/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=89152 CPUtime=0.01 /proc/22169/stat : 22169 (aptitude) D 22168 22169 17863 34816 17863 4202496 2196 1704 65 4 0 1 0 0 20 0 1 0 28650718 91291648 2062 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668150960 139982158616474 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0 /proc/22169/statm: 22288 2062 1151 1052 0 858 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 89152 [startup+1.5002 s] /proc/loadavg: 1.16 1.06 1.01 1/56 22173 /proc/meminfo: memFree=967340/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=89152 CPUtime=0.19 /proc/22169/stat : 22169 (aptitude) R 22168 22169 17863 34816 17863 4202496 7698 1704 171 4 17 2 0 0 20 0 1 0 28650718 91291648 7662 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668149264 139982158967029 0 134217728 4096 0 0 0 0 17 0 0 0 124 0 0 /proc/22169/statm: 22288 7662 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+3.10024 s] /proc/loadavg: 1.15 1.06 1.01 2/57 22174 /proc/meminfo: memFree=897520/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=115384 CPUtime=1.36 /proc/22169/stat : 22169 (aptitude) R 22168 22169 17863 34816 17863 4202496 13708 1704 175 4 130 6 0 0 20 0 2 0 28650718 118153216 12252 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151144 139982158464312 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 28846 12252 7043 1052 0 7416 0 [pid=22169/tid=22174] ppid=22168 vsize=115384 CPUtime=0 /proc/22169/task/22174/stat : 22174 (aptitude) S 22168 22169 17863 34816 17863 4202560 4 1704 0 4 0 0 0 0 20 0 2 0 28650930 118153216 12252 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066972672 139982132310740 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.36 Current children cumulated vsize (KiB) 115384 heavy processes: [startup+6.30023 s] /proc/loadavg: 1.15 1.06 1.01 2/57 22175 /proc/meminfo: memFree=867140/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=146952 CPUtime=4.55 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 23230 2201 175 6 440 14 0 1 20 0 2 0 28650718 150478848 20454 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 36738 20454 7129 1052 0 15308 0 [pid=22169/tid=22174] ppid=22168 vsize=146952 CPUtime=2.52 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 8772 2201 0 6 247 4 0 1 20 0 2 0 28650930 150478848 20454 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066964040 139982121076832 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 4.55 Current children cumulated vsize (KiB) 146952 heavy processes: [startup+12.7002 s] /proc/loadavg: 1.12 1.06 1.01 2/57 22175 /proc/meminfo: memFree=810968/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=264276 CPUtime=10.9 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 36180 2201 175 6 1068 21 0 1 20 0 2 0 28650718 270618624 33396 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 66069 33396 7129 1052 0 44639 0 [pid=22169/tid=22174] ppid=22168 vsize=264276 CPUtime=8.89 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 21721 2201 0 6 876 12 0 1 20 0 2 0 28650930 270618624 33396 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066966200 139982121076999 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 10.9 Current children cumulated vsize (KiB) 264276 [startup+25.5003 s] /proc/loadavg: 1.10 1.05 1.01 2/57 22175 /proc/meminfo: memFree=705568/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=366364 CPUtime=23.64 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 61695 2201 175 6 2331 32 0 1 20 0 2 0 28650718 375156736 58896 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 91591 58896 7129 1052 0 70161 0 [pid=22169/tid=22174] ppid=22168 vsize=366364 CPUtime=21.63 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 47236 2201 0 6 2139 23 0 1 20 0 2 0 28650930 375156736 58896 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066963992 139982166273957 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 23.64 Current children cumulated vsize (KiB) 366364 [startup+51.1002 s] /proc/loadavg: 1.07 1.05 1.00 2/57 22175 /proc/meminfo: memFree=545732/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=526952 CPUtime=49.13 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 102034 2201 175 6 4860 52 0 1 20 0 2 0 28650718 539598848 98998 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 131738 98998 7143 1052 0 110308 0 [pid=22169/tid=22174] ppid=22168 vsize=526952 CPUtime=47.11 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 87568 2201 0 6 4667 43 0 1 20 0 2 0 28650930 539598848 98998 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066963992 139982166393457 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 49.13 Current children cumulated vsize (KiB) 526952 Solver just ended. Dumping a history of the last processes samples [startup+51.2003 s] /proc/loadavg: 1.07 1.05 1.00 2/57 22175 /proc/meminfo: memFree=545732/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=527348 CPUtime=49.23 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 102120 2201 175 6 4870 52 0 1 20 0 2 0 28650718 540004352 99084 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 131837 99084 7143 1052 0 110407 0 [pid=22169/tid=22174] ppid=22168 vsize=527348 CPUtime=47.21 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 87654 2201 0 6 4677 43 0 1 20 0 2 0 28650930 540004352 99084 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066966152 139982166265436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 49.23 Current children cumulated vsize (KiB) 527348 [startup+64.0002 s] /proc/loadavg: 1.05 1.05 1.00 2/57 22175 /proc/meminfo: memFree=480384/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=590820 CPUtime=61.97 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 118086 2201 175 6 6137 59 0 1 20 0 2 0 28650718 604999680 114990 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 147705 114990 7143 1052 0 126275 0 [pid=22169/tid=22174] ppid=22168 vsize=590820 CPUtime=59.96 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 103620 2201 0 6 5945 50 0 1 20 0 2 0 28650930 604999680 114990 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066966328 139982121062316 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 61.97 Current children cumulated vsize (KiB) 590820 [startup+67.2032 s] /proc/loadavg: 1.05 1.04 1.00 2/57 22175 /proc/meminfo: memFree=460792/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=609968 CPUtime=65.14 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 122856 2201 176 6 6451 62 0 1 20 0 2 0 28650718 624607232 119760 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 152492 119760 7144 1052 0 131062 0 [pid=22169/tid=22174] ppid=22168 vsize=609968 CPUtime=63.11 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 108390 2201 1 6 6258 52 0 1 20 0 2 0 28650930 624607232 119760 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066968168 139982166340659 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 65.14 Current children cumulated vsize (KiB) 609968 [startup+70.4002 s] /proc/loadavg: 1.05 1.04 1.00 2/57 22175 /proc/meminfo: memFree=440704/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=629108 CPUtime=68.33 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 127677 2201 176 6 6768 64 0 1 20 0 2 0 28650718 644206592 124578 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668151248 139982132311627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0 /proc/22169/statm: 157277 124578 7144 1052 0 135847 0 [pid=22169/tid=22174] ppid=22168 vsize=629108 CPUtime=66.3 /proc/22169/task/22174/stat : 22174 (aptitude) R 22168 22169 17863 34816 17863 4202560 113211 2201 1 6 6574 55 0 1 20 0 2 0 28650930 644206592 124578 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066963992 139982166393480 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 68.33 Current children cumulated vsize (KiB) 629108 [startup+71.2002 s] /proc/loadavg: 1.05 1.04 1.00 2/57 22175 /proc/meminfo: memFree=440704/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=633096 CPUtime=69.03 /proc/22169/stat : 22169 (aptitude) R 22168 22169 17863 34816 17863 4202496 128805 2201 187 6 6838 64 0 1 20 0 2 0 28650718 648290304 125679 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668149624 139982166159440 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 175 0 0 /proc/22169/statm: 158274 125679 7191 1052 0 136837 0 [pid=22169/tid=22174] ppid=22168 vsize=633096 CPUtime=66.66 /proc/22169/task/22174/stat : 22174 (aptitude) S 22168 22169 17863 34816 17863 4202560 114186 2201 2 6 6610 55 0 1 20 0 2 0 28650930 648290304 125679 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066972672 139982132310740 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 69.03 Current children cumulated vsize (KiB) 633096 [startup+72.0002 s] /proc/loadavg: 1.05 1.04 1.00 2/57 22175 /proc/meminfo: memFree=435620/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=633224 CPUtime=69.83 /proc/22169/stat : 22169 (aptitude) R 22168 22169 17863 34816 17863 4202496 128848 2201 187 6 6918 64 0 1 20 0 2 0 28650718 648421376 125722 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668149624 139982121057910 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 175 0 0 /proc/22169/statm: 158306 125722 7191 1052 0 136869 0 [pid=22169/tid=22174] ppid=22168 vsize=633224 CPUtime=66.66 /proc/22169/task/22174/stat : 22174 (aptitude) S 22168 22169 17863 34816 17863 4202560 114186 2201 2 6 6610 55 0 1 20 0 2 0 28650930 648421376 125722 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066972672 139982132310740 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 69.83 Current children cumulated vsize (KiB) 633224 [startup+72.4002 s] /proc/loadavg: 1.05 1.04 1.00 2/57 22175 /proc/meminfo: memFree=435620/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=633224 CPUtime=70.22 /proc/22169/stat : 22169 (aptitude) S 22168 22169 17863 34816 17863 4202496 130755 2201 187 6 6947 74 0 1 20 0 2 0 28650718 648421376 125749 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668149264 139982121435603 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 175 0 0 /proc/22169/statm: 158306 125749 7193 1052 0 136869 0 [pid=22169/tid=22174] ppid=22168 vsize=633224 CPUtime=66.66 /proc/22169/task/22174/stat : 22174 (aptitude) S 22168 22169 17863 34816 17863 4202560 114186 2201 2 6 6610 55 0 1 20 0 2 0 28650930 648421376 125749 18446744073709551615 139982163566592 139982167873944 140734668159488 139982066972672 139982132310740 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 70.22 Current children cumulated vsize (KiB) 633224 [startup+72.5004 s] /proc/loadavg: 1.05 1.04 1.00 2/57 22175 /proc/meminfo: memFree=435620/1022884 swapFree=0/0 [pid=22169] ppid=22168 vsize=363188 CPUtime=70.32 /proc/22169/stat : 22169 (aptitude) D 22168 22169 17863 34816 17863 4202496 131087 2701 189 6 6948 82 0 2 20 0 1 0 28650718 371904512 58301 18446744073709551615 139982163566592 139982167873944 140734668159488 140734668156800 139982158377136 0 134217728 4096 0 0 0 0 17 0 0 0 175 0 0 /proc/22169/statm: 90797 58301 1520 1052 0 75053 0 Current children cumulated CPU time (s) 70.32 Current children cumulated vsize (KiB) 363188 Child status: 0 Real time (s): 72.5902 CPU time (s): 70.3964 CPU user time (s): 69.5003 CPU system time (s): 0.896056 CPU usage (%): 96.9778 Max. virtual memory (cumulated for all children) (KiB): 633224 getrusage(RUSAGE_CHILDREN,...) data: user time used= 69.5003 system time used= 0.896056 maximum resident set size= 503076 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 133852 page faults= 204 swaps= 0 block input operations= 132128 block output operations= 72 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1503 involuntary context switches= 1268 runsolver used 0.16801 second user time and 0.224014 second system time The end