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 # Version 1.0, 29-Apr-2009
  19 #
  20 # Parse event log output, looking for GC events.  Format them for human
  21 # consumption.
  22 #
  23 # ALL OUTPUT VALUES ARE APPROXIMATE.  The event log data format uses a
  24 # 12-bit floating-point representation, which means there aren't enough
  25 # bits to accurately represent anything but small integers.  Larger
  26 # values will be rounded off.
  27 #
  28 # The data is generated by dalvik/vm/alloc/HeapDebug.c.
  29 #
  30
  31 import os
  32 import re
  33 import time
  34
  35 def unfloat12(f12):
  36     """Unpack a float12 value"""
  37     if f12 < 0:
  38         raise DataParseError, "bad float12 value %s" % f12
  39     return (f12 & 0x1ff) << ((f12 >> 9) * 4)
  40
  41
  42 def parseGlobalInfo(value):
  43     """Parse event0 (global info)"""
  44     value = int(value)
  45
  46     # Global information:
  47     #
  48     # [63   ] Must be zero
  49     # [62-24] ASCII process identifier
  50     # [23-12] GC time in ms
  51     # [11- 0] Bytes freed
  52     id = (value >> 24) & 0xffffffffff
  53     gctime = unfloat12((value >> 12) & 0xfff)
  54     bytes_freed = unfloat12(value & 0xfff)
  55
  56     idstr = "%c%c%c%c%c" % ( \
  57             (id >> 32) & 0xff, \
  58             (id >> 24) & 0xff, \
  59             (id >> 16) & 0xff, \
  60             (id >> 8) & 0xff, \
  61             id & 0xff )
  62
  63     return ( idstr, gctime, bytes_freed )
  64
  65
  66 def parseAggHeapStats(value):
  67     """Parse event1 (aggregated heap stats)"""
  68     value = int(value)
  69
  70     # Aggregated heap stats:
  71     #
  72     # [63-62] 10
  73     # [61-60] Reserved; must be zero
  74     # [59-48] Objects freed
  75     # [47-36] Actual size (current footprint)
  76     # [35-24] Allowed size (current hard max)
  77     # [23-12] Objects allocated
  78     # [11- 0] Bytes allocated
  79     freed = unfloat12((value >> 48) & 0xfff)
  80     footprint = unfloat12((value >> 36) & 0xfff)
  81     allowed = unfloat12((value >> 24) & 0xfff)
  82     objs = unfloat12((value >> 12) & 0xfff)
  83     bytes = unfloat12(value & 0xfff)
  84
  85     return ( freed, footprint, allowed, objs, bytes )
  86
  87
  88 def parseZygoteStats(value):
  89     """Parse event2 (zygote heap stats)"""
  90     value = int(value)
  91
  92     # Zygote heap stats (except for the soft limit, which belongs to the
  93     # active heap):
  94     #
  95     # [63-62] 11
  96     # [61-60] Reserved; must be zero
  97     # [59-48] Soft Limit (for the active heap)
  98     # [47-36] Actual size (current footprint)
  99     # [35-24] Allowed size (current hard max)
 100     # [23-12] Objects allocated
 101     # [11- 0] Bytes allocated
 102     soft_limit = unfloat12((value >> 48) & 0xfff)
 103     actual = unfloat12((value >> 36) & 0xfff)
 104     allowed = unfloat12((value >> 24) & 0xfff)
 105     objs = unfloat12((value >> 12) & 0xfff)
 106     bytes = unfloat12(value & 0xfff)
 107
 108     return ( soft_limit, actual, allowed, objs, bytes )
 109
 110
 111 def parseExternalStats(value):
 112     """Parse event3 (external allocation stats)"""
 113     value = int(value)
 114
 115     # Report the current external allocation stats and the native heap
 116     # summary.
 117     #
 118     # [63-48] Reserved; must be zero (TODO: put new data in these slots)
 119     # [47-36] dlmalloc_footprint
 120     # [35-24] mallinfo: total allocated space
 121     # [23-12] External byte limit
 122     # [11- 0] External bytes allocated
 123     footprint = unfloat12((value >> 36) & 0xfff)    # currently disabled
 124     total = unfloat12((value >> 24) & 0xfff)        # currently disabled
 125     limit = unfloat12((value >> 12) & 0xfff)
 126     bytes = unfloat12(value & 0xfff)
 127
 128     return ( footprint, total, limit, bytes )
 129
 130
 131 def handleGcInfo(timestamp, pid, values):
 132     """Handle a single dvm_gc_info event"""
 133
 134     pid = int(pid)
 135
 136     global_info = parseGlobalInfo(values[0])
 137     heap_stats = parseAggHeapStats(values[1])
 138     zygote = parseZygoteStats(values[2])
 139     external = parseExternalStats(values[3])
 140
 141     debug = False
 142     if debug:
 143         print "RAW: %s %s (%s,%s,%s,%s)" % \
 144                 (timestamp, pid, values[0], values[1], values[2], values[3])
 145
 146         print "> id=\"%s\" time=%d freed=%d" % (global_info[0], global_info[1], global_info[2])
 147         print ">  freed=%d foot=%d allow=%d objs=%d bytes=%d" % \
 148                 (heap_stats[0], heap_stats[1], heap_stats[2], heap_stats[3], heap_stats[4])
 149         print ">  soft=%d act=%d allow=%d objs=%d bytes=%d" % \
 150                 (zygote[0], zygote[1], zygote[2], zygote[3], zygote[4])
 151         print ">  foot=%d total=%d limit=%d alloc=%d" % \
 152                 (external[0], external[1], external[2], external[3])
 153
 154     print "%s %s(%d) softlim=%dKB, extlim=%dKB, extalloc=%dKB" % \
 155             (timestamp, global_info[0], pid, zygote[0]/1024, external[2]/1024, external[3]/1024)
 156     print "  freed %d objects / %d bytes in %dms" % \
 157             (heap_stats[0], global_info[2], global_info[1])
 158
 159
 160 def filterInput(logPipe):
 161     """Loop until EOF, pulling out GC events"""
 162
 163     # 04-29 20:31:00.334 I/dvm_gc_info(   69): [8320808730292729543,-8916699241518090181,-4006371297196337158,8165229]
 164     gc_info_re = re.compile(r"""
 165         (\d+-\d+\ \d+:\d+:\d+)\.\d+     # extract the date (#1), ignoring ms
 166         .*                              # filler, usually " I/"
 167         dvm_gc_info                     # only interested in GC info lines
 168         \(\s*(\d+)\)                    # extract the pid (#2)
 169         :\ \[                           # filler
 170         ([0-9-]+),([0-9-]+),([0-9-]+),([0-9-]+) # four values, may be negative
 171         \].*                            # junk to end of line
 172         """, re.VERBOSE)
 173
 174     while True:
 175         line = logPipe.readline()
 176         if not line:
 177             print "EOF hit"
 178             return
 179
 180         match = gc_info_re.match(line)
 181         if not match:
 182             #print "no match on %s" % line.strip()
 183             continue
 184         else:
 185             handleGcInfo(match.group(1), match.group(2), ( match.group(3), \
 186                     match.group(4), match.group(5), match.group(6) ) )
 187
 188 def start():
 189     """Entry point"""
 190
 191     # launch a logcat and read from it
 192     command = 'adb logcat -v time -b events'
 193     logPipe = os.popen(command)
 194
 195     try:
 196         filterInput(logPipe)
 197     except KeyboardInterrupt, err:
 198         print "Stopping on keyboard interrupt."
 199
 200     logPipe.close()
 201
 202
 203 start()
 204