dalvik/tools/gclog.py

   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()