#!/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.
#
# 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 getopt
import sys
import os
import re
import time
DEBUG = False # DEBUG is a global variable
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(procFilter, timestamp, pid, values):
"""Handle a single dvm_gc_info event"""
pid = int(pid)
global_info = parseGlobalInfo(values[0])
if len(procFilter) > 0:
if global_info[0] != procFilter:
return
heap_stats = parseAggHeapStats(values[1])
zygote = parseZygoteStats(values[2])
external = parseExternalStats(values[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)
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 " freed %d objects / %d bytes in %dms" % \
(heap_stats[0], global_info[2], global_info[1])
def filterInput(logPipe, processFilter):
"""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(processFilter, match.group(1), match.group(2), ( match.group(3), \
match.group(4), match.group(5), match.group(6) ) )
def PrintUsage():
print "usage: %s [-p procFilter] [-d]" % sys.argv[0]
def start():
"""Entry point"""
global DEBUG
procFilter = ""
opts, args = getopt.getopt(sys.argv[1:], "hdp:")
for opt, val in opts:
if opt == "-h":
PrintUsage()
sys.exit(2)
elif opt == "-p":
procFilter = val
elif opt == "-d":
DEBUG = True
print "procfilter = %s" % procFilter
print "DEBUG = %s" % DEBUG
# launch a logcat and read from it
command = 'adb logcat -v time -b events'
logPipe = os.popen(command)
try:
filterInput(logPipe, procFilter)
except KeyboardInterrupt, err:
print "Stopping on keyboard interrupt."
logPipe.close()
start()