aa2c33126c
This is an effort to reuse profiler data processing code both in TickProcessor and Dev Tools Profiler. The old Python implementation will be removed. The new TickProcessor works almost identical to the previous one. However, it has some differences: 1. Not very useful "Call profile" section is replaced with a new WebKit-like "Bottom up (heavy) profile" which shows the most expensive functions together with their callers. I used it personally in order to find and remove bottlenecks in the tickprocessor script itself, and found it quite helpful. 2. Code entries with duplicate names (they occur for RegExes, stubs and sometimes for anonymous Function objects) are now distinguished by adding an occurence number inside curly brackets. 3. (Address -> code entry) mapping is more precise in boundary cases. 4. Windows version no more requires specifying .map file location. 5. Works faster. Review URL: http://codereview.chromium.org/99054 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@1802 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
536 lines
18 KiB
Python
536 lines
18 KiB
Python
# Copyright 2008 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 csv, splaytree, sys, re
|
|
from operator import itemgetter
|
|
import getopt, os, string
|
|
|
|
class CodeEntry(object):
|
|
|
|
def __init__(self, start_addr, name):
|
|
self.start_addr = start_addr
|
|
self.tick_count = 0
|
|
self.name = name
|
|
self.stacks = {}
|
|
|
|
def Tick(self, pc, stack):
|
|
self.tick_count += 1
|
|
if len(stack) > 0:
|
|
stack.insert(0, self.ToString())
|
|
stack_key = tuple(stack)
|
|
self.stacks[stack_key] = self.stacks.setdefault(stack_key, 0) + 1
|
|
|
|
def RegionTicks(self):
|
|
return None
|
|
|
|
def SetStartAddress(self, start_addr):
|
|
self.start_addr = start_addr
|
|
|
|
def ToString(self):
|
|
return self.name
|
|
|
|
def IsSharedLibraryEntry(self):
|
|
return False
|
|
|
|
def IsICEntry(self):
|
|
return False
|
|
|
|
|
|
class SharedLibraryEntry(CodeEntry):
|
|
|
|
def __init__(self, start_addr, name):
|
|
CodeEntry.__init__(self, start_addr, name)
|
|
|
|
def IsSharedLibraryEntry(self):
|
|
return True
|
|
|
|
|
|
class JSCodeEntry(CodeEntry):
|
|
|
|
def __init__(self, start_addr, name, type, size, assembler):
|
|
CodeEntry.__init__(self, start_addr, name)
|
|
self.type = type
|
|
self.size = size
|
|
self.assembler = assembler
|
|
self.region_ticks = None
|
|
self.builtin_ic_re = re.compile('^(Keyed)?(Call|Load|Store)IC_')
|
|
|
|
def Tick(self, pc, stack):
|
|
super(JSCodeEntry, self).Tick(pc, stack)
|
|
if not pc is None:
|
|
offset = pc - self.start_addr
|
|
seen = []
|
|
narrowest = None
|
|
narrowest_width = None
|
|
for region in self.Regions():
|
|
if region.Contains(offset):
|
|
if (not region.name in seen):
|
|
seen.append(region.name)
|
|
if narrowest is None or region.Width() < narrowest.Width():
|
|
narrowest = region
|
|
if len(seen) == 0:
|
|
return
|
|
if self.region_ticks is None:
|
|
self.region_ticks = {}
|
|
for name in seen:
|
|
if not name in self.region_ticks:
|
|
self.region_ticks[name] = [0, 0]
|
|
self.region_ticks[name][0] += 1
|
|
if name == narrowest.name:
|
|
self.region_ticks[name][1] += 1
|
|
|
|
def RegionTicks(self):
|
|
return self.region_ticks
|
|
|
|
def Regions(self):
|
|
if self.assembler:
|
|
return self.assembler.regions
|
|
else:
|
|
return []
|
|
|
|
def ToString(self):
|
|
name = self.name
|
|
if name == '':
|
|
name = '<anonymous>'
|
|
elif name.startswith(' '):
|
|
name = '<anonymous>' + name
|
|
return self.type + ': ' + name
|
|
|
|
def IsICEntry(self):
|
|
return self.type in ('CallIC', 'LoadIC', 'StoreIC') or \
|
|
(self.type == 'Builtin' and self.builtin_ic_re.match(self.name))
|
|
|
|
|
|
class CodeRegion(object):
|
|
|
|
def __init__(self, start_offset, name):
|
|
self.start_offset = start_offset
|
|
self.name = name
|
|
self.end_offset = None
|
|
|
|
def Contains(self, pc):
|
|
return (self.start_offset <= pc) and (pc <= self.end_offset)
|
|
|
|
def Width(self):
|
|
return self.end_offset - self.start_offset
|
|
|
|
|
|
class Assembler(object):
|
|
|
|
def __init__(self):
|
|
# Mapping from region ids to open regions
|
|
self.pending_regions = {}
|
|
self.regions = []
|
|
|
|
|
|
class FunctionEnumerator(object):
|
|
|
|
def __init__(self):
|
|
self.known_funcs = {}
|
|
self.next_func_id = 0
|
|
|
|
def GetFunctionId(self, name):
|
|
if not self.known_funcs.has_key(name):
|
|
self.known_funcs[name] = self.next_func_id
|
|
self.next_func_id += 1
|
|
return self.known_funcs[name]
|
|
|
|
def GetKnownFunctions(self):
|
|
known_funcs_items = self.known_funcs.items();
|
|
known_funcs_items.sort(key = itemgetter(1))
|
|
result = []
|
|
for func, id_not_used in known_funcs_items:
|
|
result.append(func)
|
|
return result
|
|
|
|
|
|
VMStates = { 'JS': 0, 'GC': 1, 'COMPILER': 2, 'OTHER': 3, 'EXTERNAL' : 4 }
|
|
|
|
|
|
class TickProcessor(object):
|
|
|
|
def __init__(self):
|
|
self.log_file = ''
|
|
self.deleted_code = []
|
|
self.vm_extent = {}
|
|
# Map from assembler ids to the pending assembler objects
|
|
self.pending_assemblers = {}
|
|
# Map from code addresses the have been allocated but not yet officially
|
|
# created to their assemblers.
|
|
self.assemblers = {}
|
|
self.js_entries = splaytree.SplayTree()
|
|
self.cpp_entries = splaytree.SplayTree()
|
|
self.total_number_of_ticks = 0
|
|
self.number_of_library_ticks = 0
|
|
self.unaccounted_number_of_ticks = 0
|
|
self.excluded_number_of_ticks = 0
|
|
self.number_of_gc_ticks = 0
|
|
# Flag indicating whether to ignore unaccounted ticks in the report
|
|
self.ignore_unknown = False
|
|
self.func_enum = FunctionEnumerator()
|
|
self.packed_stacks = []
|
|
|
|
def ProcessLogfile(self, filename, included_state = None, ignore_unknown = False, separate_ic = False, call_graph_json = False):
|
|
self.log_file = filename
|
|
self.included_state = included_state
|
|
self.ignore_unknown = ignore_unknown
|
|
self.separate_ic = separate_ic
|
|
self.call_graph_json = call_graph_json
|
|
|
|
try:
|
|
logfile = open(filename, 'rb')
|
|
except IOError:
|
|
sys.exit("Could not open logfile: " + filename)
|
|
try:
|
|
try:
|
|
logreader = csv.reader(logfile)
|
|
row_num = 1
|
|
for row in logreader:
|
|
row_num += 1
|
|
if row[0] == 'tick':
|
|
self.ProcessTick(int(row[1], 16), int(row[2], 16), int(row[3]), self.PreprocessStack(row[4:]))
|
|
elif row[0] == 'code-creation':
|
|
self.ProcessCodeCreation(row[1], int(row[2], 16), int(row[3]), row[4])
|
|
elif row[0] == 'code-move':
|
|
self.ProcessCodeMove(int(row[1], 16), int(row[2], 16))
|
|
elif row[0] == 'code-delete':
|
|
self.ProcessCodeDelete(int(row[1], 16))
|
|
elif row[0] == 'shared-library':
|
|
self.AddSharedLibraryEntry(row[1], int(row[2], 16), int(row[3], 16))
|
|
self.ParseVMSymbols(row[1], int(row[2], 16), int(row[3], 16))
|
|
elif row[0] == 'begin-code-region':
|
|
self.ProcessBeginCodeRegion(int(row[1], 16), int(row[2], 16), int(row[3], 16), row[4])
|
|
elif row[0] == 'end-code-region':
|
|
self.ProcessEndCodeRegion(int(row[1], 16), int(row[2], 16), int(row[3], 16))
|
|
elif row[0] == 'code-allocate':
|
|
self.ProcessCodeAllocate(int(row[1], 16), int(row[2], 16))
|
|
except csv.Error:
|
|
print("parse error in line " + str(row_num))
|
|
raise
|
|
finally:
|
|
logfile.close()
|
|
|
|
def AddSharedLibraryEntry(self, filename, start, end):
|
|
# Mark the pages used by this library.
|
|
i = start
|
|
while i < end:
|
|
page = i >> 12
|
|
self.vm_extent[page] = 1
|
|
i += 4096
|
|
# Add the library to the entries so that ticks for which we do not
|
|
# have symbol information is reported as belonging to the library.
|
|
self.cpp_entries.Insert(start, SharedLibraryEntry(start, filename))
|
|
|
|
def ParseVMSymbols(self, filename, start, end):
|
|
return
|
|
|
|
def ProcessCodeAllocate(self, addr, assem):
|
|
if assem in self.pending_assemblers:
|
|
assembler = self.pending_assemblers.pop(assem)
|
|
self.assemblers[addr] = assembler
|
|
|
|
def ProcessCodeCreation(self, type, addr, size, name):
|
|
if addr in self.assemblers:
|
|
assembler = self.assemblers.pop(addr)
|
|
else:
|
|
assembler = None
|
|
self.js_entries.Insert(addr, JSCodeEntry(addr, name, type, size, assembler))
|
|
|
|
def ProcessCodeMove(self, from_addr, to_addr):
|
|
try:
|
|
removed_node = self.js_entries.Remove(from_addr)
|
|
removed_node.value.SetStartAddress(to_addr);
|
|
self.js_entries.Insert(to_addr, removed_node.value)
|
|
except splaytree.KeyNotFoundError:
|
|
print('Code move event for unknown code: 0x%x' % from_addr)
|
|
|
|
def ProcessCodeDelete(self, from_addr):
|
|
try:
|
|
removed_node = self.js_entries.Remove(from_addr)
|
|
self.deleted_code.append(removed_node.value)
|
|
except splaytree.KeyNotFoundError:
|
|
print('Code delete event for unknown code: 0x%x' % from_addr)
|
|
|
|
def ProcessBeginCodeRegion(self, id, assm, start, name):
|
|
if not assm in self.pending_assemblers:
|
|
self.pending_assemblers[assm] = Assembler()
|
|
assembler = self.pending_assemblers[assm]
|
|
assembler.pending_regions[id] = CodeRegion(start, name)
|
|
|
|
def ProcessEndCodeRegion(self, id, assm, end):
|
|
assm = self.pending_assemblers[assm]
|
|
region = assm.pending_regions.pop(id)
|
|
region.end_offset = end
|
|
assm.regions.append(region)
|
|
|
|
def IncludeTick(self, pc, sp, state):
|
|
return (self.included_state is None) or (self.included_state == state)
|
|
|
|
def FindEntry(self, pc):
|
|
page = pc >> 12
|
|
if page in self.vm_extent:
|
|
entry = self.cpp_entries.FindGreatestsLessThan(pc)
|
|
if entry != None:
|
|
return entry.value
|
|
else:
|
|
return entry
|
|
max = self.js_entries.FindMax()
|
|
min = self.js_entries.FindMin()
|
|
if max != None and pc < (max.key + max.value.size) and pc > min.key:
|
|
return self.js_entries.FindGreatestsLessThan(pc).value
|
|
return None
|
|
|
|
def PreprocessStack(self, stack):
|
|
# remove all non-addresses (e.g. 'overflow') and convert to int
|
|
result = []
|
|
for frame in stack:
|
|
if frame.startswith('0x'):
|
|
result.append(int(frame, 16))
|
|
return result
|
|
|
|
def ProcessStack(self, stack):
|
|
result = []
|
|
for frame in stack:
|
|
entry = self.FindEntry(frame)
|
|
if entry != None:
|
|
result.append(entry.ToString())
|
|
return result
|
|
|
|
def ProcessTick(self, pc, sp, state, stack):
|
|
if state == VMStates['GC']:
|
|
self.number_of_gc_ticks += 1
|
|
if not self.IncludeTick(pc, sp, state):
|
|
self.excluded_number_of_ticks += 1;
|
|
return
|
|
self.total_number_of_ticks += 1
|
|
entry = self.FindEntry(pc)
|
|
if entry == None:
|
|
self.unaccounted_number_of_ticks += 1
|
|
return
|
|
if entry.IsSharedLibraryEntry():
|
|
self.number_of_library_ticks += 1
|
|
if entry.IsICEntry() and not self.separate_ic:
|
|
if len(stack) > 0:
|
|
caller_pc = stack.pop(0)
|
|
self.total_number_of_ticks -= 1
|
|
self.ProcessTick(caller_pc, sp, state, stack)
|
|
else:
|
|
self.unaccounted_number_of_ticks += 1
|
|
else:
|
|
entry.Tick(pc, self.ProcessStack(stack))
|
|
if self.call_graph_json:
|
|
self.AddToPackedStacks(pc, stack)
|
|
|
|
def AddToPackedStacks(self, pc, stack):
|
|
full_stack = stack
|
|
full_stack.insert(0, pc)
|
|
func_names = self.ProcessStack(full_stack)
|
|
func_ids = []
|
|
for func in func_names:
|
|
func_ids.append(self.func_enum.GetFunctionId(func))
|
|
self.packed_stacks.append(func_ids)
|
|
|
|
def PrintResults(self):
|
|
if not self.call_graph_json:
|
|
self.PrintStatistics()
|
|
else:
|
|
self.PrintCallGraphJSON()
|
|
|
|
def PrintStatistics(self):
|
|
print('Statistical profiling result from %s, (%d ticks, %d unaccounted, %d excluded).' %
|
|
(self.log_file,
|
|
self.total_number_of_ticks,
|
|
self.unaccounted_number_of_ticks,
|
|
self.excluded_number_of_ticks))
|
|
if self.total_number_of_ticks > 0:
|
|
js_entries = self.js_entries.ExportValueList()
|
|
js_entries.extend(self.deleted_code)
|
|
cpp_entries = self.cpp_entries.ExportValueList()
|
|
# Print the unknown ticks percentage if they are not ignored.
|
|
if not self.ignore_unknown and self.unaccounted_number_of_ticks > 0:
|
|
self.PrintHeader('Unknown')
|
|
self.PrintCounter(self.unaccounted_number_of_ticks)
|
|
# Print the library ticks.
|
|
self.PrintHeader('Shared libraries')
|
|
self.PrintEntries(cpp_entries, lambda e:e.IsSharedLibraryEntry())
|
|
# Print the JavaScript ticks.
|
|
self.PrintHeader('JavaScript')
|
|
self.PrintEntries(js_entries, lambda e:not e.IsSharedLibraryEntry())
|
|
# Print the C++ ticks.
|
|
self.PrintHeader('C++')
|
|
self.PrintEntries(cpp_entries, lambda e:not e.IsSharedLibraryEntry())
|
|
# Print the GC ticks.
|
|
self.PrintHeader('GC')
|
|
self.PrintCounter(self.number_of_gc_ticks)
|
|
# Print call profile.
|
|
print('\n [Call profile]:')
|
|
print(' total call path')
|
|
js_entries.extend(cpp_entries)
|
|
self.PrintCallProfile(js_entries)
|
|
|
|
def PrintHeader(self, header_title):
|
|
print('\n [%s]:' % header_title)
|
|
print(' ticks total nonlib name')
|
|
|
|
def PrintCounter(self, ticks_count):
|
|
percentage = ticks_count * 100.0 / self.total_number_of_ticks
|
|
print(' %(ticks)5d %(total)5.1f%%' % {
|
|
'ticks' : ticks_count,
|
|
'total' : percentage,
|
|
})
|
|
|
|
def PrintEntries(self, entries, condition):
|
|
# If ignoring unaccounted ticks don't include these in percentage
|
|
# calculations
|
|
number_of_accounted_ticks = self.total_number_of_ticks
|
|
if self.ignore_unknown:
|
|
number_of_accounted_ticks -= self.unaccounted_number_of_ticks
|
|
|
|
number_of_non_library_ticks = number_of_accounted_ticks - self.number_of_library_ticks
|
|
entries.sort(key=lambda e: (e.tick_count, e.ToString()), reverse=True)
|
|
for entry in entries:
|
|
if entry.tick_count > 0 and condition(entry):
|
|
total_percentage = entry.tick_count * 100.0 / number_of_accounted_ticks
|
|
if entry.IsSharedLibraryEntry():
|
|
non_library_percentage = 0
|
|
else:
|
|
non_library_percentage = entry.tick_count * 100.0 / number_of_non_library_ticks
|
|
print(' %(ticks)5d %(total)5.1f%% %(nonlib)6.1f%% %(name)s' % {
|
|
'ticks' : entry.tick_count,
|
|
'total' : total_percentage,
|
|
'nonlib' : non_library_percentage,
|
|
'name' : entry.ToString()
|
|
})
|
|
region_ticks = entry.RegionTicks()
|
|
if not region_ticks is None:
|
|
items = region_ticks.items()
|
|
items.sort(key=lambda e: e[1][1], reverse=True)
|
|
for (name, ticks) in items:
|
|
print(' flat cum')
|
|
print(' %(flat)5.1f%% %(accum)5.1f%% %(name)s' % {
|
|
'flat' : ticks[1] * 100.0 / entry.tick_count,
|
|
'accum' : ticks[0] * 100.0 / entry.tick_count,
|
|
'name': name
|
|
})
|
|
|
|
def PrintCallProfile(self, entries):
|
|
all_stacks = {}
|
|
total_stacks = 0
|
|
for entry in entries:
|
|
all_stacks.update(entry.stacks)
|
|
for count in entry.stacks.itervalues():
|
|
total_stacks += count
|
|
all_stacks_items = all_stacks.items();
|
|
all_stacks_items.sort(key = itemgetter(1), reverse=True)
|
|
missing_percentage = (self.total_number_of_ticks - total_stacks) * 100.0 / self.total_number_of_ticks
|
|
print(' %(ticks)5d %(total)5.1f%% <no call path information>' % {
|
|
'ticks' : self.total_number_of_ticks - total_stacks,
|
|
'total' : missing_percentage
|
|
})
|
|
for stack, count in all_stacks_items:
|
|
total_percentage = count * 100.0 / self.total_number_of_ticks
|
|
print(' %(ticks)5d %(total)5.1f%% %(call_path)s' % {
|
|
'ticks' : count,
|
|
'total' : total_percentage,
|
|
'call_path' : stack[0] + ' <- ' + stack[1]
|
|
})
|
|
|
|
def PrintCallGraphJSON(self):
|
|
print('\nvar __profile_funcs = ["' +
|
|
'",\n"'.join(self.func_enum.GetKnownFunctions()) +
|
|
'"];')
|
|
print('var __profile_ticks = [')
|
|
str_packed_stacks = []
|
|
for stack in self.packed_stacks:
|
|
str_packed_stacks.append('[' + ','.join(map(str, stack)) + ']')
|
|
print(',\n'.join(str_packed_stacks))
|
|
print('];')
|
|
|
|
class CmdLineProcessor(object):
|
|
|
|
def __init__(self):
|
|
self.options = ["js",
|
|
"gc",
|
|
"compiler",
|
|
"other",
|
|
"external",
|
|
"ignore-unknown",
|
|
"separate-ic",
|
|
"call-graph-json"]
|
|
# default values
|
|
self.state = None
|
|
self.ignore_unknown = False
|
|
self.log_file = None
|
|
self.separate_ic = False
|
|
self.call_graph_json = False
|
|
|
|
def ProcessArguments(self):
|
|
try:
|
|
opts, args = getopt.getopt(sys.argv[1:], "jgcoe", self.options)
|
|
except getopt.GetoptError:
|
|
self.PrintUsageAndExit()
|
|
for key, value in opts:
|
|
if key in ("-j", "--js"):
|
|
self.state = VMStates['JS']
|
|
if key in ("-g", "--gc"):
|
|
self.state = VMStates['GC']
|
|
if key in ("-c", "--compiler"):
|
|
self.state = VMStates['COMPILER']
|
|
if key in ("-o", "--other"):
|
|
self.state = VMStates['OTHER']
|
|
if key in ("-e", "--external"):
|
|
self.state = VMStates['EXTERNAL']
|
|
if key in ("--ignore-unknown"):
|
|
self.ignore_unknown = True
|
|
if key in ("--separate-ic"):
|
|
self.separate_ic = True
|
|
if key in ("--call-graph-json"):
|
|
self.call_graph_json = True
|
|
self.ProcessRequiredArgs(args)
|
|
|
|
def ProcessRequiredArgs(self, args):
|
|
return
|
|
|
|
def GetRequiredArgsNames(self):
|
|
return
|
|
|
|
def PrintUsageAndExit(self):
|
|
print('Usage: %(script_name)s --{%(opts)s} %(req_opts)s' % {
|
|
'script_name': os.path.basename(sys.argv[0]),
|
|
'opts': string.join(self.options, ','),
|
|
'req_opts': self.GetRequiredArgsNames()
|
|
})
|
|
sys.exit(2)
|
|
|
|
def RunLogfileProcessing(self, tick_processor):
|
|
tick_processor.ProcessLogfile(self.log_file, self.state, self.ignore_unknown,
|
|
self.separate_ic, self.call_graph_json)
|
|
|
|
|
|
if __name__ == '__main__':
|
|
sys.exit('You probably want to run windows-tick-processor.py or linux-tick-processor.py.')
|