Telemetry: Remove 'overhead' time from thread times measurement.

tools/perf/metrics/timeline.py

 # Copyright 2014 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 import collections
 import itertools
 
 from metrics import Metric
 from telemetry.core.timeline import bounds
 from telemetry.page import page_measurement
 
 TRACING_MODE = 'tracing-mode'
 TIMELINE_MODE = 'timeline-mode'
 
+
 class MissingFramesError(page_measurement.MeasurementFailure):
   def __init__(self):
     super(MissingFramesError, self).__init__(
         'No frames found in trace. Unable to normalize results.')
 
+
 class TimelineMetric(Metric):
   def __init__(self, mode):
     """ Initializes a TimelineMetric object.
     """
     super(TimelineMetric, self).__init__()
     assert mode in (TRACING_MODE, TIMELINE_MODE)
     self._mode = mode
     self._model = None
     self._renderer_process = None
     self._actions = []
@@ skipping 43 matching lines @@
   def renderer_process(self):
     return self._renderer_process
 
   @renderer_process.setter
   def renderer_process(self, p):
     self._renderer_process = p
 
   def AddResults(self, tab, results):
     return
 
+
 class LoadTimesTimelineMetric(TimelineMetric):
   def __init__(self, mode):
     super(LoadTimesTimelineMetric, self).__init__(mode)
     self.report_main_thread_only = True
 
   def AddResults(self, _, results):
     assert self._model
     if self.report_main_thread_only:
       if self._mode == TRACING_MODE:
         thread_filter = 'CrRendererMain'
@@ skipping 41 matching lines @@
 
 # We want to generate a consistant picture of our thread usage, despite
 # having several process configurations (in-proc-gpu/single-proc).
 # Since we can't isolate renderer threads in single-process mode, we
 # always sum renderer-process threads' times. We also sum all io-threads
 # for simplicity.
 TimelineThreadCategories =  {
   "Chrome_InProcGpuThread": "GPU",
   "CrGpuMain"             : "GPU",
   "AsyncTransferThread"   : "GPU_transfer",
-  "CrBrowserMain"         : "browser_main",
-  "Browser Compositor"    : "browser_compositor",
+  "CrBrowserMain"         : "browser",
+  "Browser Compositor"    : "browser",
   "CrRendererMain"        : "renderer_main",
   "Compositor"            : "renderer_compositor",
   "IOThread"              : "IO",
   "CompositorRasterWorker": "raster",
   "DummyThreadName1"      : "other",
   "DummyThreadName2"      : "total_fast_path",
   "DummyThreadName3"      : "total_all"
 }
 
-MatchBySubString = ["IOThread", "CompositorRasterWorker"]
+_MatchBySubString = ["IOThread", "CompositorRasterWorker"]
 
 AllThreads = TimelineThreadCategories.values()
 NoThreads = []
-FastPathThreads = ["GPU",
-                   "browser_main",
-                   "browser_compositor",
-                   "renderer_compositor",
-                   "IO"]
-MainThread = ["renderer_main"]
-FastPathResults = AllThreads
-FastPathDetails = NoThreads
-SilkResults = ["renderer_main", "total_all"]
-SilkDetails = MainThread
+FastPathThreads = ["GPU", "renderer_compositor", "browser", "IO"]
+
+ReportMainThreadOnly = ["renderer_main"]
+ReportFastPathResults = AllThreads
+ReportFastPathDetails = NoThreads
+ReportSilkResults = ["renderer_main", "total_all"]
+ReportSilkDetails = ["renderer_main"]
 
 # TODO(epenner): Thread names above are likely fairly stable but trace names
-# could change. We should formalize this trace to keep this robust.
-CompositorFrameTraceName = "::SwapBuffers"
+# could change. We should formalize these traces to keep this robust.
+OverheadTraceCategory = "trace_event_overhead"
+OverheadTraceName = "overhead"
+FrameTraceName = "::SwapBuffers"
+FrameTraceThreadName = "renderer_compositor"
+
+
+def ClockOverheadForEvent(event):
+  if (event.category == OverheadTraceCategory and
+      event.name == OverheadTraceName):
+    return event.duration
+  else:
+    return 0
+
+def CpuOverheadForEvent(event):
+  if (event.category == OverheadTraceCategory and
+      event.thread_duration):
+    return event.thread_duration
+  else:
+    return 0
 
 def ThreadCategoryName(thread_name):
   thread_category = "other"
   for substring, category in TimelineThreadCategories.iteritems():
-    if substring in MatchBySubString and substring in thread_name:
+    if substring in _MatchBySubString and substring in thread_name:
       thread_category = category
   if thread_name in TimelineThreadCategories:
     thread_category = TimelineThreadCategories[thread_name]
   return thread_category
 
 def ThreadTimeResultName(thread_category):
   return "thread_" + thread_category + "_clock_time_per_frame"
 
 def ThreadCpuTimeResultName(thread_category):
   return "thread_" + thread_category + "_cpu_time_per_frame"
 
 def ThreadDetailResultName(thread_category, detail):
   return "thread_" + thread_category + "|" + detail
 
+
 class ResultsForThread(object):
   def __init__(self, model, action_ranges, name):
     self.model = model
     self.toplevel_slices = []
     self.all_slices = []
     self.name = name
     self.action_ranges = action_ranges
 
   @property
   def clock_time(self):
-    return sum([x.duration for x in self.toplevel_slices])
+    clock_duration = sum([x.duration for x in self.toplevel_slices])
+    clock_overhead = sum([ClockOverheadForEvent(x) for x in self.all_slices])
+    return clock_duration - clock_overhead
 
   @property
   def cpu_time(self):
-    res = 0
+    cpu_duration = 0
+    cpu_overhead = sum([CpuOverheadForEvent(x) for x in self.all_slices])
     for x in self.toplevel_slices:
       # Only report thread-duration if we have it for all events.
       #
       # A thread_duration of 0 is valid, so this only returns 0 if it is None.
       if x.thread_duration == None:
         if not x.duration:
           continue
         else:
           return 0
       else:
-        res += x.thread_duration
-    return res
+        cpu_duration += x.thread_duration
+    return cpu_duration - cpu_overhead
 
-  def ActionSlices(self, slices):
+  def SlicesInActions(self, slices):
     slices_in_actions = []
     for event in slices:
       for action_range in self.action_ranges:
         if action_range.Contains(bounds.Bounds.CreateFromEvent(event)):
           slices_in_actions.append(event)
           break
     return slices_in_actions
 
   def AppendThreadSlices(self, thread):
-    self.all_slices.extend(self.ActionSlices(thread.all_slices))
-    self.toplevel_slices.extend(self.ActionSlices(thread.toplevel_slices))
+    self.all_slices.extend(self.SlicesInActions(thread.all_slices))
+    self.toplevel_slices.extend(self.SlicesInActions(thread.toplevel_slices))
 
   def AddResults(self, num_frames, results):
     clock_report_name = ThreadTimeResultName(self.name)
     cpu_report_name  = ThreadCpuTimeResultName(self.name)
     clock_per_frame = (float(self.clock_time) / num_frames) if num_frames else 0
     cpu_per_frame   = (float(self.cpu_time) / num_frames) if num_frames else 0
     results.Add(clock_report_name, 'ms', clock_per_frame)
     results.Add(cpu_report_name, 'ms', cpu_per_frame)
 
   def AddDetailedResults(self, num_frames, results):
     slices_by_category = collections.defaultdict(list)
     for s in self.all_slices:
       slices_by_category[s.category].append(s)
     all_self_times = []
     for category, slices_in_category in slices_by_category.iteritems():
       self_time = sum([x.self_time for x in slices_in_category])
       all_self_times.append(self_time)
       self_time_result = (float(self_time) / num_frames) if num_frames else 0
       results.Add(ThreadDetailResultName(self.name, category),
                   'ms', self_time_result)
     all_measured_time = sum(all_self_times)
     all_action_time = sum([action.bounds for action in self.action_ranges])
     idle_time = max(0, all_action_time - all_measured_time)
     idle_time_result = (float(idle_time) / num_frames) if num_frames else 0
     results.Add(ThreadDetailResultName(self.name, "idle"),
                 'ms', idle_time_result)
 
+
 class ThreadTimesTimelineMetric(TimelineMetric):
   def __init__(self):
     super(ThreadTimesTimelineMetric, self).__init__(TRACING_MODE)
     self.results_to_report = AllThreads
     self.details_to_report = NoThreads
 
   def CountSlices(self, slices, substring):
     count = 0
     for event in slices:
       if substring in event.name:
@@ skipping 18 matching lines @@
 
     # Group all threads.
     for thread in self._model.GetAllThreads():
       thread_category_results['total_all'].AppendThreadSlices(thread)
 
     # Also group fast-path threads.
     for thread in self._model.GetAllThreads():
       if ThreadCategoryName(thread.name) in FastPathThreads:
         thread_category_results['total_fast_path'].AppendThreadSlices(thread)
 
-    # Calculate the number of frames from the CC thread.
-    cc_slices = thread_category_results['renderer_compositor'].all_slices
-    num_frames = self.CountSlices(cc_slices, CompositorFrameTraceName)
+    # Calculate the number of frames.
+    frame_slices = thread_category_results[FrameTraceThreadName].all_slices
+    num_frames = self.CountSlices(frame_slices, FrameTraceName)
 
     # Report the desired results and details.
     for thread_results in thread_category_results.values():
       if thread_results.name in self.results_to_report:
         thread_results.AddResults(num_frames, results)
       # TOOD(nduca): When generic results objects are done, this special case
       # can be replaced with a generic UI feature.
       if thread_results.name in self.details_to_report:
         thread_results.AddDetailedResults(num_frames, results)