| #!/usr/bin/env python |
| # |
| # Copyright 2010 the V8 project authors. All rights reserved. |
| # Redistribution and use in source and binary forms, with or without |
| # modification, are permitted provided that the following conditions are |
| # met: |
| # |
| # * Redistributions of source code must retain the above copyright |
| # notice, this list of conditions and the following disclaimer. |
| # * Redistributions in binary form must reproduce the above |
| # copyright notice, this list of conditions and the following |
| # disclaimer in the documentation and/or other materials provided |
| # with the distribution. |
| # * Neither the name of Google Inc. nor the names of its |
| # contributors may be used to endorse or promote products derived |
| # from this software without specific prior written permission. |
| # |
| # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS |
| # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT |
| # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR |
| # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT |
| # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, |
| # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT |
| # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, |
| # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY |
| # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT |
| # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE |
| # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. |
| |
| import bisect |
| import collections |
| import ctypes |
| import mmap |
| import optparse |
| import os |
| import re |
| import subprocess |
| import sys |
| import tempfile |
| import time |
| |
| |
| USAGE="""usage: %prog [OPTION]... |
| |
| Analyses V8 and perf logs to produce profiles. |
| |
| Perf logs can be collected using a command like: |
| $ perf record -R -e cycles -c 10000 -f -i ./shell bench.js --ll-prof |
| # -R: collect all data |
| # -e cycles: use cpu-cycles event (run "perf list" for details) |
| # -c 10000: write a sample after each 10000 events |
| # -f: force output file overwrite |
| # -i: limit profiling to our process and the kernel |
| # --ll-prof shell flag enables the right V8 logs |
| This will produce a binary trace file (perf.data) that %prog can analyse. |
| |
| Examples: |
| # Print flat profile with annotated disassembly for the 10 top |
| # symbols. Use default log names and include the snapshot log. |
| $ %prog --snapshot --disasm-top=10 |
| |
| # Print flat profile with annotated disassembly for all used symbols. |
| # Use default log names and include kernel symbols into analysis. |
| $ %prog --disasm-all --kernel |
| |
| # Print flat profile. Use custom log names. |
| $ %prog --log=foo.log --snapshot-log=snap-foo.log --trace=foo.data --snapshot |
| """ |
| |
| |
| # Must match kGcFakeMmap. |
| V8_GC_FAKE_MMAP = "/tmp/__v8_gc__" |
| |
| JS_ORIGIN = "js" |
| JS_SNAPSHOT_ORIGIN = "js-snapshot" |
| |
| # Avoid using the slow (google-specific) wrapper around objdump. |
| OBJDUMP_BIN = "/usr/bin/objdump" |
| if not os.path.exists(OBJDUMP_BIN): |
| OBJDUMP_BIN = "objdump" |
| |
| |
| class Code(object): |
| """Code object.""" |
| |
| _COMMON_DISASM_OPTIONS = ["-M", "intel-mnemonic", "-C"] |
| |
| _DISASM_HEADER_RE = re.compile(r"[a-f0-9]+\s+<.*:$") |
| _DISASM_LINE_RE = re.compile(r"\s*([a-f0-9]+):.*") |
| |
| # Keys must match constants in Logger::LogCodeInfo. |
| _ARCH_MAP = { |
| "ia32": "-m i386", |
| "x64": "-m i386 -M x86-64", |
| "arm": "-m arm" # Not supported by our objdump build. |
| } |
| |
| _id = 0 |
| |
| def __init__(self, name, start_address, end_address, origin, origin_offset): |
| self.id = Code._id |
| Code._id += 1 |
| self.name = name |
| self.other_names = None |
| self.start_address = start_address |
| self.end_address = end_address |
| self.origin = origin |
| self.origin_offset = origin_offset |
| self.self_ticks = 0 |
| self.self_ticks_map = None |
| self.callee_ticks = None |
| |
| def AddName(self, name): |
| assert self.name != name |
| if self.other_names is None: |
| self.other_names = [name] |
| return |
| if not name in self.other_names: |
| self.other_names.append(name) |
| |
| def FullName(self): |
| if self.other_names is None: |
| return self.name |
| self.other_names.sort() |
| return "%s (aka %s)" % (self.name, ", ".join(self.other_names)) |
| |
| def IsUsed(self): |
| return self.self_ticks > 0 or self.callee_ticks is not None |
| |
| def Tick(self, pc): |
| self.self_ticks += 1 |
| if self.self_ticks_map is None: |
| self.self_ticks_map = collections.defaultdict(lambda: 0) |
| offset = pc - self.start_address |
| self.self_ticks_map[offset] += 1 |
| |
| def CalleeTick(self, callee): |
| if self.callee_ticks is None: |
| self.callee_ticks = collections.defaultdict(lambda: 0) |
| self.callee_ticks[callee] += 1 |
| |
| def PrintAnnotated(self, code_info, options): |
| if self.self_ticks_map is None: |
| ticks_map = [] |
| else: |
| ticks_map = self.self_ticks_map.items() |
| # Convert the ticks map to offsets and counts arrays so that later |
| # we can do binary search in the offsets array. |
| ticks_map.sort(key=lambda t: t[0]) |
| ticks_offsets = [t[0] for t in ticks_map] |
| ticks_counts = [t[1] for t in ticks_map] |
| # Get a list of disassembled lines and their addresses. |
| lines = [] |
| for line in self._GetDisasmLines(code_info, options): |
| match = Code._DISASM_LINE_RE.match(line) |
| if match: |
| line_address = int(match.group(1), 16) |
| lines.append((line_address, line)) |
| if len(lines) == 0: |
| return |
| # Print annotated lines. |
| address = lines[0][0] |
| total_count = 0 |
| for i in xrange(len(lines)): |
| start_offset = lines[i][0] - address |
| if i == len(lines) - 1: |
| end_offset = self.end_address - self.start_address |
| else: |
| end_offset = lines[i + 1][0] - address |
| # Ticks (reported pc values) are not always precise, i.e. not |
| # necessarily point at instruction starts. So we have to search |
| # for ticks that touch the current instruction line. |
| j = bisect.bisect_left(ticks_offsets, end_offset) |
| count = 0 |
| for offset, cnt in reversed(zip(ticks_offsets[:j], ticks_counts[:j])): |
| if offset < start_offset: |
| break |
| count += cnt |
| total_count += count |
| count = 100.0 * count / self.self_ticks |
| if count >= 0.01: |
| print "%15.2f %s" % (count, lines[i][1]) |
| else: |
| print "%s %s" % (" " * 15, lines[i][1]) |
| print |
| assert total_count == self.self_ticks, \ |
| "Lost ticks (%d != %d) in %s" % (total_count, self.self_ticks, self) |
| |
| def __str__(self): |
| return "%s [0x%x, 0x%x) size: %d origin: %s" % ( |
| self.name, |
| self.start_address, |
| self.end_address, |
| self.end_address - self.start_address, |
| self.origin) |
| |
| def _GetDisasmLines(self, code_info, options): |
| tmp_name = None |
| if self.origin == JS_ORIGIN or self.origin == JS_SNAPSHOT_ORIGIN: |
| assert code_info.arch in Code._ARCH_MAP, \ |
| "Unsupported architecture '%s'" % arch |
| arch_flags = Code._ARCH_MAP[code_info.arch] |
| # Create a temporary file just with this code object. |
| tmp_name = tempfile.mktemp(".v8code") |
| size = self.end_address - self.start_address |
| command = "dd if=%s.code of=%s bs=1 count=%d skip=%d && " \ |
| "%s %s -D -b binary %s %s" % ( |
| options.log, tmp_name, size, self.origin_offset, |
| OBJDUMP_BIN, ' '.join(Code._COMMON_DISASM_OPTIONS), arch_flags, |
| tmp_name) |
| else: |
| command = "%s %s --start-address=%d --stop-address=%d -d %s " % ( |
| OBJDUMP_BIN, ' '.join(Code._COMMON_DISASM_OPTIONS), |
| self.origin_offset, |
| self.origin_offset + self.end_address - self.start_address, |
| self.origin) |
| process = subprocess.Popen(command, |
| shell=True, |
| stdout=subprocess.PIPE, |
| stderr=subprocess.STDOUT) |
| out, err = process.communicate() |
| lines = out.split("\n") |
| header_line = 0 |
| for i, line in enumerate(lines): |
| if Code._DISASM_HEADER_RE.match(line): |
| header_line = i |
| break |
| if tmp_name: |
| os.unlink(tmp_name) |
| return lines[header_line + 1:] |
| |
| |
| class CodePage(object): |
| """Group of adjacent code objects.""" |
| |
| SHIFT = 12 # 4K pages |
| SIZE = (1 << SHIFT) |
| MASK = ~(SIZE - 1) |
| |
| @staticmethod |
| def PageAddress(address): |
| return address & CodePage.MASK |
| |
| @staticmethod |
| def PageId(address): |
| return address >> CodePage.SHIFT |
| |
| @staticmethod |
| def PageAddressFromId(id): |
| return id << CodePage.SHIFT |
| |
| def __init__(self, address): |
| self.address = address |
| self.code_objects = [] |
| |
| def Add(self, code): |
| self.code_objects.append(code) |
| |
| def Remove(self, code): |
| self.code_objects.remove(code) |
| |
| def Find(self, pc): |
| code_objects = self.code_objects |
| for i, code in enumerate(code_objects): |
| if code.start_address <= pc < code.end_address: |
| code_objects[0], code_objects[i] = code, code_objects[0] |
| return code |
| return None |
| |
| def __iter__(self): |
| return self.code_objects.__iter__() |
| |
| |
| class CodeMap(object): |
| """Code object map.""" |
| |
| def __init__(self): |
| self.pages = {} |
| self.min_address = 1 << 64 |
| self.max_address = -1 |
| |
| def Add(self, code, max_pages=-1): |
| page_id = CodePage.PageId(code.start_address) |
| limit_id = CodePage.PageId(code.end_address + CodePage.SIZE - 1) |
| pages = 0 |
| while page_id < limit_id: |
| if max_pages >= 0 and pages > max_pages: |
| print >>sys.stderr, \ |
| "Warning: page limit (%d) reached for %s [%s]" % ( |
| max_pages, code.name, code.origin) |
| break |
| if page_id in self.pages: |
| page = self.pages[page_id] |
| else: |
| page = CodePage(CodePage.PageAddressFromId(page_id)) |
| self.pages[page_id] = page |
| page.Add(code) |
| page_id += 1 |
| pages += 1 |
| self.min_address = min(self.min_address, code.start_address) |
| self.max_address = max(self.max_address, code.end_address) |
| |
| def Remove(self, code): |
| page_id = CodePage.PageId(code.start_address) |
| limit_id = CodePage.PageId(code.end_address + CodePage.SIZE - 1) |
| removed = False |
| while page_id < limit_id: |
| if page_id not in self.pages: |
| page_id += 1 |
| continue |
| page = self.pages[page_id] |
| page.Remove(code) |
| removed = True |
| page_id += 1 |
| return removed |
| |
| def AllCode(self): |
| for page in self.pages.itervalues(): |
| for code in page: |
| if CodePage.PageAddress(code.start_address) == page.address: |
| yield code |
| |
| def UsedCode(self): |
| for code in self.AllCode(): |
| if code.IsUsed(): |
| yield code |
| |
| def Print(self): |
| for code in self.AllCode(): |
| print code |
| |
| def Find(self, pc): |
| if pc < self.min_address or pc >= self.max_address: |
| return None |
| page_id = CodePage.PageId(pc) |
| if page_id not in self.pages: |
| return None |
| return self.pages[page_id].Find(pc) |
| |
| |
| class CodeInfo(object): |
| """Generic info about generated code objects.""" |
| |
| def __init__(self, arch, header_size): |
| self.arch = arch |
| self.header_size = header_size |
| |
| |
| class CodeLogReader(object): |
| """V8 code event log reader.""" |
| |
| _CODE_INFO_RE = re.compile( |
| r"code-info,([^,]+),(\d+)") |
| |
| _CODE_CREATE_RE = re.compile( |
| r"code-creation,([^,]+),(0x[a-f0-9]+),(\d+),\"(.*)\"(?:,(\d+))?") |
| |
| _CODE_MOVE_RE = re.compile( |
| r"code-move,(0x[a-f0-9]+),(0x[a-f0-9]+)") |
| |
| _CODE_DELETE_RE = re.compile( |
| r"code-delete,(0x[a-f0-9]+)") |
| |
| _SNAPSHOT_POS_RE = re.compile( |
| r"snapshot-pos,(0x[a-f0-9]+),(\d+)") |
| |
| _CODE_MOVING_GC = "code-moving-gc" |
| |
| def __init__(self, log_name, code_map, is_snapshot, snapshot_pos_to_name): |
| self.log = open(log_name, "r") |
| self.code_map = code_map |
| self.is_snapshot = is_snapshot |
| self.snapshot_pos_to_name = snapshot_pos_to_name |
| self.address_to_snapshot_name = {} |
| |
| def ReadCodeInfo(self): |
| line = self.log.readline() or "" |
| match = CodeLogReader._CODE_INFO_RE.match(line) |
| assert match, "No code info in log" |
| return CodeInfo(arch=match.group(1), header_size=int(match.group(2))) |
| |
| def ReadUpToGC(self, code_info): |
| made_progress = False |
| code_header_size = code_info.header_size |
| while True: |
| line = self.log.readline() |
| if not line: |
| return made_progress |
| made_progress = True |
| |
| if line.startswith(CodeLogReader._CODE_MOVING_GC): |
| self.address_to_snapshot_name.clear() |
| return made_progress |
| |
| match = CodeLogReader._CODE_CREATE_RE.match(line) |
| if match: |
| start_address = int(match.group(2), 16) + code_header_size |
| end_address = start_address + int(match.group(3)) - code_header_size |
| if start_address in self.address_to_snapshot_name: |
| name = self.address_to_snapshot_name[start_address] |
| origin = JS_SNAPSHOT_ORIGIN |
| else: |
| name = "%s:%s" % (match.group(1), match.group(4)) |
| origin = JS_ORIGIN |
| if self.is_snapshot: |
| origin_offset = 0 |
| else: |
| origin_offset = int(match.group(5)) |
| code = Code(name, start_address, end_address, origin, origin_offset) |
| conficting_code = self.code_map.Find(start_address) |
| if conficting_code: |
| CodeLogReader._HandleCodeConflict(conficting_code, code) |
| # TODO(vitalyr): this warning is too noisy because of our |
| # attempts to reconstruct code log from the snapshot. |
| # print >>sys.stderr, \ |
| # "Warning: Skipping duplicate code log entry %s" % code |
| continue |
| self.code_map.Add(code) |
| continue |
| |
| match = CodeLogReader._CODE_MOVE_RE.match(line) |
| if match: |
| old_start_address = int(match.group(1), 16) + code_header_size |
| new_start_address = int(match.group(2), 16) + code_header_size |
| if old_start_address == new_start_address: |
| # Skip useless code move entries. |
| continue |
| code = self.code_map.Find(old_start_address) |
| if not code: |
| print >>sys.stderr, "Warning: Not found %x" % old_start_address |
| continue |
| assert code.start_address == old_start_address, \ |
| "Inexact move address %x for %s" % (old_start_address, code) |
| self.code_map.Remove(code) |
| size = code.end_address - code.start_address |
| code.start_address = new_start_address |
| code.end_address = new_start_address + size |
| self.code_map.Add(code) |
| continue |
| |
| match = CodeLogReader._CODE_DELETE_RE.match(line) |
| if match: |
| old_start_address = int(match.group(1), 16) + code_header_size |
| code = self.code_map.Find(old_start_address) |
| if not code: |
| print >>sys.stderr, "Warning: Not found %x" % old_start_address |
| continue |
| assert code.start_address == old_start_address, \ |
| "Inexact delete address %x for %s" % (old_start_address, code) |
| self.code_map.Remove(code) |
| continue |
| |
| match = CodeLogReader._SNAPSHOT_POS_RE.match(line) |
| if match: |
| start_address = int(match.group(1), 16) + code_header_size |
| snapshot_pos = int(match.group(2)) |
| if self.is_snapshot: |
| code = self.code_map.Find(start_address) |
| if code: |
| assert code.start_address == start_address, \ |
| "Inexact snapshot address %x for %s" % (start_address, code) |
| self.snapshot_pos_to_name[snapshot_pos] = code.name |
| else: |
| if snapshot_pos in self.snapshot_pos_to_name: |
| self.address_to_snapshot_name[start_address] = \ |
| self.snapshot_pos_to_name[snapshot_pos] |
| |
| def Dispose(self): |
| self.log.close() |
| |
| @staticmethod |
| def _HandleCodeConflict(old_code, new_code): |
| assert (old_code.start_address == new_code.start_address and |
| old_code.end_address == new_code.end_address), \ |
| "Conficting code log entries %s and %s" % (old_code, new_code) |
| CodeLogReader._UpdateNames(old_code, new_code) |
| |
| @staticmethod |
| def _UpdateNames(old_code, new_code): |
| if old_code.name == new_code.name: |
| return |
| # Kludge: there are code objects with custom names that don't |
| # match their flags. |
| misnamed_code = set(["Builtin:CpuFeatures::Probe"]) |
| if old_code.name in misnamed_code: |
| return |
| # Code object may be shared by a few functions. Collect the full |
| # set of names. |
| old_code.AddName(new_code.name) |
| |
| |
| class Descriptor(object): |
| """Descriptor of a structure in the binary trace log.""" |
| |
| CTYPE_MAP = { |
| "u16": ctypes.c_uint16, |
| "u32": ctypes.c_uint32, |
| "u64": ctypes.c_uint64 |
| } |
| |
| def __init__(self, fields): |
| class TraceItem(ctypes.Structure): |
| _fields_ = Descriptor.CtypesFields(fields) |
| |
| def __str__(self): |
| return ", ".join("%s: %s" % (field, self.__getattribute__(field)) |
| for field, _ in TraceItem._fields_) |
| |
| self.ctype = TraceItem |
| |
| def Read(self, trace, offset): |
| return self.ctype.from_buffer(trace, offset) |
| |
| @staticmethod |
| def CtypesFields(fields): |
| return [(field, Descriptor.CTYPE_MAP[format]) for (field, format) in fields] |
| |
| |
| # Please see http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=tree;f=tools/perf |
| # for the gory details. |
| |
| |
| TRACE_HEADER_DESC = Descriptor([ |
| ("magic", "u64"), |
| ("size", "u64"), |
| ("attr_size", "u64"), |
| ("attrs_offset", "u64"), |
| ("attrs_size", "u64"), |
| ("data_offset", "u64"), |
| ("data_size", "u64"), |
| ("event_types_offset", "u64"), |
| ("event_types_size", "u64") |
| ]) |
| |
| |
| PERF_EVENT_ATTR_DESC = Descriptor([ |
| ("type", "u32"), |
| ("size", "u32"), |
| ("config", "u64"), |
| ("sample_period_or_freq", "u64"), |
| ("sample_type", "u64"), |
| ("read_format", "u64"), |
| ("flags", "u64"), |
| ("wakeup_events_or_watermark", "u32"), |
| ("bt_type", "u32"), |
| ("bp_addr", "u64"), |
| ("bp_len", "u64"), |
| ]) |
| |
| |
| PERF_EVENT_HEADER_DESC = Descriptor([ |
| ("type", "u32"), |
| ("misc", "u16"), |
| ("size", "u16") |
| ]) |
| |
| |
| PERF_MMAP_EVENT_BODY_DESC = Descriptor([ |
| ("pid", "u32"), |
| ("tid", "u32"), |
| ("addr", "u64"), |
| ("len", "u64"), |
| ("pgoff", "u64") |
| ]) |
| |
| |
| # perf_event_attr.sample_type bits control the set of |
| # perf_sample_event fields. |
| PERF_SAMPLE_IP = 1 << 0 |
| PERF_SAMPLE_TID = 1 << 1 |
| PERF_SAMPLE_TIME = 1 << 2 |
| PERF_SAMPLE_ADDR = 1 << 3 |
| PERF_SAMPLE_READ = 1 << 4 |
| PERF_SAMPLE_CALLCHAIN = 1 << 5 |
| PERF_SAMPLE_ID = 1 << 6 |
| PERF_SAMPLE_CPU = 1 << 7 |
| PERF_SAMPLE_PERIOD = 1 << 8 |
| PERF_SAMPLE_STREAM_ID = 1 << 9 |
| PERF_SAMPLE_RAW = 1 << 10 |
| |
| |
| PERF_SAMPLE_EVENT_BODY_FIELDS = [ |
| ("ip", "u64", PERF_SAMPLE_IP), |
| ("pid", "u32", PERF_SAMPLE_TID), |
| ("tid", "u32", PERF_SAMPLE_TID), |
| ("time", "u64", PERF_SAMPLE_TIME), |
| ("addr", "u64", PERF_SAMPLE_ADDR), |
| ("id", "u64", PERF_SAMPLE_ID), |
| ("stream_id", "u64", PERF_SAMPLE_STREAM_ID), |
| ("cpu", "u32", PERF_SAMPLE_CPU), |
| ("res", "u32", PERF_SAMPLE_CPU), |
| ("period", "u64", PERF_SAMPLE_PERIOD), |
| # Don't want to handle read format that comes after the period and |
| # before the callchain and has variable size. |
| ("nr", "u64", PERF_SAMPLE_CALLCHAIN) |
| # Raw data follows the callchain and is ignored. |
| ] |
| |
| |
| PERF_SAMPLE_EVENT_IP_FORMAT = "u64" |
| |
| |
| PERF_RECORD_MMAP = 1 |
| PERF_RECORD_SAMPLE = 9 |
| |
| |
| class TraceReader(object): |
| """Perf (linux-2.6/tools/perf) trace file reader.""" |
| |
| _TRACE_HEADER_MAGIC = 4993446653023372624 |
| |
| def __init__(self, trace_name): |
| self.trace_file = open(trace_name, "r") |
| self.trace = mmap.mmap(self.trace_file.fileno(), 0, mmap.MAP_PRIVATE) |
| self.trace_header = TRACE_HEADER_DESC.Read(self.trace, 0) |
| if self.trace_header.magic != TraceReader._TRACE_HEADER_MAGIC: |
| print >>sys.stderr, "Warning: unsupported trace header magic" |
| self.offset = self.trace_header.data_offset |
| self.limit = self.trace_header.data_offset + self.trace_header.data_size |
| assert self.limit <= self.trace.size(), \ |
| "Trace data limit exceeds trace file size" |
| self.header_size = ctypes.sizeof(PERF_EVENT_HEADER_DESC.ctype) |
| assert self.trace_header.attrs_size != 0, \ |
| "No perf event attributes found in the trace" |
| perf_event_attr = PERF_EVENT_ATTR_DESC.Read(self.trace, |
| self.trace_header.attrs_offset) |
| self.sample_event_body_desc = self._SampleEventBodyDesc( |
| perf_event_attr.sample_type) |
| self.callchain_supported = \ |
| (perf_event_attr.sample_type & PERF_SAMPLE_CALLCHAIN) != 0 |
| if self.callchain_supported: |
| self.ip_struct = Descriptor.CTYPE_MAP[PERF_SAMPLE_EVENT_IP_FORMAT] |
| self.ip_size = ctypes.sizeof(self.ip_struct) |
| |
| def ReadEventHeader(self): |
| if self.offset >= self.limit: |
| return None, 0 |
| offset = self.offset |
| header = PERF_EVENT_HEADER_DESC.Read(self.trace, self.offset) |
| self.offset += header.size |
| return header, offset |
| |
| def ReadMmap(self, header, offset): |
| mmap_info = PERF_MMAP_EVENT_BODY_DESC.Read(self.trace, |
| offset + self.header_size) |
| # Read null-padded filename. |
| filename = self.trace[offset + self.header_size + ctypes.sizeof(mmap_info): |
| offset + header.size].rstrip(chr(0)) |
| mmap_info.filename = filename |
| return mmap_info |
| |
| def ReadSample(self, header, offset): |
| sample = self.sample_event_body_desc.Read(self.trace, |
| offset + self.header_size) |
| if not self.callchain_supported: |
| return sample |
| sample.ips = [] |
| offset += self.header_size + ctypes.sizeof(sample) |
| for _ in xrange(sample.nr): |
| sample.ips.append( |
| self.ip_struct.from_buffer(self.trace, offset).value) |
| offset += self.ip_size |
| return sample |
| |
| def Dispose(self): |
| self.trace.close() |
| self.trace_file.close() |
| |
| def _SampleEventBodyDesc(self, sample_type): |
| assert (sample_type & PERF_SAMPLE_READ) == 0, \ |
| "Can't hande read format in samples" |
| fields = [(field, format) |
| for (field, format, bit) in PERF_SAMPLE_EVENT_BODY_FIELDS |
| if (bit & sample_type) != 0] |
| return Descriptor(fields) |
| |
| |
| OBJDUMP_SECTION_HEADER_RE = re.compile( |
| r"^\s*\d+\s(\.\S+)\s+[a-f0-9]") |
| OBJDUMP_SYMBOL_LINE_RE = re.compile( |
| r"^([a-f0-9]+)\s(.{7})\s(\S+)\s+([a-f0-9]+)\s+(?:\.hidden\s+)?(.*)$") |
| OBJDUMP_DYNAMIC_SYMBOLS_START_RE = re.compile( |
| r"^DYNAMIC SYMBOL TABLE") |
| KERNEL_ALLSYMS_FILE = "/proc/kallsyms" |
| PERF_KERNEL_ALLSYMS_RE = re.compile( |
| r".*kallsyms.*") |
| KERNEL_ALLSYMS_LINE_RE = re.compile( |
| r"^([a-f0-9]+)\s(?:t|T)\s(\S+)$") |
| |
| |
| class LibraryRepo(object): |
| def __init__(self): |
| self.infos = [] |
| self.names = set() |
| self.ticks = {} |
| |
| def Load(self, mmap_info, code_map, options): |
| # Skip kernel mmaps when requested using the fact that their tid |
| # is 0. |
| if mmap_info.tid == 0 and not options.kernel: |
| return True |
| if PERF_KERNEL_ALLSYMS_RE.match(mmap_info.filename): |
| return self._LoadKernelSymbols(code_map) |
| self.infos.append(mmap_info) |
| mmap_info.ticks = 0 |
| mmap_info.unique_name = self._UniqueMmapName(mmap_info) |
| if not os.path.exists(mmap_info.filename): |
| return True |
| # Request section headers (-h), symbols (-t), and dynamic symbols |
| # (-T) from objdump. |
| # Unfortunately, section headers span two lines, so we have to |
| # keep the just seen section name (from the first line in each |
| # section header) in the after_section variable. |
| process = subprocess.Popen( |
| "%s -h -t -T -C %s" % (OBJDUMP_BIN, mmap_info.filename), |
| shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT) |
| pipe = process.stdout |
| after_section = None |
| code_sections = set() |
| reloc_sections = set() |
| dynamic = False |
| try: |
| for line in pipe: |
| if after_section: |
| if line.find("CODE") != -1: |
| code_sections.add(after_section) |
| if line.find("RELOC") != -1: |
| reloc_sections.add(after_section) |
| after_section = None |
| continue |
| |
| match = OBJDUMP_SECTION_HEADER_RE.match(line) |
| if match: |
| after_section = match.group(1) |
| continue |
| |
| if OBJDUMP_DYNAMIC_SYMBOLS_START_RE.match(line): |
| dynamic = True |
| continue |
| |
| match = OBJDUMP_SYMBOL_LINE_RE.match(line) |
| if match: |
| start_address = int(match.group(1), 16) |
| origin_offset = start_address |
| flags = match.group(2) |
| section = match.group(3) |
| if section in code_sections: |
| if dynamic or section in reloc_sections: |
| start_address += mmap_info.addr |
| size = int(match.group(4), 16) |
| name = match.group(5) |
| origin = mmap_info.filename |
| code_map.Add(Code(name, start_address, start_address + size, |
| origin, origin_offset)) |
| finally: |
| pipe.close() |
| assert process.wait() == 0, "Failed to objdump %s" % mmap_info.filename |
| |
| def Tick(self, pc): |
| for i, mmap_info in enumerate(self.infos): |
| if mmap_info.addr <= pc < (mmap_info.addr + mmap_info.len): |
| mmap_info.ticks += 1 |
| self.infos[0], self.infos[i] = mmap_info, self.infos[0] |
| return True |
| return False |
| |
| def _UniqueMmapName(self, mmap_info): |
| name = mmap_info.filename |
| index = 1 |
| while name in self.names: |
| name = "%s-%d" % (mmap_info.filename, index) |
| index += 1 |
| self.names.add(name) |
| return name |
| |
| def _LoadKernelSymbols(self, code_map): |
| if not os.path.exists(KERNEL_ALLSYMS_FILE): |
| print >>sys.stderr, "Warning: %s not found" % KERNEL_ALLSYMS_FILE |
| return False |
| kallsyms = open(KERNEL_ALLSYMS_FILE, "r") |
| code = None |
| for line in kallsyms: |
| match = KERNEL_ALLSYMS_LINE_RE.match(line) |
| if match: |
| start_address = int(match.group(1), 16) |
| end_address = start_address |
| name = match.group(2) |
| if code: |
| code.end_address = start_address |
| code_map.Add(code, 16) |
| code = Code(name, start_address, end_address, "kernel", 0) |
| return True |
| |
| |
| def PrintReport(code_map, library_repo, code_info, options): |
| print "Ticks per symbol:" |
| used_code = [code for code in code_map.UsedCode()] |
| used_code.sort(key=lambda x: x.self_ticks, reverse=True) |
| for i, code in enumerate(used_code): |
| print "%10d %s [%s]" % (code.self_ticks, code.FullName(), code.origin) |
| if options.disasm_all or i < options.disasm_top: |
| code.PrintAnnotated(code_info, options) |
| print |
| print "Ticks per library:" |
| mmap_infos = [m for m in library_repo.infos] |
| mmap_infos.sort(key=lambda m: m.ticks, reverse=True) |
| for mmap_info in mmap_infos: |
| print "%10d %s" % (mmap_info.ticks, mmap_info.unique_name) |
| |
| |
| def PrintDot(code_map, options): |
| print "digraph G {" |
| for code in code_map.UsedCode(): |
| if code.self_ticks < 10: |
| continue |
| print "n%d [shape=box,label=\"%s\"];" % (code.id, code.name) |
| if code.callee_ticks: |
| for callee, ticks in code.callee_ticks.iteritems(): |
| print "n%d -> n%d [label=\"%d\"];" % (code.id, callee.id, ticks) |
| print "}" |
| |
| |
| if __name__ == "__main__": |
| parser = optparse.OptionParser(USAGE) |
| parser.add_option("--snapshot-log", |
| default="obj/release/snapshot.log", |
| help="V8 snapshot log file name [default: %default]") |
| parser.add_option("--log", |
| default="v8.log", |
| help="V8 log file name [default: %default]") |
| parser.add_option("--snapshot", |
| default=False, |
| action="store_true", |
| help="process V8 snapshot log [default: %default]") |
| parser.add_option("--trace", |
| default="perf.data", |
| help="perf trace file name [default: %default]") |
| parser.add_option("--kernel", |
| default=False, |
| action="store_true", |
| help="process kernel entries [default: %default]") |
| parser.add_option("--disasm-top", |
| default=0, |
| type="int", |
| help=("number of top symbols to disassemble and annotate " |
| "[default: %default]")) |
| parser.add_option("--disasm-all", |
| default=False, |
| action="store_true", |
| help=("disassemble and annotate all used symbols " |
| "[default: %default]")) |
| parser.add_option("--dot", |
| default=False, |
| action="store_true", |
| help="produce dot output (WIP) [default: %default]") |
| parser.add_option("--quiet", "-q", |
| default=False, |
| action="store_true", |
| help="no auxiliary messages [default: %default]") |
| options, args = parser.parse_args() |
| |
| if not options.quiet: |
| if options.snapshot: |
| print "V8 logs: %s, %s, %s.code" % (options.snapshot_log, |
| options.log, |
| options.log) |
| else: |
| print "V8 log: %s, %s.code (no snapshot)" % (options.log, options.log) |
| print "Perf trace file: %s" % options.trace |
| |
| # Stats. |
| events = 0 |
| ticks = 0 |
| missed_ticks = 0 |
| really_missed_ticks = 0 |
| mmap_time = 0 |
| sample_time = 0 |
| |
| # Initialize the log reader and get the code info. |
| code_map = CodeMap() |
| snapshot_name_map = {} |
| log_reader = CodeLogReader(log_name=options.log, |
| code_map=code_map, |
| is_snapshot=False, |
| snapshot_pos_to_name=snapshot_name_map) |
| code_info = log_reader.ReadCodeInfo() |
| if not options.quiet: |
| print "Generated code architecture: %s" % code_info.arch |
| print |
| |
| # Process the snapshot log to fill the snapshot name map. |
| if options.snapshot: |
| snapshot_log_reader = CodeLogReader(log_name=options.snapshot_log, |
| code_map=CodeMap(), |
| is_snapshot=True, |
| snapshot_pos_to_name=snapshot_name_map) |
| while snapshot_log_reader.ReadUpToGC(code_info): |
| pass |
| |
| # Process the code and trace logs. |
| library_repo = LibraryRepo() |
| log_reader.ReadUpToGC(code_info) |
| trace_reader = TraceReader(options.trace) |
| while True: |
| header, offset = trace_reader.ReadEventHeader() |
| if not header: |
| break |
| events += 1 |
| if header.type == PERF_RECORD_MMAP: |
| start = time.time() |
| mmap_info = trace_reader.ReadMmap(header, offset) |
| if mmap_info.filename == V8_GC_FAKE_MMAP: |
| log_reader.ReadUpToGC(code_info) |
| else: |
| library_repo.Load(mmap_info, code_map, options) |
| mmap_time += time.time() - start |
| elif header.type == PERF_RECORD_SAMPLE: |
| ticks += 1 |
| start = time.time() |
| sample = trace_reader.ReadSample(header, offset) |
| code = code_map.Find(sample.ip) |
| if code: |
| code.Tick(sample.ip) |
| else: |
| missed_ticks += 1 |
| if not library_repo.Tick(sample.ip) and not code: |
| really_missed_ticks += 1 |
| if trace_reader.callchain_supported: |
| for ip in sample.ips: |
| caller_code = code_map.Find(ip) |
| if caller_code: |
| if code: |
| caller_code.CalleeTick(code) |
| code = caller_code |
| sample_time += time.time() - start |
| |
| if options.dot: |
| PrintDot(code_map, options) |
| else: |
| PrintReport(code_map, library_repo, code_info, options) |
| |
| if not options.quiet: |
| print |
| print "Stats:" |
| print "%10d total trace events" % events |
| print "%10d total ticks" % ticks |
| print "%10d ticks not in symbols" % missed_ticks |
| print "%10d unaccounted ticks" % really_missed_ticks |
| print "%10d total symbols" % len([c for c in code_map.AllCode()]) |
| print "%10d used symbols" % len([c for c in code_map.UsedCode()]) |
| print "%9.2fs library processing time" % mmap_time |
| print "%9.2fs tick processing time" % sample_time |
| |
| log_reader.Dispose() |
| trace_reader.Dispose() |
