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/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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.16 1.12 1.09 2/55 26541 /proc/meminfo: memFree=964616/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=3152 CPUtime=0 /proc/26541/stat : 26541 (runsolver) D 26540 26541 17863 34816 17863 4202560 76 0 0 0 0 0 0 0 20 0 1 0 29868472 3227648 98 18446744073709551615 134512640 134586868 4291263040 4291261064 4149453727 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/26541/statm: 788 98 66 19 0 73 0 [startup+0.126402 s] /proc/loadavg: 1.16 1.12 1.09 2/55 26541 /proc/meminfo: memFree=964616/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=7872 CPUtime=0 /proc/26541/stat : 26541 (aptitude) D 26540 26541 17863 34816 17863 4202496 117 0 3 0 0 0 0 0 20 0 1 0 29868472 8060928 39 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089037864 140221263091235 0 0 0 0 0 0 0 17 0 0 0 12 0 0 /proc/26541/statm: 1968 39 30 1052 0 29 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 7872 [startup+0.200397 s] /proc/loadavg: 1.16 1.12 1.09 2/55 26541 /proc/meminfo: memFree=964616/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=23840 CPUtime=0 /proc/26541/stat : 26541 (aptitude) D 26540 26541 17863 34816 17863 4202496 144 0 9 0 0 0 0 0 20 0 1 0 29868472 24412160 67 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089037576 140221263090446 0 0 0 0 0 0 0 17 0 0 0 19 0 0 /proc/26541/statm: 5960 67 45 1052 0 31 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 23840 [startup+0.300381 s] /proc/loadavg: 1.16 1.12 1.09 2/55 26541 /proc/meminfo: memFree=964616/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=40832 CPUtime=0 /proc/26541/stat : 26541 (aptitude) D 26540 26541 17863 34816 17863 4202496 176 0 16 0 0 0 0 0 20 0 1 0 29868472 41811968 100 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089037288 140221263091235 0 0 0 0 0 0 0 17 0 0 0 28 0 0 /proc/26541/statm: 10208 100 63 1052 0 60 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 40832 [startup+0.700323 s] /proc/loadavg: 1.16 1.12 1.09 2/55 26541 /proc/meminfo: memFree=964616/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=99196 CPUtime=0.01 /proc/26541/stat : 26541 (aptitude) D 26540 26541 17863 34816 17863 4202496 1296 1140 30 4 1 0 0 0 20 0 1 0 29868472 101576704 1156 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089033928 140221223384271 0 134217728 4096 0 0 0 0 17 0 0 0 61 0 0 /proc/26541/statm: 24799 1156 970 1052 0 136 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 99196 [startup+1.50022 s] /proc/loadavg: 1.16 1.12 1.09 1/56 26545 /proc/meminfo: memFree=955920/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=103288 CPUtime=0.03 /proc/26541/stat : 26541 (aptitude) R 26540 26541 17863 34816 17863 4202496 3276 1707 144 4 1 2 0 0 20 0 1 0 29868472 105766912 3219 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032336 140221260281754 0 134217728 4096 0 0 0 0 17 0 0 0 140 0 0 /proc/26541/statm: 25822 3219 2008 1052 0 1159 0 Current children cumulated CPU time (s) 0.03 Current children cumulated vsize (KiB) 103288 [startup+3.10022 s] /proc/loadavg: 1.16 1.12 1.09 2/56 26545 /proc/meminfo: memFree=952820/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=114256 CPUtime=0.34 /proc/26541/stat : 26541 (aptitude) R 26540 26541 17863 34816 17863 4202496 13440 1707 350 4 31 3 0 0 20 0 1 0 29868472 116998144 13581 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032456 140221223449206 0 134217728 4096 0 0 0 0 17 0 0 0 269 0 0 /proc/26541/statm: 28564 13581 9961 1052 0 3901 0 Current children cumulated CPU time (s) 0.34 Current children cumulated vsize (KiB) 114256 heavy processes: [startup+6.30024 s] /proc/loadavg: 1.15 1.11 1.09 2/57 26546 /proc/meminfo: memFree=805128/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=137872 CPUtime=2.73 /proc/26541/stat : 26541 (aptitude) R 26540 26541 17863 34816 17863 4202496 21663 2203 350 6 250 23 0 0 20 0 2 0 29868472 141180928 17960 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032888 140221222742343 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 34468 17960 10303 1052 0 9805 0 [pid=26541/tid=26546] ppid=26540 vsize=137872 CPUtime=0 /proc/26541/task/26546/stat : 26546 (aptitude) S 26540 26541 17863 34816 17863 4202560 6 2203 0 6 0 0 0 0 20 0 2 0 29868904 141180928 17960 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152909312 140221233976020 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.73 Current children cumulated vsize (KiB) 137872 heavy processes: [startup+12.7002 s] /proc/loadavg: 1.14 1.11 1.09 2/57 26547 /proc/meminfo: memFree=758504/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=254692 CPUtime=9.1 /proc/26541/stat : 26541 (aptitude) S 26540 26541 17863 34816 17863 4202496 35127 2203 350 6 879 31 0 0 20 0 2 0 29868472 260804608 30990 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032624 140221233976907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 63673 30990 10358 1052 0 39010 0 [pid=26541/tid=26546] ppid=26540 vsize=254692 CPUtime=5.57 /proc/26541/task/26546/stat : 26546 (aptitude) R 26540 26541 17863 34816 17863 4202560 13418 2203 0 6 550 7 0 0 20 0 2 0 29868904 260804608 30990 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152902840 140221267863909 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 9.1 Current children cumulated vsize (KiB) 254692 heavy processes: [startup+25.5002 s] /proc/loadavg: 1.11 1.11 1.09 2/57 26547 /proc/meminfo: memFree=653104/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=355056 CPUtime=21.84 /proc/26541/stat : 26541 (aptitude) S 26540 26541 17863 34816 17863 4202496 60444 2203 350 6 2137 47 0 0 20 0 2 0 29868472 363577344 56047 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032624 140221233976907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 88764 56047 10359 1052 0 64101 0 [pid=26541/tid=26546] ppid=26540 vsize=355056 CPUtime=18.3 /proc/26541/task/26546/stat : 26546 (aptitude) R 26540 26541 17863 34816 17863 4202560 38735 2203 0 6 1807 23 0 0 20 0 2 0 29868904 363577344 56047 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152900632 140221222732065 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 21.84 Current children cumulated vsize (KiB) 355056 [startup+51.1003 s] /proc/loadavg: 1.07 1.10 1.08 2/57 26555 /proc/meminfo: memFree=482596/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=524976 CPUtime=47.3 /proc/26541/stat : 26541 (aptitude) S 26540 26541 17863 34816 17863 4202496 102964 2203 350 6 4656 74 0 0 20 0 2 0 29868472 537575424 98501 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032624 140221233976907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 131244 98501 10373 1052 0 106581 0 [pid=26541/tid=26546] ppid=26540 vsize=524976 CPUtime=43.76 /proc/26541/task/26546/stat : 26546 (aptitude) R 26540 26541 17863 34816 17863 4202560 81248 2203 0 6 4326 50 0 0 20 0 2 0 29868904 537575424 98501 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152900632 140221222742152 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 47.3 Current children cumulated vsize (KiB) 524976 [startup+102.3 s] /proc/loadavg: 1.03 1.08 1.08 2/57 26555 /proc/meminfo: memFree=165404/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=837976 CPUtime=98.26 /proc/26541/stat : 26541 (aptitude) S 26540 26541 17863 34816 17863 4202496 181274 2203 350 6 9713 113 0 0 20 0 2 0 29868472 858087424 176660 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032624 140221233976907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 209494 176660 10374 1052 0 184831 0 [pid=26541/tid=26546] ppid=26540 vsize=837976 CPUtime=94.73 /proc/26541/task/26546/stat : 26546 (aptitude) R 26540 26541 17863 34816 17863 4202560 159558 2203 0 6 9383 90 0 0 20 0 2 0 29868904 858087424 176660 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152900632 140221223452912 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 98.26 Current children cumulated vsize (KiB) 837976 [startup+162.3 s] /proc/loadavg: 1.20 1.11 1.09 2/57 26555 /proc/meminfo: memFree=10068/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=1149012 CPUtime=156.33 /proc/26541/stat : 26541 (aptitude) S 26540 26541 17863 34816 17863 4202496 259411 2203 444 6 15475 158 0 0 20 0 2 0 29868472 1176588288 243365 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032624 140221233976907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 287253 243365 10236 1052 0 262590 0 [pid=26541/tid=26546] ppid=26540 vsize=1149012 CPUtime=152.79 /proc/26541/task/26546/stat : 26546 (aptitude) R 26540 26541 17863 34816 17863 4202560 237687 2203 90 6 15144 135 0 0 20 0 2 0 29868904 1176588288 243365 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152900632 140221267919894 0 134217728 4096 0 0 0 0 -1 0 0 0 121 0 0 Current children cumulated CPU time (s) 156.33 Current children cumulated vsize (KiB) 1149012 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+162.8 s] /proc/loadavg: 1.20 1.11 1.09 2/57 26555 /proc/meminfo: memFree=9820/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=1150992 CPUtime=156.7 /proc/26541/stat : 26541 (aptitude) S 26540 26541 17863 34816 17863 4202496 259909 2203 462 6 15512 158 0 0 20 0 2 0 29868472 1178615808 243551 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032624 140221233976907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 287748 243551 10176 1052 0 263085 0 [pid=26541/tid=26546] ppid=26540 vsize=1150992 CPUtime=153.15 /proc/26541/task/26546/stat : 26546 (aptitude) R 26540 26541 17863 34816 17863 4202560 238185 2203 108 6 15180 135 0 0 20 0 2 0 29868904 1178615808 243551 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152900632 140221267930691 0 134217728 4096 0 0 0 0 -1 0 0 0 134 0 0 Current children cumulated CPU time (s) 156.7 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 [startup+162.8 s] /proc/loadavg: 1.20 1.11 1.09 2/57 26555 /proc/meminfo: memFree=9820/1022884 swapFree=0/0 [pid=26541] ppid=26540 vsize=1150992 CPUtime=156.7 /proc/26541/stat : 26541 (aptitude) S 26540 26541 17863 34816 17863 4202496 259909 2203 462 6 15512 158 0 0 20 0 2 0 29868472 1178615808 243551 18446744073709551615 140221265231872 140221269539224 140734089040864 140734089032624 140221233976907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 346 0 0 /proc/26541/statm: 287748 243551 10176 1052 0 263085 0 [pid=26541/tid=26546] ppid=26540 vsize=1150992 CPUtime=153.15 /proc/26541/task/26546/stat : 26546 (aptitude) R 26540 26541 17863 34816 17863 4202560 238185 2203 108 6 15180 135 0 0 20 0 2 0 29868904 1178615808 243551 18446744073709551615 140221265231872 140221269539224 140734089040864 140221152900632 140221267930691 0 134217728 4096 0 0 0 0 -1 0 0 0 134 0 0 Current children cumulated CPU time (s) 156.7 Current children cumulated vsize (KiB) 1150992 Child ended because it received signal 15 (SIGTERM) Real time (s): 162.885 CPU time (s): 156.806 CPU user time (s): 155.146 CPU system time (s): 1.6601 CPU usage (%): 96.2681 Max. virtual memory (cumulated for all children) (KiB): 1150992 getrusage(RUSAGE_CHILDREN,...) data: user time used= 155.146 system time used= 1.6601 maximum resident set size= 978128 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 262124 page faults= 468 swaps= 0 block input operations= 265192 block output operations= 160 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 3018 involuntary context switches= 3641 runsolver used 0.248015 second user time and 0.512032 second system time The end