[telemetry] Add a V8GCTimes measurement and benchmarks.

tools/perf/measurements/v8_gc_times.py

+# Copyright 2015 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.
+
+from telemetry.core.platform import tracing_category_filter
+from telemetry.core.platform import tracing_options
+from telemetry.page import page_test
+from telemetry.timeline.model import TimelineModel
+from telemetry.util import statistics
+from telemetry.value import scalar
+
+
+class V8GCTimes(page_test.PageTest):
+
+  _TIME_OUT_IN_SECONDS = 60
+  _CATEGORIES = ['blink.console',
+                 'renderer.scheduler',
+                 'toplevel',
+                 'v8',
+                 'webkit.console']
+  _RENDERER_MAIN_THREAD = 'CrRendererMain'
+  _IDLE_TASK_PARENT = 'SingleThreadIdleTaskRunner::RunTask'
+
+  def __init__(self):
+    super(V8GCTimes, self).__init__('RunPageInteractions')
+    self._v8_event_stats = [
+        V8EventStat('V8.GCIncrementalMarking',
+                    'gc_incremental_marking',

[Sami, 2015/02/04 19:19:28]

I wonder if we should have v8 somewhere in the name here? If you want to have
this measurement plus the oilpan one[1] active simultaneously, the results might
look confusing.

[1]
https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/measure...

[rmcilroy, 2015/02/05 16:23:25]

Sounds good, done.

+                    'incremental marking steps'),
+        V8EventStat('V8.GCScavenger',
+                    'gc_scavenger',
+                    'scavenges'),
+        V8EventStat('V8.GCCompactor',
+                    'gc_mark_compactor',
+                    'mark-sweep-compactor')]
+    self._renderer_process = None
+
+  def WillNavigateToPage(self, page, tab):
+    category_filter = tracing_category_filter.TracingCategoryFilter()
+
+    for category in self._CATEGORIES:
+      category_filter.AddIncludedCategory(category)
+
+    options = tracing_options.TracingOptions()
+    options.enable_chrome_trace = True
+
+    tab.browser.platform.tracing_controller.Start(
+        options, category_filter, self._TIME_OUT_IN_SECONDS)
+
+  def DidRunActions(self, page, tab):
+    trace_data = tab.browser.platform.tracing_controller.Stop()
+    timeline_model = TimelineModel(trace_data)
+
+    self._renderer_process = timeline_model.GetRendererProcessFromTabId(tab.id)
+
+  def ValidateAndMeasurePage(self, page, tab, results):
+    self._AddV8MetricsToResults(self._renderer_process, results)
+
+  def _AddV8MetricsToResults(self, process, results):
+    if process is None:
+      return
+
+    for thread in process.threads.values():
+      if thread.name != self._RENDERER_MAIN_THREAD:
+        continue
+
+      self._AddV8EventStatsToResults(thread, results)
+      self._AddCpuTimeStatsToResults(thread, results)
+
+  def _AddV8EventStatsToResults(self, thread, results):
+    # Find all V8 GC events in the trace.
+    for event in thread.IterAllSlices():
+      event_stat = _FindV8EventStatForEvent(self._v8_event_stats, event.name)
+      if event_stat:

[Sami, 2015/02/04 19:19:28]

nit: this and the one below would be a little neater as early-outs.

[rmcilroy, 2015/02/05 16:23:25]

Agree for this one, but not the one below.  If you feel strongly I'll change
that one to though.

[Sami, 2015/02/05 17:29:31]

Ok :)

+        event_stat.thread_duration += event.thread_duration
+        parent_idle_task = _ParentIdleTask(event)
+        if parent_idle_task:
+          allotted_idle_time = parent_idle_task.args['allotted_time_ms']
+          idle_task_overrun = 0
+          if event.thread_duration > allotted_idle_time:
+            idle_task_overrun = event.thread_duration - allotted_idle_time

[Sami, 2015/02/04 19:19:28]

Should we be looking at the wall clock here instead? That's what defines the
deadline and if we miss it because of descheduling, it's still kinda our fault,
right?

[rmcilroy, 2015/02/05 16:23:25]

Hmm yeah, good point.  I've done this, but it means we are comparing
thread_duration and wall_duration which doesn't seem good.  Do avoid this I've
assumed that the amount of "inside_idle" thread duration time is proportional to
the ratio of idle wall duration time (simplistic but hopefully reasonable
assumption in general).

I've added an extra test to check this.

[Sami, 2015/02/05 17:29:31]

That seems like a reasonable assumption given the numbers we have to work with.

+          # Don't count time over the deadline as being inside idle time.
+          event_stat.thread_duration_inside_idle += (
+              event.thread_duration - idle_task_overrun)
+          event_stat.idle_task_overrun_duration += idle_task_overrun
+
+    for v8_event_stat in self._v8_event_stats:
+      results.AddValue(scalar.ScalarValue(
+          results.current_page, v8_event_stat.result_name, 'ms',
+          v8_event_stat.thread_duration,
+          'Total thread duration spent in ' + v8_event_stat.result_description))

[Sami, 2015/02/04 19:19:29]

nit: string interpolation would be a little easier to read (below too).

[rmcilroy, 2015/02/05 16:23:25]

Done.

+      results.AddValue(scalar.ScalarValue(results.current_page,
+          v8_event_stat.result_name + '_outside_idle', 'ms',
+          v8_event_stat.thread_duration_outside_idle,
+          'Total thread duration spent in ' + v8_event_stat.result_description +
+          'outside of idle tasks'))
+      results.AddValue(scalar.ScalarValue(results.current_page,
+          v8_event_stat.result_name + '_idle_deadline_overrun', 'ms',
+          v8_event_stat.idle_task_overrun_duration,
+          'Total idle task deadline overrun for ' +
+          v8_event_stat.result_description + 'idle tasks'))
+      results.AddValue(scalar.ScalarValue(results.current_page,
+          v8_event_stat.result_name + '_percentage_idle', '%',
+          v8_event_stat.percentage_thread_duration_during_idle,
+          'Percentage of ' + v8_event_stat.result_description +
+          'spent in idle tasks'))
+
+    # Add total metrics.
+    gc_total = sum(x.thread_duration for x in self._v8_event_stats)
+    gc_total_outside_idle = sum(
+        x.thread_duration_outside_idle for x in self._v8_event_stats)
+    gc_total_idle_deadline_overrun = sum(
+        x.idle_task_overrun_duration for x in self._v8_event_stats)
+    gc_total_percentage_idle = statistics.DivideIfPossibleOrZero(
+        100 * (gc_total - gc_total_outside_idle), gc_total)
+
+    results.AddValue(scalar.ScalarValue(results.current_page,
+        'gc_total', 'ms', gc_total,
+        'Total thread duration of all garbage collection events'))
+    results.AddValue(scalar.ScalarValue(results.current_page,
+        'gc_total_outside_idle', 'ms', gc_total_outside_idle,
+        'Total thread duration of all garbage collection events outside of idle'

[Sami, 2015/02/04 19:19:29]

Missing a space at end of string.

[rmcilroy, 2015/02/05 16:23:25]

Done.

+        'tasks'))
+    results.AddValue(scalar.ScalarValue(results.current_page,
+        'gc_total_idle_deadline_overrun', 'ms', gc_total_idle_deadline_overrun,
+        'Total idle task deadline overrun for all idle tasks garbage collection'

[Sami, 2015/02/04 19:19:28]

Missing a space at end of string.

[rmcilroy, 2015/02/05 16:23:25]

Done.

+        'events'))
+    results.AddValue(scalar.ScalarValue(results.current_page,
+        'gc_total_percentage_idle', '%', gc_total_percentage_idle,
+        'Percentage of the thread duration of all garbage collection events'

[Sami, 2015/02/04 19:19:28]

Missing a space at end of string.

[rmcilroy, 2015/02/05 16:23:25]

Done.

+        'spent inside of idle tasks'))
+
+  def _AddCpuTimeStatsToResults(self, thread, results):
+    if thread.toplevel_slices:
+      start_time = min(s.start for s in thread.toplevel_slices)
+      end_time = max(s.end for s in thread.toplevel_slices)
+      duration = end_time - start_time
+      cpu_time = sum(s.thread_duration for s in thread.toplevel_slices)
+    else:
+      duration = cpu_time = 0
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'duration', 'ms', duration))
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'cpu_time', 'ms', cpu_time))
+
+
+def _FindV8EventStatForEvent(v8_event_stats_list, event_name):
+  for v8_event_stat in v8_event_stats_list:
+    if v8_event_stat.src_event_name == event_name:
+      return v8_event_stat
+  return None
+
+
+def _ParentIdleTask(event):
+  parent = event.parent_slice
+  while parent:
+    if parent.name == V8GCTimes._IDLE_TASK_PARENT:
+      return parent
+    parent = parent.parent_slice
+  return None
+
+
+class V8EventStat(object):
+
+  def __init__(self, src_event_name, result_name, result_description):
+    self.src_event_name = src_event_name
+    self.result_name = result_name
+    self.result_description = result_description
+    self.thread_duration = 0.0
+    self.thread_duration_inside_idle = 0.0
+    self.idle_task_overrun_duration = 0.0
+
+  @property
+  def thread_duration_outside_idle(self):
+    return self.thread_duration - self.thread_duration_inside_idle
+
+  @property
+  def percentage_thread_duration_during_idle(self):
+    return statistics.DivideIfPossibleOrZero(
+        100 * self.thread_duration_inside_idle, self.thread_duration)