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/43.runsolver.aptitude aptitude -s -y --without-recommends install libasn1-6-heimdal libpcd2 libsigc-perl gnome-pilot tkvnc 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.09 1.11 1.04 2/55 25589 /proc/meminfo: memFree=749300/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=3152 CPUtime=0 /proc/25589/stat : 25589 (runsolver) R 25588 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29492147 3227648 32 18446744073709551615 134512640 134586868 4292303280 4292301328 4151657520 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.19594 s] /proc/loadavg: 1.09 1.11 1.04 2/55 25589 /proc/meminfo: memFree=749300/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=103288 CPUtime=0.18 /proc/25589/stat : 25589 (aptitude) R 25588 25589 17863 34816 17863 4202496 11300 1710 0 0 16 2 0 0 20 0 1 0 29492147 105766912 11101 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396320 139955334031888 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 25822 11101 9888 1052 0 1159 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 103288 [startup+0.200323 s] /proc/loadavg: 1.09 1.11 1.04 2/55 25589 /proc/meminfo: memFree=749300/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=103288 CPUtime=0.18 /proc/25589/stat : 25589 (aptitude) R 25588 25589 17863 34816 17863 4202496 11301 1710 0 0 16 2 0 0 20 0 1 0 29492147 105766912 11102 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396320 139955334152854 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 25822 11102 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 103288 [startup+0.300262 s] /proc/loadavg: 1.09 1.11 1.04 2/55 25589 /proc/meminfo: memFree=749300/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=103432 CPUtime=0.28 /proc/25589/stat : 25589 (aptitude) R 25588 25589 17863 34816 17863 4202496 11428 1710 0 0 26 2 0 0 20 0 1 0 29492147 105914368 11221 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675394832 139955334162402 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 25858 11221 9956 1052 0 1195 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 103432 [startup+0.700202 s] /proc/loadavg: 1.09 1.11 1.04 2/55 25589 /proc/meminfo: memFree=749300/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=123068 CPUtime=0.68 /proc/25589/stat : 25589 (aptitude) R 25588 25589 17863 34816 17863 4202496 17689 1710 0 0 63 5 0 0 20 0 1 0 29492147 126021632 15966 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675394488 139955296849427 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 30767 15966 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123068 [startup+1.50025 s] /proc/loadavg: 1.09 1.11 1.04 2/57 25594 /proc/meminfo: memFree=729328/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=136068 CPUtime=1.48 /proc/25589/stat : 25589 (aptitude) R 25588 25589 17863 34816 17863 4202496 20647 1710 0 0 141 7 0 0 20 0 2 0 29492147 139333632 17565 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396328 139955340138081 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 34017 17565 10207 1052 0 9354 0 [pid=25589/tid=25594] ppid=25588 vsize=136068 CPUtime=0 /proc/25589/task/25594/stat : 25594 (aptitude) S 25588 25589 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29492224 139333632 17565 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226986496 139955308053204 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) 136068 [startup+3.10025 s] /proc/loadavg: 1.09 1.11 1.04 2/57 25594 /proc/meminfo: memFree=719036/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=137820 CPUtime=3.07 /proc/25589/stat : 25589 (aptitude) R 25588 25589 17863 34816 17863 4202496 21982 2208 0 0 295 12 0 0 20 0 2 0 29492147 141127680 17931 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675391760 139955341510427 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 34455 17931 10303 1052 0 9792 0 [pid=25589/tid=25594] ppid=25588 vsize=137820 CPUtime=0 /proc/25589/task/25594/stat : 25594 (aptitude) S 25588 25589 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 29492224 141127680 17931 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226986496 139955308053204 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) 137820 [startup+6.30025 s] /proc/loadavg: 1.08 1.11 1.04 2/57 25595 /proc/meminfo: memFree=683448/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=182596 CPUtime=6.25 /proc/25589/stat : 25589 (aptitude) S 25588 25589 17863 34816 17863 4202496 33692 2208 0 0 609 16 0 0 20 0 2 0 29492147 186978304 29365 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396816 139955308054091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 45649 29365 10359 1052 0 20986 0 [pid=25589/tid=25594] ppid=25588 vsize=182596 CPUtime=2.84 /proc/25589/task/25594/stat : 25594 (aptitude) R 25588 25589 17863 34816 17863 4202560 11710 2208 0 0 280 4 0 0 20 0 2 0 29492224 186978304 29365 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226980024 139955341985305 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.25 Current children cumulated vsize (KiB) 182596 [startup+12.7002 s] /proc/loadavg: 1.08 1.10 1.04 2/57 25595 /proc/meminfo: memFree=616364/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=308844 CPUtime=12.62 /proc/25589/stat : 25589 (aptitude) S 25588 25589 17863 34816 17863 4202496 49168 2208 0 0 1236 26 0 0 20 0 2 0 29492147 316256256 44528 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396816 139955308054091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 77211 44528 10359 1052 0 52548 0 [pid=25589/tid=25594] ppid=25588 vsize=308844 CPUtime=9.21 /proc/25589/task/25594/stat : 25594 (aptitude) R 25588 25589 17863 34816 17863 4202560 27185 2208 0 0 907 14 0 0 20 0 2 0 29492224 316256256 44528 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226977816 139955296819216 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.62 Current children cumulated vsize (KiB) 308844 [startup+25.5003 s] /proc/loadavg: 1.06 1.10 1.04 2/57 25595 /proc/meminfo: memFree=516916/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=404696 CPUtime=25.35 /proc/25589/stat : 25589 (aptitude) S 25588 25589 17863 34816 17863 4202496 73478 2208 0 0 2500 35 0 0 20 0 2 0 29492147 414408704 68468 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396816 139955308054091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 101174 68468 10360 1052 0 76511 0 [pid=25589/tid=25594] ppid=25588 vsize=404696 CPUtime=21.95 /proc/25589/task/25594/stat : 25594 (aptitude) R 25588 25589 17863 34816 17863 4202560 51495 2208 0 0 2172 23 0 0 20 0 2 0 29492224 414408704 68468 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226977864 139955334709889 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.35 Current children cumulated vsize (KiB) 404696 [startup+51.1003 s] /proc/loadavg: 1.10 1.11 1.04 2/57 25595 /proc/meminfo: memFree=380144/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=542548 CPUtime=50.82 /proc/25589/stat : 25589 (aptitude) S 25588 25589 17863 34816 17863 4202496 108351 2208 0 0 5027 55 0 0 20 0 2 0 29492147 555569152 102887 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396816 139955308054091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 135637 102887 10374 1052 0 110974 0 [pid=25589/tid=25594] ppid=25588 vsize=542548 CPUtime=47.41 /proc/25589/task/25594/stat : 25594 (aptitude) R 25588 25589 17863 34816 17863 4202560 86362 2208 0 0 4698 43 0 0 20 0 2 0 29492224 555569152 102887 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226977768 139955341933730 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 50.82 Current children cumulated vsize (KiB) 542548 [startup+102.3 s] /proc/loadavg: 1.04 1.09 1.04 2/57 25595 /proc/meminfo: memFree=46832/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=873440 CPUtime=101.78 /proc/25589/stat : 25589 (aptitude) S 25588 25589 17863 34816 17863 4202496 191105 2208 0 0 10078 100 0 0 20 0 2 0 29492147 894402560 185498 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396816 139955308054091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 218360 185498 10375 1052 0 193697 0 [pid=25589/tid=25594] ppid=25588 vsize=873440 CPUtime=98.36 /proc/25589/task/25594/stat : 25594 (aptitude) R 25588 25589 17863 34816 17863 4202560 169116 2208 0 0 9748 88 0 0 20 0 2 0 29492224 894402560 185498 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226977816 139955341672024 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.78 Current children cumulated vsize (KiB) 873440 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+132 s] /proc/loadavg: 1.29 1.14 1.06 1/57 25595 /proc/meminfo: memFree=8088/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=1152052 CPUtime=126.24 /proc/25589/stat : 25589 (aptitude) S 25588 25589 17863 34816 17863 4202496 261039 2208 292 0 12470 154 0 0 20 0 2 0 29492147 1179701248 233766 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396816 139955308054091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 288013 233766 7725 1052 0 263350 0 [pid=25589/tid=25594] ppid=25588 vsize=1152052 CPUtime=122.83 /proc/25589/task/25594/stat : 25594 (aptitude) R 25588 25589 17863 34816 17863 4202560 239050 2208 292 0 12141 142 0 0 20 0 2 0 29492224 1179701248 233766 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226977816 139955341904062 0 134217728 4096 0 0 0 0 -1 0 0 0 478 0 0 Current children cumulated CPU time (s) 126.24 Current children cumulated vsize (KiB) 1152052 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+132 s] /proc/loadavg: 1.29 1.14 1.06 1/57 25595 /proc/meminfo: memFree=8088/1022884 swapFree=0/0 [pid=25589] ppid=25588 vsize=1152052 CPUtime=126.24 /proc/25589/stat : 25589 (aptitude) S 25588 25589 17863 34816 17863 4202496 261039 2208 292 0 12470 154 0 0 20 0 2 0 29492147 1179701248 233766 18446744073709551615 139955339309056 139955343616408 140733675405056 140733675396816 139955308054091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25589/statm: 288013 233766 7725 1052 0 263350 0 [pid=25589/tid=25594] ppid=25588 vsize=1152052 CPUtime=122.83 /proc/25589/task/25594/stat : 25594 (aptitude) R 25588 25589 17863 34816 17863 4202560 239050 2208 292 0 12141 142 0 0 20 0 2 0 29492224 1179701248 233766 18446744073709551615 139955339309056 139955343616408 140733675405056 139955226977816 139955341904062 0 134217728 4096 0 0 0 0 -1 0 0 0 478 0 0 Current children cumulated CPU time (s) 126.24 Current children cumulated vsize (KiB) 1152052 Child ended because it received signal 15 (SIGTERM) Real time (s): 132.355 CPU time (s): 126.376 CPU user time (s): 124.768 CPU system time (s): 1.6081 CPU usage (%): 95.4826 Max. virtual memory (cumulated for all children) (KiB): 1152052 getrusage(RUSAGE_CHILDREN,...) data: user time used= 124.768 system time used= 1.6081 maximum resident set size= 942664 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 263392 page faults= 293 swaps= 0 block input operations= 9552 block output operations= 80 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 676 involuntary context switches= 3248 runsolver used 0.16401 second user time and 0.48803 second system time The end