Script that formats dvm_gc_info lines.
Simple (?) script that parses the dvm_gc_info lines out of the event log
and parses the contents. Mostly useful for displaying the external
allocation "limit" and "allocated" values, which don't really show up
anywhere else.
diff --git a/tools/gclog.py b/tools/gclog.py
new file mode 100755
index 0000000..4696965
--- /dev/null
+++ b/tools/gclog.py
@@ -0,0 +1,204 @@
+#!/usr/bin/env python
+#
+# Copyright (C) 2009 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+#
+# Version 1.0, 29-Apr-2009
+#
+# Parse event log output, looking for GC events. Format them for human
+# consumption.
+#
+# ALL OUTPUT VALUES ARE APPROXIMATE. The event log data format uses a
+# 12-bit floating-point representation, which means there aren't enough
+# bits to accurately represent anything but small integers. Larger
+# values will be rounded off.
+#
+# The data is generated by dalvik/vm/alloc/HeapDebug.c.
+#
+
+import os
+import re
+import time
+
+def unfloat12(f12):
+ """Unpack a float12 value"""
+ if f12 < 0:
+ raise DataParseError, "bad float12 value %s" % f12
+ return (f12 & 0x1ff) << ((f12 >> 9) * 4)
+
+
+def parseGlobalInfo(value):
+ """Parse event0 (global info)"""
+ value = int(value)
+
+ # Global information:
+ #
+ # [63 ] Must be zero
+ # [62-24] ASCII process identifier
+ # [23-12] GC time in ms
+ # [11- 0] Bytes freed
+ id = (value >> 24) & 0xffffffffff
+ gctime = unfloat12((value >> 12) & 0xfff)
+ bytes_freed = unfloat12(value & 0xfff)
+
+ idstr = "%c%c%c%c%c" % ( \
+ (id >> 32) & 0xff, \
+ (id >> 24) & 0xff, \
+ (id >> 16) & 0xff, \
+ (id >> 8) & 0xff, \
+ id & 0xff )
+
+ return ( idstr, gctime, bytes_freed )
+
+
+def parseAggHeapStats(value):
+ """Parse event1 (aggregated heap stats)"""
+ value = int(value)
+
+ # Aggregated heap stats:
+ #
+ # [63-62] 10
+ # [61-60] Reserved; must be zero
+ # [59-48] Objects freed
+ # [47-36] Actual size (current footprint)
+ # [35-24] Allowed size (current hard max)
+ # [23-12] Objects allocated
+ # [11- 0] Bytes allocated
+ freed = unfloat12((value >> 48) & 0xfff)
+ footprint = unfloat12((value >> 36) & 0xfff)
+ allowed = unfloat12((value >> 24) & 0xfff)
+ objs = unfloat12((value >> 12) & 0xfff)
+ bytes = unfloat12(value & 0xfff)
+
+ return ( freed, footprint, allowed, objs, bytes )
+
+
+def parseZygoteStats(value):
+ """Parse event2 (zygote heap stats)"""
+ value = int(value)
+
+ # Zygote heap stats (except for the soft limit, which belongs to the
+ # active heap):
+ #
+ # [63-62] 11
+ # [61-60] Reserved; must be zero
+ # [59-48] Soft Limit (for the active heap)
+ # [47-36] Actual size (current footprint)
+ # [35-24] Allowed size (current hard max)
+ # [23-12] Objects allocated
+ # [11- 0] Bytes allocated
+ soft_limit = unfloat12((value >> 48) & 0xfff)
+ actual = unfloat12((value >> 36) & 0xfff)
+ allowed = unfloat12((value >> 24) & 0xfff)
+ objs = unfloat12((value >> 12) & 0xfff)
+ bytes = unfloat12(value & 0xfff)
+
+ return ( soft_limit, actual, allowed, objs, bytes )
+
+
+def parseExternalStats(value):
+ """Parse event3 (external allocation stats)"""
+ value = int(value)
+
+ # Report the current external allocation stats and the native heap
+ # summary.
+ #
+ # [63-48] Reserved; must be zero (TODO: put new data in these slots)
+ # [47-36] dlmalloc_footprint
+ # [35-24] mallinfo: total allocated space
+ # [23-12] External byte limit
+ # [11- 0] External bytes allocated
+ footprint = unfloat12((value >> 36) & 0xfff) # currently disabled
+ total = unfloat12((value >> 24) & 0xfff) # currently disabled
+ limit = unfloat12((value >> 12) & 0xfff)
+ bytes = unfloat12(value & 0xfff)
+
+ return ( footprint, total, limit, bytes )
+
+
+def handleGcInfo(timestamp, pid, values):
+ """Handle a single dvm_gc_info event"""
+
+ pid = int(pid)
+
+ global_info = parseGlobalInfo(values[0])
+ heap_stats = parseAggHeapStats(values[1])
+ zygote = parseZygoteStats(values[2])
+ external = parseExternalStats(values[3])
+
+ debug = False
+ if debug:
+ print "RAW: %s %s (%s,%s,%s,%s)" % \
+ (timestamp, pid, values[0], values[1], values[2], values[3])
+
+ print "> id=\"%s\" time=%d freed=%d" % (global_info[0], global_info[1], global_info[2])
+ print "> freed=%d foot=%d allow=%d objs=%d bytes=%d" % \
+ (heap_stats[0], heap_stats[1], heap_stats[2], heap_stats[3], heap_stats[4])
+ print "> soft=%d act=%d allow=%d objs=%d bytes=%d" % \
+ (zygote[0], zygote[1], zygote[2], zygote[3], zygote[4])
+ print "> foot=%d total=%d limit=%d alloc=%d" % \
+ (external[0], external[1], external[2], external[3])
+
+ print "%s %s(%d) softlim=%dKB, extlim=%dKB, extalloc=%dKB" % \
+ (timestamp, global_info[0], pid, zygote[0]/1024, external[2]/1024, external[3]/1024)
+ print " freed %d objects / %d bytes in %dms" % \
+ (heap_stats[0], global_info[2], global_info[1])
+
+
+def filterInput(logPipe):
+ """Loop until EOF, pulling out GC events"""
+
+ # 04-29 20:31:00.334 I/dvm_gc_info( 69): [8320808730292729543,-8916699241518090181,-4006371297196337158,8165229]
+ gc_info_re = re.compile(r"""
+ (\d+-\d+\ \d+:\d+:\d+)\.\d+ # extract the date (#1), ignoring ms
+ .* # filler, usually " I/"
+ dvm_gc_info # only interested in GC info lines
+ \(\s*(\d+)\) # extract the pid (#2)
+ :\ \[ # filler
+ ([0-9-]+),([0-9-]+),([0-9-]+),([0-9-]+) # four values, may be negative
+ \].* # junk to end of line
+ """, re.VERBOSE)
+
+ while True:
+ line = logPipe.readline()
+ if not line:
+ print "EOF hit"
+ return
+
+ match = gc_info_re.match(line)
+ if not match:
+ #print "no match on %s" % line.strip()
+ continue
+ else:
+ handleGcInfo(match.group(1), match.group(2), ( match.group(3), \
+ match.group(4), match.group(5), match.group(6) ) )
+
+def start():
+ """Entry point"""
+
+ # launch a logcat and read from it
+ command = 'adb logcat -v time -b events'
+ logPipe = os.popen(command)
+
+ try:
+ filterInput(logPipe)
+ except KeyboardInterrupt, err:
+ print "Stopping on keyboard interrupt."
+
+ logPipe.close()
+
+
+start()
+
