ll_prof: Reduce profiling hooks overhead from >400% to 25%.

tools/ll_prof.py

 #!/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
@@ skipping 106 matching lines @@
     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):
+  def PrintAnnotated(self, arch, 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 = self._GetDisasmLines(code_info, options)
+    lines = self._GetDisasmLines(arch, options)
     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:
@@ skipping 18 matching lines @@
         "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):
+  def _GetDisasmLines(self, arch, options):
     if self.origin == JS_ORIGIN or self.origin == JS_SNAPSHOT_ORIGIN:
       inplace = False
-      filename = options.log + ".code"
+      filename = options.log + ".ll"
     else:
       inplace = True
       filename = self.origin
     return disasm.GetDisasmLines(filename,
                                  self.origin_offset,
                                  self.end_address - self.start_address,
-                                 code_info.arch,
+                                 arch,
                                  inplace)
 
 
 class CodePage(object):
   """Group of adjacent code objects."""
 
   SHIFT = 12  # 4K pages
   SIZE = (1 << SHIFT)
   MASK = ~(SIZE - 1)
 
@@ skipping 99 matching lines @@
 
 
 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."""
+class SnapshotLogReader(object):
+  """V8 snapshot log reader."""
 
-  _CODE_INFO_RE = re.compile(
-    r"code-info,([^,]+),(\d+)")
+  _SNAPSHOT_CODE_NAME_RE = re.compile(
+    r"snapshot-code-name,(\d+),\"(.*)\"")
 
-  _CODE_CREATE_RE = re.compile(
-    r"code-creation,([^,]+),(0x[a-f0-9]+),(\d+),\"(.*)\"(?:,(0x[a-f0-9]+),([~*])?)?(?:,(\d+))?")
+  def __init__(self, log_name):
+    self.log_name = log_name
 
-  _CODE_MOVE_RE = re.compile(
-    r"code-move,(0x[a-f0-9]+),(0x[a-f0-9]+)")
+  def ReadNameMap(self):
+    log = open(self.log_name, "r")
+    try:
+      snapshot_pos_to_name = {}
+      for line in log:
+        match = SnapshotLogReader._SNAPSHOT_CODE_NAME_RE.match(line)
+        if match:
+          pos = int(match.group(1))
+          name = match.group(2)
+          snapshot_pos_to_name[pos] = name
+    finally:
+      log.close()
+    return snapshot_pos_to_name
 
-  _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+)")
+class LogReader(object):
+  """V8 low-level (binary) log reader."""
 
-  _CODE_MOVING_GC = "code-moving-gc"
+  _ARCH_TO_POINTER_TYPE_MAP = {
+    "ia32": ctypes.c_uint32,
+    "arm": ctypes.c_uint32,
+    "x64": ctypes.c_uint64
+  }
 
-  def __init__(self, log_name, code_map, is_snapshot, snapshot_pos_to_name):
-    self.log = open(log_name, "r")
+  _CODE_CREATE_TAG = "C"
+  _CODE_MOVE_TAG = "M"
+  _CODE_DELETE_TAG = "D"
+  _SNAPSHOT_POSITION_TAG = "P"
+  _CODE_MOVING_GC_TAG = "G"
+
+  def __init__(self, log_name, code_map, snapshot_pos_to_name):
+    self.log_file = open(log_name, "r")
+    self.log = mmap.mmap(self.log_file.fileno(), 0, mmap.MAP_PRIVATE)
+    self.log_pos = 0
     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)))
+    self.arch = self.log[:self.log.find("\0")]
+    self.log_pos += len(self.arch) + 1
+    assert self.arch in LogReader._ARCH_TO_POINTER_TYPE_MAP, \
+        "Unsupported architecture %s" % self.arch
+    pointer_type = LogReader._ARCH_TO_POINTER_TYPE_MAP[self.arch]
 
-  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
+    self.code_create_struct = LogReader._DefineStruct([
+        ("name_size", ctypes.c_int32),
+        ("code_address", pointer_type),
+        ("code_size", ctypes.c_int32)])
 
-      if line.startswith(CodeLogReader._CODE_MOVING_GC):
+    self.code_move_struct = LogReader._DefineStruct([
+        ("from_address", pointer_type),
+        ("to_address", pointer_type)])
+
+    self.code_delete_struct = LogReader._DefineStruct([
+        ("address", pointer_type)])
+
+    self.snapshot_position_struct = LogReader._DefineStruct([
+        ("address", pointer_type),
+        ("position", ctypes.c_int32)])
+
+  def ReadUpToGC(self):
+    while self.log_pos < self.log.size():
+      tag = self.log[self.log_pos]
+      self.log_pos += 1
+
+      if tag == LogReader._CODE_MOVING_GC_TAG:
         self.address_to_snapshot_name.clear()
-        return made_progress
+        return
 
-      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 tag == LogReader._CODE_CREATE_TAG:
+        event = self.code_create_struct.from_buffer(self.log, self.log_pos)
+        self.log_pos += ctypes.sizeof(event)
+        start_address = event.code_address
+        end_address = start_address + event.code_size
         if start_address in self.address_to_snapshot_name:
           name = self.address_to_snapshot_name[start_address]
           origin = JS_SNAPSHOT_ORIGIN
         else:
-          tag = match.group(1)
-          optimization_status = match.group(6)
-          func_name = match.group(4)
-          if optimization_status:
-            name = "%s:%s%s" % (tag, optimization_status, func_name)
-          else:
-            name = "%s:%s" % (tag, func_name)
+          name = self.log[self.log_pos:self.log_pos + event.name_size]
           origin = JS_ORIGIN
-        if self.is_snapshot:
-          origin_offset = 0
-        else:
-          origin_offset = int(match.group(7))
+        self.log_pos += event.name_size
+        origin_offset = self.log_pos
+        self.log_pos += event.code_size
         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)
+          LogReader._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 tag == LogReader._CODE_MOVE_TAG:
+        event = self.code_move_struct.from_buffer(self.log, self.log_pos)
+        self.log_pos += ctypes.sizeof(event)
+        old_start_address = event.from_address
+        new_start_address = event.to_address
         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
+      if tag == LogReader._CODE_DELETE_TAG:
+        event = self.code_delete_struct.from_buffer(self.log, self.log_pos)
+        self.log_pos += ctypes.sizeof(event)
+        old_start_address = event.address
         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]
+      if tag == LogReader._SNAPSHOT_POSITION_TAG:
+        event = self.snapshot_position_struct.from_buffer(self.log,
+                                                          self.log_pos)
+        self.log_pos += ctypes.sizeof(event)
+        start_address = event.address
+        snapshot_pos = event.position
+        if snapshot_pos in self.snapshot_pos_to_name:
+          self.address_to_snapshot_name[start_address] = \
+              self.snapshot_pos_to_name[snapshot_pos]
+        continue
+
+      assert False, "Unknown tag %s" % tag
 
   def Dispose(self):
     self.log.close()
+    self.log_file.close()
+
+  @staticmethod
+  def _DefineStruct(fields):
+    class Struct(ctypes.Structure):
+      _fields_ = fields
+    return Struct
 
   @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,
@@ skipping 288 matching lines @@
         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):
+def PrintReport(code_map, library_repo, arch, 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)
+      code.PrintAnnotated(arch, 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 {"
@@ skipping 41 matching lines @@
                     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)
+      print "V8 logs: %s, %s, %s.ll" % (options.snapshot_log,
+                                        options.log,
+                                        options.log)
     else:
-      print "V8 log: %s, %s.code (no snapshot)" % (options.log, options.log)
+      print "V8 log: %s, %s.ll (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.
+  # Process the snapshot log to fill the snapshot name map.
+  snapshot_name_map = {}
+  if options.snapshot:
+    snapshot_log_reader = SnapshotLogReader(log_name=options.snapshot_log)
+    snapshot_name_map = snapshot_log_reader.ReadNameMap()
+
+  # Initialize the log reader.
   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()
+  log_reader = LogReader(log_name=options.log + ".ll",
+                         code_map=code_map,
+                         snapshot_pos_to_name=snapshot_name_map)
   if not options.quiet:
-    print "Generated code architecture: %s" % code_info.arch
+    print "Generated code architecture: %s" % log_reader.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)
+  log_reader.ReadUpToGC()
   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)
+        log_reader.ReadUpToGC()
       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)
+    PrintReport(code_map, library_repo, log_reader.arch, 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()