tools/perf/metrics/timeline.py

   1 # Copyright 2014 The Chromium Authors. All rights reserved.
   2 # Use of this source code is governed by a BSD-style license that can be
   3 # found in the LICENSE file.
   4 import collections
   5
   6 from telemetry.util.statistics import DivideIfPossibleOrZero
   7 from telemetry.value import scalar
   8 from telemetry.web_perf.metrics import timeline_based_metric
   9
  10
  11 class LoadTimesTimelineMetric(timeline_based_metric.TimelineBasedMetric):
  12   def __init__(self):
  13     super(LoadTimesTimelineMetric, self).__init__()
  14     self.report_main_thread_only = True
  15
  16   def AddResults(self, model, renderer_thread, interaction_records, results):
  17     assert model
  18     assert len(interaction_records) == 1, (
  19       'LoadTimesTimelineMetric cannot compute metrics for more than 1 time '
  20       'range.')
  21     interaction_record = interaction_records[0]
  22     if self.report_main_thread_only:
  23       thread_filter = 'CrRendererMain'
  24     else:
  25       thread_filter = None
  26
  27     events_by_name = collections.defaultdict(list)
  28     renderer_process = renderer_thread.parent
  29
  30     for thread in renderer_process.threads.itervalues():
  31
  32       if thread_filter and not thread.name in thread_filter:
  33         continue
  34
  35       thread_name = thread.name.replace('/','_')
  36       for e in thread.IterAllSlicesInRange(interaction_record.start,
  37                                            interaction_record.end):
  38         events_by_name[e.name].append(e)
  39
  40       for event_name, event_group in events_by_name.iteritems():
  41         times = [event.self_time for event in event_group]
  42         total = sum(times)
  43         biggest_jank = max(times)
  44
  45         # Results objects cannot contain the '.' character, so remove that here.
  46         sanitized_event_name = event_name.replace('.', '_')
  47
  48         full_name = thread_name + '|' + sanitized_event_name
  49         results.AddValue(scalar.ScalarValue(
  50             results.current_page, full_name, 'ms', total))
  51         results.AddValue(scalar.ScalarValue(
  52             results.current_page, full_name + '_max', 'ms', biggest_jank))
  53         results.AddValue(scalar.ScalarValue(
  54             results.current_page, full_name + '_avg', 'ms', total / len(times)))
  55
  56     for counter_name, counter in renderer_process.counters.iteritems():
  57       total = sum(counter.totals)
  58
  59       # Results objects cannot contain the '.' character, so remove that here.
  60       sanitized_counter_name = counter_name.replace('.', '_')
  61
  62       results.AddValue(scalar.ScalarValue(
  63           results.current_page, sanitized_counter_name, 'count', total))
  64       results.AddValue(scalar.ScalarValue(
  65           results.current_page, sanitized_counter_name + '_avg', 'count',
  66           total / float(len(counter.totals))))
  67
  68 # We want to generate a consistant picture of our thread usage, despite
  69 # having several process configurations (in-proc-gpu/single-proc).
  70 # Since we can't isolate renderer threads in single-process mode, we
  71 # always sum renderer-process threads' times. We also sum all io-threads
  72 # for simplicity.
  73 TimelineThreadCategories =  {
  74   "Chrome_InProcGpuThread": "GPU",
  75   "CrGpuMain"             : "GPU",
  76   "AsyncTransferThread"   : "GPU_transfer",
  77   "CrBrowserMain"         : "browser",
  78   "Browser Compositor"    : "browser",
  79   "CrRendererMain"        : "renderer_main",
  80   "Compositor"            : "renderer_compositor",
  81   "IOThread"              : "IO",
  82   "CompositorTileWorker"  : "raster",
  83   "DummyThreadName1"      : "other",
  84   "DummyThreadName2"      : "total_fast_path",
  85   "DummyThreadName3"      : "total_all"
  86 }
  87
  88 _MatchBySubString = ["IOThread", "CompositorTileWorker"]
  89
  90 AllThreads = TimelineThreadCategories.values()
  91 NoThreads = []
  92 FastPathThreads = ["GPU", "renderer_compositor", "browser", "IO"]
  93
  94 ReportMainThreadOnly = ["renderer_main"]
  95 ReportSilkDetails = ["renderer_main"]
  96
  97 # TODO(epenner): Thread names above are likely fairly stable but trace names
  98 # could change. We should formalize these traces to keep this robust.
  99 OverheadTraceCategory = "trace_event_overhead"
 100 OverheadTraceName = "overhead"
 101 FrameTraceName = "::SwapBuffers"
 102 FrameTraceThreadName = "renderer_compositor"
 103
 104 IntervalNames = ["frame", "second"]
 105
 106 def Rate(numerator, denominator):
 107   return DivideIfPossibleOrZero(numerator, denominator)
 108
 109 def ClockOverheadForEvent(event):
 110   if (event.category == OverheadTraceCategory and
 111       event.name == OverheadTraceName):
 112     return event.duration
 113   else:
 114     return 0
 115
 116 def CpuOverheadForEvent(event):
 117   if (event.category == OverheadTraceCategory and
 118       event.thread_duration):
 119     return event.thread_duration
 120   else:
 121     return 0
 122
 123 def ThreadCategoryName(thread_name):
 124   thread_category = "other"
 125   for substring, category in TimelineThreadCategories.iteritems():
 126     if substring in _MatchBySubString and substring in thread_name:
 127       thread_category = category
 128   if thread_name in TimelineThreadCategories:
 129     thread_category = TimelineThreadCategories[thread_name]
 130   return thread_category
 131
 132 def ThreadCpuTimeResultName(thread_category, interval_name):
 133   # This isn't a good name, but I don't want to change it and lose continuity.
 134   return "thread_" + thread_category + "_cpu_time_per_" + interval_name
 135
 136 def ThreadTasksResultName(thread_category, interval_name):
 137   return "tasks_per_" + interval_name + "_" + thread_category
 138
 139 def ThreadMeanFrameTimeResultName(thread_category):
 140   return "mean_frame_time_" + thread_category
 141
 142 def ThreadDetailResultName(thread_category, interval_name, detail):
 143   detail_sanitized = detail.replace('.','_')
 144   interval_sanitized = ""
 145   # Special-case per-frame detail names to preserve continuity.
 146   if interval_name == "frame":
 147     interval_sanitized = ""
 148   else:
 149     interval_sanitized = "_per_" + interval_name
 150   return (
 151       "thread_" + thread_category + interval_sanitized + "|" + detail_sanitized)
 152
 153 def ThreadCpuTimeUnits(interval_name):
 154   if interval_name == "second":
 155     return "%"
 156   return "ms"
 157
 158 def ThreadCpuTimeValue(ms_cpu_time_per_interval, interval_name):
 159   # When measuring seconds of CPU time per second of system time, report a %.
 160   if interval_name == "second":
 161     return (ms_cpu_time_per_interval / 1000.0) * 100.0
 162   return ms_cpu_time_per_interval
 163
 164
 165 class ResultsForThread(object):
 166   def __init__(self, model, record_ranges, name):
 167     self.model = model
 168     self.toplevel_slices = []
 169     self.all_slices = []
 170     self.name = name
 171     self.record_ranges = record_ranges
 172     self.all_action_time = \
 173         sum([record_range.bounds for record_range in self.record_ranges])
 174
 175   @property
 176   def clock_time(self):
 177     clock_duration = sum([x.duration for x in self.toplevel_slices])
 178     clock_overhead = sum([ClockOverheadForEvent(x) for x in self.all_slices])
 179     return clock_duration - clock_overhead
 180
 181   @property
 182   def cpu_time(self):
 183     cpu_duration = 0
 184     cpu_overhead = sum([CpuOverheadForEvent(x) for x in self.all_slices])
 185     for x in self.toplevel_slices:
 186       # Only report thread-duration if we have it for all events.
 187       #
 188       # A thread_duration of 0 is valid, so this only returns 0 if it is None.
 189       if x.thread_duration == None:
 190         if not x.duration:
 191           continue
 192         else:
 193           return 0
 194       else:
 195         cpu_duration += x.thread_duration
 196     return cpu_duration - cpu_overhead
 197
 198   def SlicesInActions(self, slices):
 199     slices_in_actions = []
 200     for event in slices:
 201       for record_range in self.record_ranges:
 202         if record_range.ContainsInterval(event.start, event.end):
 203           slices_in_actions.append(event)
 204           break
 205     return slices_in_actions
 206
 207   def AppendThreadSlices(self, thread):
 208     self.all_slices.extend(self.SlicesInActions(thread.all_slices))
 209     self.toplevel_slices.extend(self.SlicesInActions(thread.toplevel_slices))
 210
 211   # Reports cpu-time per interval and tasks per interval.
 212   def AddResults(self, num_intervals, interval_name, results):
 213     cpu_per_interval = Rate(self.cpu_time, num_intervals)
 214     tasks_per_interval = Rate(len(self.toplevel_slices), num_intervals)
 215     results.AddValue(scalar.ScalarValue(
 216         results.current_page,
 217         ThreadCpuTimeResultName(self.name, interval_name),
 218         ThreadCpuTimeUnits(interval_name),
 219         ThreadCpuTimeValue(cpu_per_interval, interval_name)))
 220     results.AddValue(scalar.ScalarValue(
 221         results.current_page,
 222         ThreadTasksResultName(self.name, interval_name),
 223         'tasks', tasks_per_interval))
 224
 225   def AddDetailedResults(self, num_intervals, interval_name, results):
 226     slices_by_category = collections.defaultdict(list)
 227     for s in self.all_slices:
 228       slices_by_category[s.category].append(s)
 229     all_self_times = []
 230     for category, slices_in_category in slices_by_category.iteritems():
 231       self_time = sum([x.self_time for x in slices_in_category])
 232       all_self_times.append(self_time)
 233       self_time_per_interval = Rate(self_time, num_intervals)
 234       results.AddValue(scalar.ScalarValue(
 235           results.current_page,
 236           ThreadDetailResultName(self.name, interval_name, category),
 237           ThreadCpuTimeUnits(interval_name),
 238           ThreadCpuTimeValue(self_time_per_interval, interval_name)))
 239     all_measured_time = sum(all_self_times)
 240     idle_time = max(0, self.all_action_time - all_measured_time)
 241     idle_time_per_interval = Rate(idle_time, num_intervals)
 242     results.AddValue(scalar.ScalarValue(
 243         results.current_page,
 244         ThreadDetailResultName(self.name, interval_name, "idle"),
 245         ThreadCpuTimeUnits(interval_name),
 246         ThreadCpuTimeValue(idle_time_per_interval, interval_name)))
 247
 248   def CountTracesWithName(self, substring):
 249     count = 0
 250     for event in self.all_slices:
 251       if substring in event.name:
 252         count += 1
 253     return count
 254
 255
 256 class ThreadTimesTimelineMetric(timeline_based_metric.TimelineBasedMetric):
 257   def __init__(self):
 258     super(ThreadTimesTimelineMetric, self).__init__()
 259     # Minimal traces, for minimum noise in CPU-time measurements.
 260     self.results_to_report = AllThreads
 261     self.details_to_report = NoThreads
 262
 263   def AddResults(self, model, _, interaction_records, results):
 264     # Set up each thread category for consistant results.
 265     thread_category_results = {}
 266     for name in TimelineThreadCategories.values():
 267       thread_category_results[name] = ResultsForThread(
 268           model, [r.GetBounds() for r in interaction_records], name)
 269
 270     # Group the slices by their thread category.
 271     for thread in model.GetAllThreads():
 272       thread_category = ThreadCategoryName(thread.name)
 273       thread_category_results[thread_category].AppendThreadSlices(thread)
 274
 275     # Group all threads.
 276     for thread in model.GetAllThreads():
 277       thread_category_results['total_all'].AppendThreadSlices(thread)
 278
 279     # Also group fast-path threads.
 280     for thread in model.GetAllThreads():
 281       if ThreadCategoryName(thread.name) in FastPathThreads:
 282         thread_category_results['total_fast_path'].AppendThreadSlices(thread)
 283
 284     # Calculate the interaction's number of frames.
 285     frame_rate_thread = thread_category_results[FrameTraceThreadName]
 286     num_frames = frame_rate_thread.CountTracesWithName(FrameTraceName)
 287
 288     # Calculate the interaction's duration.
 289     all_threads = thread_category_results['total_all']
 290     num_seconds = all_threads.all_action_time / 1000.0
 291
 292     # Report the desired results and details for each interval type.
 293     intervals = [('frame', num_frames), ('second', num_seconds)]
 294     for (interval_name, num_intervals) in intervals:
 295       for thread_results in thread_category_results.values():
 296         if thread_results.name in self.results_to_report:
 297           thread_results.AddResults(num_intervals, interval_name, results)
 298         # TOOD(nduca): When generic results objects are done, this special case
 299         # can be replaced with a generic UI feature.
 300         if thread_results.name in self.details_to_report:
 301           thread_results.AddDetailedResults(
 302               num_intervals, interval_name, results)
 303
 304     # Report mean frame time for the frame rate thread. We could report other
 305     # frame rates (eg. renderer_main) but this might get confusing.
 306     mean_frame_time = Rate(frame_rate_thread.all_action_time, num_frames)
 307     results.AddValue(scalar.ScalarValue(
 308         results.current_page,
 309         ThreadMeanFrameTimeResultName(FrameTraceThreadName),
 310         'ms', mean_frame_time))