1 #!/usr/bin/env python 2 # 3 # Copyright (C) 2009 The Android Open Source Project 4 # 5 # Licensed under the Apache License, Version 2.0 (the "License"); 6 # you may not use this file except in compliance with the License. 7 # You may obtain a copy of the License at 8 # 9 # http://www.apache.org/licenses/LICENSE-2.0 10 # 11 # Unless required by applicable law or agreed to in writing, software 12 # distributed under the License is distributed on an "AS IS" BASIS, 13 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14 # See the License for the specific language governing permissions and 15 # limitations under the License. 16 17 # 18 # Parse event log output, looking for GC events. Format them for human 19 # consumption. 20 # 21 # ALL OUTPUT VALUES ARE APPROXIMATE. The event log data format uses a 22 # 12-bit floating-point representation, which means there aren't enough 23 # bits to accurately represent anything but small integers. Larger 24 # values will be rounded off. 25 # 26 # The data is generated by dalvik/vm/alloc/HeapDebug.c. 27 # 28 29 import getopt 30 import sys 31 import os 32 import re 33 import time 34 35 DEBUG = False # DEBUG is a global variable 36 37 38 def unfloat12(f12): 39 """Unpack a float12 value""" 40 if f12 < 0: 41 raise DataParseError, "bad float12 value %s" % f12 42 return (f12 & 0x1ff) << ((f12 >> 9) * 4) 43 44 45 def parseGlobalInfo(value): 46 """Parse event0 (global info)""" 47 value = int(value) 48 49 # Global information: 50 # 51 # [63 ] Must be zero 52 # [62-24] ASCII process identifier 53 # [23-12] GC time in ms 54 # [11- 0] Bytes freed 55 id = (value >> 24) & 0xffffffffff 56 gctime = unfloat12((value >> 12) & 0xfff) 57 bytes_freed = unfloat12(value & 0xfff) 58 59 idstr = "%c%c%c%c%c" % ( \ 60 (id >> 32) & 0xff, \ 61 (id >> 24) & 0xff, \ 62 (id >> 16) & 0xff, \ 63 (id >> 8) & 0xff, \ 64 id & 0xff ) 65 66 return ( idstr, gctime, bytes_freed ) 67 68 69 def parseAggHeapStats(value): 70 """Parse event1 (aggregated heap stats)""" 71 value = int(value) 72 73 # Aggregated heap stats: 74 # 75 # [63-62] 10 76 # [61-60] Reserved; must be zero 77 # [59-48] Objects freed 78 # [47-36] Actual size (current footprint) 79 # [35-24] Allowed size (current hard max) 80 # [23-12] Objects allocated 81 # [11- 0] Bytes allocated 82 freed = unfloat12((value >> 48) & 0xfff) 83 footprint = unfloat12((value >> 36) & 0xfff) 84 allowed = unfloat12((value >> 24) & 0xfff) 85 objs = unfloat12((value >> 12) & 0xfff) 86 bytes = unfloat12(value & 0xfff) 87 88 return ( freed, footprint, allowed, objs, bytes ) 89 90 91 def parseZygoteStats(value): 92 """Parse event2 (zygote heap stats)""" 93 value = int(value) 94 95 # Zygote heap stats (except for the soft limit, which belongs to the 96 # active heap): 97 # 98 # [63-62] 11 99 # [61-60] Reserved; must be zero 100 # [59-48] Soft Limit (for the active heap) 101 # [47-36] Actual size (current footprint) 102 # [35-24] Allowed size (current hard max) 103 # [23-12] Objects allocated 104 # [11- 0] Bytes allocated 105 soft_limit = unfloat12((value >> 48) & 0xfff) 106 actual = unfloat12((value >> 36) & 0xfff) 107 allowed = unfloat12((value >> 24) & 0xfff) 108 objs = unfloat12((value >> 12) & 0xfff) 109 bytes = unfloat12(value & 0xfff) 110 111 return ( soft_limit, actual, allowed, objs, bytes ) 112 113 114 def parseExternalStats(value): 115 """Parse event3 (external allocation stats)""" 116 value = int(value) 117 118 # Report the current external allocation stats and the native heap 119 # summary. 120 # 121 # [63-48] Reserved; must be zero (TODO: put new data in these slots) 122 # [47-36] dlmalloc_footprint 123 # [35-24] mallinfo: total allocated space 124 # [23-12] External byte limit 125 # [11- 0] External bytes allocated 126 footprint = unfloat12((value >> 36) & 0xfff) # currently disabled 127 total = unfloat12((value >> 24) & 0xfff) # currently disabled 128 limit = unfloat12((value >> 12) & 0xfff) 129 bytes = unfloat12(value & 0xfff) 130 131 return ( footprint, total, limit, bytes ) 132 133 134 def handleGcInfo(procFilter, timestamp, pid, values): 135 """Handle a single dvm_gc_info event""" 136 137 pid = int(pid) 138 139 global_info = parseGlobalInfo(values[0]) 140 141 if len(procFilter) > 0: 142 if global_info[0] != procFilter: 143 return 144 145 heap_stats = parseAggHeapStats(values[1]) 146 zygote = parseZygoteStats(values[2]) 147 external = parseExternalStats(values[3]) 148 149 print "%s %s(%d) softlim=%dKB, extlim=%dKB, extalloc=%dKB" % \ 150 (timestamp, global_info[0], pid, zygote[0]/1024, external[2]/1024, external[3]/1024) 151 152 if DEBUG: 153 # print "RAW: %s %s (%s,%s,%s,%s)" % \ 154 # (timestamp, pid, values[0], values[1], values[2], values[3]) 155 156 print "+ id=\"%s\" time=%d freed=%d" % (global_info[0], global_info[1], global_info[2]) 157 print "+ freed=%d foot=%d allow=%d objs=%d bytes=%d" % \ 158 (heap_stats[0], heap_stats[1], heap_stats[2], heap_stats[3], heap_stats[4]) 159 print "+ soft=%d act=%d allow=%d objs=%d bytes=%d" % \ 160 (zygote[0], zygote[1], zygote[2], zygote[3], zygote[4]) 161 print "+ foot=%d total=%d limit=%d alloc=%d" % \ 162 (external[0], external[1], external[2], external[3]) 163 164 print " freed %d objects / %d bytes in %dms" % \ 165 (heap_stats[0], global_info[2], global_info[1]) 166 167 168 def filterInput(logPipe, processFilter): 169 """Loop until EOF, pulling out GC events""" 170 171 # 04-29 20:31:00.334 I/dvm_gc_info( 69): [8320808730292729543,-8916699241518090181,-4006371297196337158,8165229] 172 gc_info_re = re.compile(r""" 173 (\d+-\d+\ \d+:\d+:\d+)\.\d+ # extract the date (#1), ignoring ms 174 .* # filler, usually " I/" 175 dvm_gc_info # only interested in GC info lines 176 \(\s*(\d+)\) # extract the pid (#2) 177 :\ \[ # filler 178 ([0-9-]+),([0-9-]+),([0-9-]+),([0-9-]+) # four values, may be negative 179 \].* # junk to end of line 180 """, re.VERBOSE) 181 182 while True: 183 line = logPipe.readline() 184 if not line: 185 print "EOF hit" 186 return 187 188 match = gc_info_re.match(line) 189 if not match: 190 #print "no match on %s" % line.strip() 191 continue 192 else: 193 handleGcInfo(processFilter, match.group(1), match.group(2), ( match.group(3), \ 194 match.group(4), match.group(5), match.group(6) ) ) 195 196 def PrintUsage(): 197 print "usage: %s [-p procFilter] [-d]" % sys.argv[0] 198 199 200 def start(): 201 """Entry point""" 202 203 global DEBUG 204 205 procFilter = "" 206 207 opts, args = getopt.getopt(sys.argv[1:], "hdp:") 208 209 for opt, val in opts: 210 if opt == "-h": 211 PrintUsage() 212 sys.exit(2) 213 elif opt == "-p": 214 procFilter = val 215 elif opt == "-d": 216 DEBUG = True 217 218 print "procfilter = %s" % procFilter 219 print "DEBUG = %s" % DEBUG 220 221 # launch a logcat and read from it 222 command = 'adb logcat -v time -b events' 223 logPipe = os.popen(command) 224 225 226 try: 227 filterInput(logPipe, procFilter) 228 except KeyboardInterrupt, err: 229 print "Stopping on keyboard interrupt." 230 231 logPipe.close() 232 233 234 start() 235 236
