• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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
29import getopt
30import sys
31import os
32import re
33import time
34
35DEBUG = False       # DEBUG is a global variable
36
37
38def 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
45def 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
69def 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
91def 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
114def 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
134def 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
168def 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
196def PrintUsage():
197  print "usage: %s [-p procFilter] [-d]" % sys.argv[0]
198
199
200def 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
234start()
235