tickprocessor.py

# 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

  def IsJSFunction(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))

  def IsJSFunction(self):
    return self.type in ('Function', 'LazyCompile', 'Script')

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], 16), int(row[4]), self.PreprocessStack(row[5:]))
          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] == 'function-creation':
            self.ProcessFunctionCreation(int(row[1], 16), int(row[2], 16))
          elif row[0] == 'function-move':
            self.ProcessFunctionMove(int(row[1], 16), int(row[2], 16))
          elif row[0] == 'function-delete':
            self.ProcessFunctionDelete(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 ProcessFunctionCreation(self, func_addr, code_addr):
    js_entry_node = self.js_entries.Find(code_addr)
    if js_entry_node:
      js_entry = js_entry_node.value
      self.js_entries.Insert(func_addr, JSCodeEntry(func_addr, js_entry.name, js_entry.type, 1, None))

  def ProcessFunctionMove(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:
      return

  def ProcessFunctionDelete(self, from_addr):
    try:
      removed_node = self.js_entries.Remove(from_addr)
      self.deleted_code.append(removed_node.value)
    except splaytree.KeyNotFoundError:
      return

  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, func, 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, func, state, stack)
      else:
        self.unaccounted_number_of_ticks += 1
    else:
      processed_stack = self.ProcessStack(stack)
      if not entry.IsSharedLibraryEntry() and not entry.IsJSFunction():
        func_entry_node = self.js_entries.Find(func)
        if func_entry_node and func_entry_node.value.IsJSFunction():
          processed_stack.insert(0, func_entry_node.value.ToString())
      entry.Tick(pc, processed_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.')