llprof improvements

tools/ll_prof.py

 #!/usr/bin/env python
 #
 # Copyright 2012 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 27 matching lines @@
 import subprocess
 import sys
 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
+  $ perf record -R -e cycles -c 10000 -f -i ./d8 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.
 
+IMPORTANT:
+  The kernel has an internal maximum for events per second, it is 100K by
+  default. That's not enough for "-c 10000". Set it to some higher value:
+  $ echo 10000000 | sudo tee /proc/sys/kernel/perf_event_max_sample_rate
+  You can also make the warning about kernel address maps go away:
+  $ echo 0 | sudo tee /proc/sys/kernel/kptr_restrict
+
+We have a convenience script that handles all of the above for you:
+  $ tools/run-llprof.sh ./d8 bench.js
+
 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
 """
 
 
 JS_ORIGIN = "js"
 JS_SNAPSHOT_ORIGIN = "js-snapshot"
 
 class Code(object):
   """Code object."""
 
   _id = 0
+  UNKNOWN = 0
+  V8INTERNAL = 1
+  FULL_CODEGEN = 2
+  OPTIMIZED = 3
 
   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
+    if name.startswith("LazyCompile:*"):
+      self.codetype = Code.OPTIMIZED
+    elif name.startswith("LazyCompile:"):
+      self.codetype = Code.FULL_CODEGEN
+    elif name.startswith("v8::internal::"):
+      self.codetype = Code.V8INTERNAL
+    else:
+      self.codetype = Code.UNKNOWN
 
   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):
@@ skipping 77 matching lines @@
     return disasm.GetDisasmLines(filename,
                                  self.origin_offset,
                                  self.end_address - self.start_address,
                                  arch,
                                  inplace)
 
 
 class CodePage(object):
   """Group of adjacent code objects."""
 
-  SHIFT = 12  # 4K pages
+  SHIFT = 20  # 1M pages
   SIZE = (1 << SHIFT)
   MASK = ~(SIZE - 1)
 
   @staticmethod
   def PageAddress(address):
     return address & CodePage.MASK
 
   @staticmethod
   def PageId(address):
     return address >> CodePage.SHIFT
@@ skipping 301 matching lines @@
 
   @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.
 
 
+# Reference: struct perf_file_header in kernel/tools/perf/util/header.h
 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")
 ])
 
 
+# Reference: /usr/include/linux/perf_event.h
 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_type", "u32"),
   ("bp_addr", "u64"),
-  ("bp_len", "u64"),
+  ("bp_len", "u64")
 ])
 
 
+# Reference: /usr/include/linux/perf_event.h
 PERF_EVENT_HEADER_DESC = Descriptor([
   ("type", "u32"),
   ("misc", "u16"),
   ("size", "u16")
 ])
 
 
+# Reference: kernel/events/core.c
 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
 
 
+# Reference: /usr/include/perf_event.h, the comment for PERF_RECORD_SAMPLE.
 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),
@@ skipping 116 matching lines @@
     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.
+    if mmap_info.filename.endswith(".ko"):
+      dynamic_symbols = ""
+    else:
+      dynamic_symbols = "-T"
     process = subprocess.Popen(
-      "%s -h -t -T -C %s" % (OBJDUMP_BIN, mmap_info.filename),
+      "%s -h -t %s -C %s" % (OBJDUMP_BIN, dynamic_symbols, 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:
@@ skipping 71 matching lines @@
   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):
     code_ticks = code.self_ticks
     print "%10d %5.1f%% %s [%s]" % (code_ticks, 100. * code_ticks / ticks,
                                     code.FullName(), code.origin)
     if options.disasm_all or i < options.disasm_top:
       code.PrintAnnotated(arch, options)
   print
   print "Ticks per library:"
-  mmap_infos = [m for m in library_repo.infos]
+  mmap_infos = [m for m in library_repo.infos if m.ticks > 0]
   mmap_infos.sort(key=lambda m: m.ticks, reverse=True)
   for mmap_info in mmap_infos:
     mmap_ticks = mmap_info.ticks
     print "%10d %5.1f%% %s" % (mmap_ticks, 100. * mmap_ticks / ticks,
                                mmap_info.unique_name)
 
 
 def PrintDot(code_map, options):
   print "digraph G {"
   for code in code_map.UsedCode():
@@ skipping 69 matching lines @@
     disasm.OBJDUMP_BIN = options.objdump
     OBJDUMP_BIN = options.objdump
   else:
     print "Cannot find %s, falling back to default objdump" % options.objdump
 
   # Stats.
   events = 0
   ticks = 0
   missed_ticks = 0
   really_missed_ticks = 0
+  optimized_ticks = 0
+  generated_ticks = 0
+  v8_internal_ticks = 0
   mmap_time = 0
   sample_time = 0
 
   # 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.
@@ skipping 23 matching lines @@
       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)
+        if code.codetype == Code.OPTIMIZED:
+          optimized_ticks += 1
+        elif code.codetype == Code.FULL_CODEGEN:
+          generated_ticks += 1
+        elif code.codetype == Code.V8INTERNAL:
+          v8_internal_ticks += 1
       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, log_reader.arch, ticks, options)
 
     if not options.quiet:
+      def PrintTicks(number, total, description):
+        print("%10d %5.1f%% ticks in %s" %
+              (number, 100.0*number/total, description))
       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
+      unaccounted = "unaccounted ticks"
+      if really_missed_ticks > 0:
+        unaccounted += " (probably in the kernel, try --kernel)"
+      PrintTicks(really_missed_ticks, ticks, unaccounted)
+      PrintTicks(optimized_ticks, ticks, "ticks in optimized code")
+      PrintTicks(generated_ticks, ticks, "ticks in other lazily compiled code")
+      PrintTicks(v8_internal_ticks, ticks, "ticks in v8::internal::*")
       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()