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/109.runsolver.aptitude aptitude -s -y --without-recommends remove ktuberling libedata-cal5 libattr1 artsbuilder kdemultimedia-kfile-plugins 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.06 1.08 1.04 2/55 24333 /proc/meminfo: memFree=868688/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=54860 CPUtime=0 /proc/24333/stat : 24333 (aptitude) R 24332 24333 17863 34816 17863 4202496 586 0 0 0 0 0 0 0 20 0 1 0 29200689 56176640 486 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021650088 140609994745726 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 13715 486 398 1052 0 73 0 [startup+0.157745 s] /proc/loadavg: 1.06 1.08 1.04 2/55 24333 /proc/meminfo: memFree=868688/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=100508 CPUtime=0.14 /proc/24333/stat : 24333 (aptitude) R 24332 24333 17863 34816 17863 4202496 10593 1708 0 0 12 2 0 0 20 0 1 0 29200689 102920192 10395 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642144 140609991625488 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 25127 10395 9220 1052 0 1122 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 100508 [startup+0.200284 s] /proc/loadavg: 1.06 1.08 1.04 2/55 24333 /proc/meminfo: memFree=868688/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=100508 CPUtime=0.19 /proc/24333/stat : 24333 (aptitude) R 24332 24333 17863 34816 17863 4202496 10605 1708 0 0 17 2 0 0 20 0 1 0 29200689 102920192 10407 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642144 140609992344049 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 25127 10407 9232 1052 0 1122 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 100508 [startup+0.300265 s] /proc/loadavg: 1.06 1.08 1.04 2/55 24333 /proc/meminfo: memFree=868688/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=111108 CPUtime=0.28 /proc/24333/stat : 24333 (aptitude) R 24332 24333 17863 34816 17863 4202496 12374 1708 0 0 26 2 0 0 20 0 1 0 29200689 113774592 12168 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642472 140609999074907 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 27777 12168 9302 1052 0 3772 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 111108 [startup+0.700205 s] /proc/loadavg: 1.06 1.08 1.04 2/55 24333 /proc/meminfo: memFree=868688/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=123288 CPUtime=0.68 /proc/24333/stat : 24333 (aptitude) R 24332 24333 17863 34816 17863 4202496 17024 1708 0 0 61 7 0 0 20 0 2 0 29200689 126246912 14299 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021644504 140609999068718 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 30822 14299 9478 1052 0 6817 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123288 [startup+1.50024 s] /proc/loadavg: 1.06 1.08 1.04 2/57 24338 /proc/meminfo: memFree=840656/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=131940 CPUtime=1.47 /proc/24333/stat : 24333 (aptitude) R 24332 24333 17863 34816 17863 4202496 19296 1708 0 0 140 7 0 0 20 0 2 0 29200689 135106560 16567 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021639048 140609963248620 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 32985 16567 9568 1052 0 8980 0 [pid=24333/tid=24338] ppid=24332 vsize=131940 CPUtime=0 /proc/24333/task/24338/stat : 24338 (aptitude) S 24332 24333 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29200754 135106560 16567 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887770624 140609965687508 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.47 Current children cumulated vsize (KiB) 131940 [startup+3.10024 s] /proc/loadavg: 1.06 1.07 1.04 2/57 24338 /proc/meminfo: memFree=839912/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=140560 CPUtime=3.07 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 21556 1708 0 0 299 8 0 0 20 0 2 0 29200689 143933440 18826 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 35140 18826 9661 1052 0 11135 0 [pid=24333/tid=24338] ppid=24332 vsize=140560 CPUtime=0.53 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 2118 1708 0 0 53 0 0 0 20 0 2 0 29200754 143933440 18826 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887762312 140609999536453 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) 140560 [startup+6.30024 s] /proc/loadavg: 1.06 1.07 1.04 2/57 24338 /proc/meminfo: memFree=803208/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=176632 CPUtime=6.26 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 30552 1708 0 0 615 11 0 0 20 0 2 0 29200689 180871168 27822 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 44158 27822 9662 1052 0 20153 0 [pid=24333/tid=24338] ppid=24332 vsize=176632 CPUtime=3.72 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 11113 1708 0 0 369 3 0 0 20 0 2 0 29200754 180871168 27822 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887761944 140609963248620 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) 176632 [startup+12.7003 s] /proc/loadavg: 1.05 1.07 1.04 2/57 24338 /proc/meminfo: memFree=748524/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=228644 CPUtime=12.61 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 43557 1708 0 0 1244 17 0 0 20 0 2 0 29200689 234131456 40827 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 57161 40827 9663 1052 0 33156 0 [pid=24333/tid=24338] ppid=24332 vsize=228644 CPUtime=10.08 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 24118 1708 0 0 999 9 0 0 20 0 2 0 29200754 234131456 40827 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887761944 140609999770080 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 12.61 Current children cumulated vsize (KiB) 228644 [startup+25.5003 s] /proc/loadavg: 1.04 1.07 1.04 2/57 24338 /proc/meminfo: memFree=663088/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=376004 CPUtime=25.35 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 64006 1708 0 0 2507 28 0 0 20 0 2 0 29200689 385028096 61276 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 94001 61276 9677 1052 0 69996 0 [pid=24333/tid=24338] ppid=24332 vsize=376004 CPUtime=22.81 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 44560 1708 0 0 2261 20 0 0 20 0 2 0 29200754 385028096 61276 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887764104 140609991767161 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 25.35 Current children cumulated vsize (KiB) 376004 [startup+51.1003 s] /proc/loadavg: 1.02 1.06 1.03 2/57 24338 /proc/meminfo: memFree=518752/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=522008 CPUtime=50.83 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 100466 1708 0 0 5035 48 0 0 20 0 2 0 29200689 534536192 97736 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 130502 97736 9677 1052 0 106497 0 [pid=24333/tid=24338] ppid=24332 vsize=522008 CPUtime=48.29 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 81020 1708 0 0 4789 40 0 0 20 0 2 0 29200754 534536192 97736 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887761944 140609999589865 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 522008 [startup+102.3 s] /proc/loadavg: 1.01 1.05 1.03 2/57 24338 /proc/meminfo: memFree=269636/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=767292 CPUtime=101.79 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 161739 1708 0 0 10097 82 0 0 20 0 2 0 29200689 785707008 159009 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 191823 159009 9677 1052 0 167818 0 [pid=24333/tid=24338] ppid=24332 vsize=767292 CPUtime=99.25 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 142293 1708 0 0 9851 74 0 0 20 0 2 0 29200754 785707008 159009 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887764056 140609999568058 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 101.79 Current children cumulated vsize (KiB) 767292 [startup+162.3 s] /proc/loadavg: 1.00 1.04 1.02 2/57 24338 /proc/meminfo: memFree=27588/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=1011944 CPUtime=161.5 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 222662 1708 0 0 16029 121 0 0 20 0 2 0 29200689 1036230656 219932 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 252986 219932 9677 1052 0 228981 0 [pid=24333/tid=24338] ppid=24332 vsize=1011944 CPUtime=158.95 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 203216 1708 0 0 15782 113 0 0 20 0 2 0 29200754 1036230656 219932 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887764280 140609992344114 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 161.5 Current children cumulated vsize (KiB) 1011944 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+193.5 s] /proc/loadavg: 1.34 1.11 1.05 2/57 24338 /proc/meminfo: memFree=8832/1022884 swapFree=0/0 [pid=24333] ppid=24332 vsize=1151656 CPUtime=190.37 /proc/24333/stat : 24333 (aptitude) S 24332 24333 17863 34816 17863 4202496 257899 1708 251 0 18891 146 0 0 20 0 2 0 29200689 1179295744 246995 18446744073709551615 140609996943360 140610001250712 140736021650880 140736021642640 140609965688395 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/24333/statm: 287914 246995 8751 1052 0 263909 0 [pid=24333/tid=24338] ppid=24332 vsize=1151656 CPUtime=187.82 /proc/24333/task/24338/stat : 24338 (aptitude) R 24332 24333 17863 34816 17863 4202560 238445 1708 248 0 18644 138 0 0 20 0 2 0 29200754 1179295744 246995 18446744073709551615 140609996943360 140610001250712 140736021650880 140609887761944 140609997526640 0 134217728 4096 0 0 0 0 -1 0 0 0 180 0 0 Current children cumulated CPU time (s) 190.37 Current children cumulated vsize (KiB) 1151656 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): 193.763 CPU time (s): 190.52 CPU user time (s): 188.976 CPU system time (s): 1.5441 CPU usage (%): 98.3261 Max. virtual memory (cumulated for all children) (KiB): 1151656 getrusage(RUSAGE_CHILDREN,...) data: user time used= 188.976 system time used= 1.5441 maximum resident set size= 989548 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 259715 page faults= 256 swaps= 0 block input operations= 10968 block output operations= 72 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 715 involuntary context switches= 4080 runsolver used 0.280017 second user time and 0.628039 second system time The end