tools/gclog.py

#!/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()