51b494d096
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@5921 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
956 lines
31 KiB
Python
Executable File
956 lines
31 KiB
Python
Executable File
#!/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()
|