Revert of [telemetry] Add a V8GCTimes measurement and benchmarks. (patchset #2...

Revert of [telemetry] Add a V8GCTimes measurement and benchmarks. (patchset #2 id:20001 of https://codereview.chromium.org/898673005/)

Reason for revert:
Failing on mac:

http://chromegw/i/chromium.perf/builders/Mac%2010.9%20Perf%20%281%29/builds/2017

Original issue's description:
> [telemetry] Add a V8GCTimes measurement and benchmarks.
>
> Replaces the v8_stats metric with a v8_gc_times
> measurement.  This new measurement measures the amount of
> time spent in GC during the whole benchmark rather than
> just during gestures.
>
> The following gc metrics are measured:
>   v8_gc_incremental_marking
>   v8_gc_incremental_marking_idle_deadline_overrun
>   v8_gc_incremental_marking_outside_idle
>   v8_gc_incremental_marking_percentage_idle
>   v8_gc_mark_compactor
>   v8_gc_mark_compactor_idle_deadline_overrun
>   v8_gc_mark_compactor_outside_idle
>   v8_gc_mark_compactor_percentage_idle
>   v8_gc_scavenger
>   v8_gc_scavenger_idle_deadline_overrun
>   v8_gc_scavenger_outside_idle
>   v8_gc_scavenger_percentage_idle
>   v8_gc_total
>   v8_gc_total_idle_deadline_overrun
>   v8_gc_total_outside_idle
>
> It also measures the duration of the measurement and the
> amount of CPU time used.
>
> The v8_garbage_collection_cases benchmark is modified to
> use this new v8_gc_times measurement, and v8.top_25_smooth
> and v8.key_mobile_sites_smooth benchmarks have been added.
>
> Since v8_garbage_collection_cases was the only benchmark to
> use the is_fast metric type, and these measurements are now
> done as part of the v8_gc_times measurement now, this CL
> also removes the fast metric type.
>
> Perf Sherrifs: Since this CL changes he way in which the GC
> measurements are done it may cause a movement in the
> v8_garbage_collection_cases benchmarks.
>
> Committed: https://crrev.com/452de5927e54e1da0d57a4b2df8b447f4d442360
> Cr-Commit-Position: refs/heads/master@{#314868}

TBR=hpayer@chromium.org,rmcilroy@chromium.org
NOPRESUBMIT=true
NOTREECHECKS=true
NOTRY=true

Review URL: https://codereview.chromium.org/904903002

Cr-Commit-Position: refs/heads/master@{#315035}

tools/perf/benchmarks/v8.py

@@ -3,40 +3,20 @@
 # found in the LICENSE file.
 
 import page_sets
-from measurements import v8_gc_times
+from telemetry.web_perf import timeline_based_measurement
 from telemetry import benchmark
 
 
 @benchmark.Disabled('win')  # crbug.com/416502
 class V8GarbageCollectionCases(benchmark.Benchmark):
-  """Measure V8 GC metrics on the garbage collection cases."""
-  test = v8_gc_times.V8GCTimes
-  page_set = page_sets.GarbageCollectionCasesPageSet
+  """Measure V8 metrics on the garbage collection cases."""
+  def CreateTimelineBasedMeasurementOptions(self):
+    # TODO(ernstm): Remove v8-overhead when benchmark relevant v8 events become
+    # available in the 'benchmark' category.
+    return timeline_based_measurement.Options(overhead_level='v8-overhead')
 
   @classmethod
   def Name(cls):
     return 'v8.garbage_collection_cases'
 
-@benchmark.Disabled('win')  # crbug.com/416502
-class V8Top25(benchmark.Benchmark):
-  """Measures V8 GC metrics on the while scrolling down the top 25 web pages.
-
-  http://www.chromium.org/developers/design-documents/rendering-benchmarks"""
-  test = v8_gc_times.V8GCTimes
-  page_set = page_sets.Top25SmoothPageSet
-
-  @classmethod
-  def Name(cls):
-    return 'v8.top_25_smooth'
-
-@benchmark.Enabled('android')
-class V8KeyMobileSites(benchmark.Benchmark):
-  """Measures V8 GC metrics on the while scrolling down key mobile sites.
-
-  http://www.chromium.org/developers/design-documents/rendering-benchmarks"""
-  test = v8_gc_times.V8GCTimes
-  page_set = page_sets.KeyMobileSitesSmoothPageSet
-
-  @classmethod
-  def Name(cls):
-    return 'v8.key_mobile_sites_smooth'
+  page_set = page_sets.GarbageCollectionCasesPageSet

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',
-                    'v8_gc_incremental_marking',
-                    'incremental marking steps'),
-        V8EventStat('V8.GCScavenger',
-                    'v8_gc_scavenger',
-                    'scavenges'),
-        V8EventStat('V8.GCCompactor',
-                    'v8_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 not event_stat:
-        continue
-
-      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_wall_overrun = 0
-        if event.duration > allotted_idle_time:
-          idle_task_wall_overrun = event.duration - allotted_idle_time
-        # Don't count time over the deadline as being inside idle time.
-        # Since the deadline should be relative to wall clock we compare
-        # allotted_time_ms with wall duration instead of thread duration, and
-        # then assume the thread duration was inside idle for the same
-        # percentage of time.
-        inside_idle = event.thread_duration * statistics.DivideIfPossibleOrZero(
-            event.duration - idle_task_wall_overrun, event.duration)
-        event_stat.thread_duration_inside_idle += inside_idle
-        event_stat.idle_task_overrun_duration += idle_task_wall_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 %s' %
-           v8_event_stat.result_description)))
-      results.AddValue(scalar.ScalarValue(results.current_page,
-          '%s_outside_idle' % v8_event_stat.result_name, 'ms',
-          v8_event_stat.thread_duration_outside_idle,
-          ('Total thread duration spent in %s outside of idle tasks' %
-           v8_event_stat.result_description)))
-      results.AddValue(scalar.ScalarValue(results.current_page,
-          '%s_idle_deadline_overrun' % v8_event_stat.result_name, 'ms',
-          v8_event_stat.idle_task_overrun_duration,
-          ('Total idle task deadline overrun for %s idle tasks'
-           % v8_event_stat.result_description)))
-      results.AddValue(scalar.ScalarValue(results.current_page,
-          '%s_percentage_idle' % v8_event_stat.result_name, '%',
-          v8_event_stat.percentage_thread_duration_during_idle,
-          ('Percentage of %s spent in idle time' %
-           v8_event_stat.result_description)))
-
-    # 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,
-        'v8_gc_total', 'ms', gc_total,
-        'Total thread duration of all garbage collection events'))
-    results.AddValue(scalar.ScalarValue(results.current_page,
-        'v8_gc_total_outside_idle', 'ms', gc_total_outside_idle,
-        'Total thread duration of all garbage collection events outside of '
-        'idle tasks'))
-    results.AddValue(scalar.ScalarValue(results.current_page,
-        'v8_gc_total_idle_deadline_overrun', 'ms',
-        gc_total_idle_deadline_overrun,
-        'Total idle task deadline overrun for all idle tasks garbage '
-        'collection events'))
-    results.AddValue(scalar.ScalarValue(results.current_page,
-        'v8_gc_total_percentage_idle', '%', gc_total_percentage_idle,
-        'Percentage of the thread duration of all garbage collection events '
-        '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)

tools/perf/page_sets/garbage_collection_cases.py

@@ -24,7 +24,8 @@ class SpinningBallsPage(page_module.Page):
         "document.readyState == 'complete'")
 
   def RunPageInteractions(self, action_runner):
-    interaction = action_runner.BeginInteraction('RunSmoothAllActions')
+    interaction = action_runner.BeginInteraction(
+        'RunSmoothAllActions', is_fast=True)
     action_runner.Wait(15)
     interaction.End()
 

tools/telemetry/telemetry/page/actions/action_runner.py

@@ -33,8 +33,8 @@ class ActionRunner(object):
     action.WillRunAction(self._tab)
     action.RunAction(self._tab)
 
-  def BeginInteraction(self, label, is_smooth=False, is_responsive=False,
-                       repeatable=False):
+  def BeginInteraction(self, label, is_fast=False, is_smooth=False,
+                       is_responsive=False, repeatable=False):
     """Marks the beginning of an interaction record.
 
     An interaction record is a labeled time period containing
@@ -46,6 +46,8 @@ class ActionRunner(object):
     Args:
       label: A label for this particular interaction. This can be any
           user-defined string, but must not contain '/'.
+      is_fast: Whether to measure how fast the browser completes necessary work
+          for this interaction record. See fast_metric.py for details.
       is_smooth: Whether to check for smoothness metrics for this interaction.
       is_responsive: Whether to check for responsiveness metrics for
           this interaction.
@@ -54,6 +56,8 @@ class ActionRunner(object):
           have the same flags.
     """
     flags = []
+    if is_fast:
+      flags.append(timeline_interaction_record.IS_FAST)
     if is_smooth:
       flags.append(timeline_interaction_record.IS_SMOOTH)
     if is_responsive:
@@ -65,8 +69,8 @@ class ActionRunner(object):
     interaction.Begin()
     return interaction
 
-  def BeginGestureInteraction(self, label, is_smooth=False, is_responsive=False,
-                              repeatable=False):
+  def BeginGestureInteraction(self, label, is_fast=False, is_smooth=False,
+                              is_responsive=False, repeatable=False):
     """Marks the beginning of a gesture-based interaction record.
 
     This is similar to normal interaction record, but it will
@@ -80,6 +84,8 @@ class ActionRunner(object):
     Args:
       label: A label for this particular interaction. This can be any
           user-defined string, but must not contain '/'.
+      is_fast: Whether to measure how fast the browser completes necessary work
+          for this interaction record. See fast_metric.py for details.
       is_smooth: Whether to check for smoothness metrics for this interaction.
       is_responsive: Whether to check for responsiveness metrics for
           this interaction.
@@ -87,8 +93,8 @@ class ActionRunner(object):
           as this interaction. All interactions with the same logical name must
           have the same flags.
     """
-    return self.BeginInteraction('Gesture_' + label, is_smooth, is_responsive,
-                                 repeatable)
+    return self.BeginInteraction('Gesture_' + label, is_fast, is_smooth,
+                                 is_responsive, repeatable)
 
   def NavigateToPage(self, page, timeout_in_seconds=60):
     """Navigates to the given page.

tools/telemetry/telemetry/page/actions/action_runner_unittest.py

@@ -51,9 +51,10 @@ class ActionRunnerInteractionTest(tab_test_case.TabTestCase):
   # Test disabled for android: crbug.com/437057
   @decorators.Disabled('android', 'chromeos')
   def testIssuingMultipleMeasurementInteractionRecords(self):
+    self.VerifyIssuingInteractionRecords(is_fast=True)
     self.VerifyIssuingInteractionRecords(is_responsive=True)
     self.VerifyIssuingInteractionRecords(is_smooth=True)
-    self.VerifyIssuingInteractionRecords(is_responsive=True, is_smooth=True)
+    self.VerifyIssuingInteractionRecords(is_fast=True, is_smooth=True)
 
 
 class ActionRunnerTest(tab_test_case.TabTestCase):

tools/telemetry/telemetry/web_perf/metrics/fast_metric.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 logging
+
+from telemetry.timeline import bounds
+from telemetry.value import scalar
+from telemetry.web_perf import timeline_interaction_record as tir_module
+from telemetry.web_perf.metrics import timeline_based_metric
+from telemetry.web_perf.metrics import v8_stats as v8_stats_module
+
+
+class FastMetric(timeline_based_metric.TimelineBasedMetric):
+  def __init__(self):
+    super(FastMetric, self).__init__()
+
+  def AddResults(self, model, renderer_thread, interaction_records, results):
+    """Add 11 results: duration, cpu_time, and idle_time,
+                       incremental_marking, incremental_marking_outside_idle,
+                       scavenger, scavenger_outside_idle,
+                       mark_compactor, mark_compactor_outside_idle,
+                       total_garbage_collection,
+                       total_garbage_collection_outside_idle
+
+    duration is the total wall time for |interaction_records|.
+    cpu_time is the renderer thread time that intersects |interaction_records|.
+    idle time is wall time for |interaction_records| for which renderer slices
+        do not overlap. Note that unscheduled renderer thread time is not
+        counted. Idle time is time for which there was nothing to do.
+    incremental_marking is the total thread duration spent in incremental
+        marking steps.
+    incremental_marking_outside_idle is the thread duration spent in incremental
+        marking steps outside of idle notifications.
+    scavenger is the total thread duration spent in scavenges.
+    scavenger_outside_idle is the thread duration spent in scavenges outside of
+        idle notifications.
+    mark_compactor is the total thread duration spent in mark-sweep-compactor.
+    mark_compactor_outside_idle is the thread duration spent in
+        mark-sweep-compactor outside of idle notifications.
+    total_garbage_collection is the total thread duration spend in garbage
+        collection
+    total_garbage_collection_outside_idle is the total thread duration spend in
+        garbage collection outside of idle notification.
+
+    Args:
+      model: a TimelineModule instance
+      renderer_thread: a telemetry.timeline.thread.Thread() instance
+      interaction_records: an iterable of TimelineInteractionRecord instances
+      results: an instance of page.PageTestResults
+    """
+    self.VerifyNonOverlappedRecords(interaction_records)
+
+    duration = sum(r.end - r.start for r in interaction_records)
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'fast-duration', 'ms', duration))
+
+    try:
+      cpu_time = sum(
+          r.GetOverlappedThreadTimeForSlice(s)
+          for r in interaction_records
+          for s in renderer_thread.toplevel_slices)
+    except tir_module.NoThreadTimeDataException:
+      logging.warning(
+          'Main thread cpu_time cannot be computed for records %s since '
+          'trace does not contain thread time data.',
+          repr(interaction_records))
+    else:
+      results.AddValue(scalar.ScalarValue(
+          results.current_page, 'fast-cpu_time', 'ms', cpu_time))
+
+    idle_time = duration - sum(
+        bounds.Bounds.GetOverlap(r.start, r.end, s.start, s.end)
+        for r in interaction_records
+        for s in renderer_thread.toplevel_slices)
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'fast-idle_time', 'ms', idle_time))
+
+    v8_stats = v8_stats_module.V8Stats(renderer_thread, interaction_records)
+
+    for event_stats in v8_stats.all_event_stats:
+      results.AddValue(scalar.ScalarValue(
+          results.current_page, 'fast-' + event_stats.result_name, 'ms',
+          event_stats.thread_duration,
+          event_stats.result_description))
+      results.AddValue(scalar.ScalarValue(
+          results.current_page,
+          'fast-' + event_stats.result_name + '_outside_idle', 'ms',
+          event_stats.thread_duration_outside_idle,
+          event_stats.result_description + 'outside of idle notifications'))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'fast-total_garbage_collection', 'ms',
+        v8_stats.total_gc_thread_duration,
+        'Total thread duration of all garbage collection events'))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'fast-total_garbage_collection_outside_idle',
+        'ms', v8_stats.total_gc_thread_duration_outside_idle,
+        'Total thread duration of all garbage collection events outside of idle'
+        'notifications'))

tools/telemetry/telemetry/web_perf/metrics/fast_metric_unittest.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 logging
+import StringIO
+import unittest
+
+from telemetry.results import page_test_results
+from telemetry.timeline import model as model_module
+from telemetry.timeline import async_slice
+from telemetry.web_perf import timeline_interaction_record as tir_module
+from telemetry.web_perf.metrics import fast_metric
+
+
+class RendererThreadHelper(object):
+  def __init__(self, wall_start, wall_duration, thread_start, thread_duration):
+    self._model = model_module.TimelineModel()
+    renderer_process = self._model.GetOrCreateProcess(1)
+    self._renderer_thread = renderer_process.GetOrCreateThread(2)
+    self._renderer_thread.name = 'CrRendererMain'
+    self._renderer_thread.BeginSlice('cat1', 'x.y', wall_start, thread_start)
+    self._renderer_thread.EndSlice(wall_start + wall_duration,
+                                   thread_start + thread_duration)
+    self._async_slices = []
+
+  def AddInteraction(self, logical_name='LogicalName', **kwargs):
+    # Rename kwargs for AsyncSlice.
+    kwargs['timestamp'] = kwargs.pop('wall_start')
+    kwargs['duration'] = kwargs.pop('wall_duration')
+
+    self._async_slices.append(async_slice.AsyncSlice(
+        'cat', 'Interaction.%s/is_fast' % logical_name,
+        start_thread=self._renderer_thread, end_thread=self._renderer_thread,
+        **kwargs))
+
+  def AddEvent(self, category, name, wall_start, wall_duration, thread_start,
+               thread_duration):
+    self._renderer_thread.BeginSlice(category, name, wall_start, thread_start)
+    self._renderer_thread.EndSlice(wall_start + wall_duration,
+                                   thread_start + thread_duration)
+
+  def MeasureFakePage(self, metric):
+    self._renderer_thread.async_slices.extend(self._async_slices)
+    self._model.FinalizeImport()
+    interaction_records = [
+        tir_module.TimelineInteractionRecord.FromAsyncEvent(s)
+        for s in self._async_slices]
+    results = page_test_results.PageTestResults()
+    fake_page = None
+    results.WillRunPage(fake_page)
+    metric.AddResults(self._model, self._renderer_thread, interaction_records,
+                      results)
+    results.DidRunPage(fake_page)
+    return results
+
+
+class FastMetricTests(unittest.TestCase):
+
+  def setUp(self):
+    self.log_output = StringIO.StringIO()
+    self.stream_handler = logging.StreamHandler(self.log_output)
+    logging.getLogger().addHandler(self.stream_handler)
+
+  def tearDown(self):
+    logging.getLogger().removeHandler(self.stream_handler)
+    self.log_output.close()
+
+  def LogOutput(self):
+    return self.log_output.getvalue()
+
+  def ActualValues(self, results):
+    return sorted(
+        (v.name, v.units, v.value)
+        for v in results.all_page_specific_values
+        )
+
+  def testAddResultsWithThreadTime(self):
+    # Wall time diagram:
+    #           1         2         3         4
+    # 01234567890123456789012345678901234567890123456789
+    #      [               x.y               ]
+    #                                 [  Interaction.LogicalName/is_fast  ]
+    renderer_thread_helper = RendererThreadHelper(
+        wall_start=5, wall_duration=35, thread_start=0, thread_duration=54)
+    renderer_thread_helper.AddInteraction(
+        wall_start=32, wall_duration=37, thread_start=51, thread_duration=33)
+
+    metric = fast_metric.FastMetric()
+    results = renderer_thread_helper.MeasureFakePage(metric)
+
+    expected_values = [
+        ('fast-cpu_time', 'ms', 3),  # 54 - 51; thread overlap
+        ('fast-duration', 'ms', 37),  # total interaction wall duration
+        ('fast-idle_time', 'ms', 29),  # (32 + 37) - (5 + 35); interaction wall
+                                       # time outside of renderer wall time.
+        ('fast-incremental_marking', 'ms', 0.0),
+        ('fast-incremental_marking_outside_idle', 'ms', 0.0),
+        ('fast-mark_compactor', 'ms', 0.0),
+        ('fast-mark_compactor_outside_idle', 'ms', 0.0),
+        ('fast-scavenger', 'ms', 0.0),
+        ('fast-scavenger_outside_idle', 'ms', 0.0),
+        ('fast-total_garbage_collection', 'ms', 0.0),
+        ('fast-total_garbage_collection_outside_idle', 'ms', 0.0)
+        ]
+    self.assertEqual(expected_values, self.ActualValues(results))
+
+  def testAddResultsWithoutThreadTime(self):
+    # Wall time diagram:
+    #           1         2         3         4
+    # 01234567890123456789012345678901234567890123456789
+    #      [               x.y               ]
+    #                                 [  Interaction.LogicalName/is_fast  ]
+    renderer_thread_helper = RendererThreadHelper(
+        wall_start=5, wall_duration=35, thread_start=0, thread_duration=54)
+    renderer_thread_helper.AddInteraction(
+        wall_start=32, wall_duration=37)  # no thread_start, no thread_duration
+
+    metric = fast_metric.FastMetric()
+    results = renderer_thread_helper.MeasureFakePage(metric)
+
+    expected_values = [
+        # cpu_time is skipped because there is no thread time.
+        ('fast-duration', 'ms', 37),  # total interaction wall duration
+        ('fast-idle_time', 'ms', 29),  # (32 + 37) - (5 + 35); interaction wall
+                                       # time outside of renderer wall time.
+        ('fast-incremental_marking', 'ms', 0.0),
+        ('fast-incremental_marking_outside_idle', 'ms', 0.0),
+        ('fast-mark_compactor', 'ms', 0.0),
+        ('fast-mark_compactor_outside_idle', 'ms', 0.0),
+        ('fast-scavenger', 'ms', 0.0),
+        ('fast-scavenger_outside_idle', 'ms', 0.0),
+        ('fast-total_garbage_collection', 'ms', 0.0),
+        ('fast-total_garbage_collection_outside_idle', 'ms', 0.0)
+        ]
+    self.assertEqual(expected_values, self.ActualValues(results))
+    self.assertIn('Main thread cpu_time cannot be computed for records',
+                  self.LogOutput())
+
+  def testAddResultsWithMultipleInteractions(self):
+    # Wall time diagram:
+    #           1         2         3         4
+    # 01234567890123456789012345678901234567890123456789
+    #   [                    x.y                    ]
+    #       [ Interaction.Foo/is_fast ]     [ Interaction.Bar/is_fast ]
+    renderer_thread_helper = RendererThreadHelper(
+        wall_start=2, wall_duration=45, thread_start=0, thread_duration=101)
+    renderer_thread_helper.AddInteraction(
+        logical_name='Foo',
+        wall_start=6, wall_duration=27, thread_start=51, thread_duration=33)
+    renderer_thread_helper.AddInteraction(
+        logical_name='Bar',
+        wall_start=38, wall_duration=27, thread_start=90, thread_duration=33)
+
+    metric = fast_metric.FastMetric()
+    results = renderer_thread_helper.MeasureFakePage(metric)
+
+    expected_values = [
+        ('fast-cpu_time', 'ms', 44),  # thread overlap
+        ('fast-duration', 'ms', 54),  # 27 + 27; total interaction wall duration
+        ('fast-idle_time', 'ms', 18),  # (38 + 27) - (2 + 45); interaction wall
+                                       # time outside of renderer wall time.
+        ('fast-incremental_marking', 'ms', 0.0),
+        ('fast-incremental_marking_outside_idle', 'ms', 0.0),
+        ('fast-mark_compactor', 'ms', 0.0),
+        ('fast-mark_compactor_outside_idle', 'ms', 0.0),
+        ('fast-scavenger', 'ms', 0.0),
+        ('fast-scavenger_outside_idle', 'ms', 0.0),
+        ('fast-total_garbage_collection', 'ms', 0.0),
+        ('fast-total_garbage_collection_outside_idle', 'ms', 0.0)
+        ]
+    self.assertEqual(expected_values, self.ActualValues(results))
+
+  def testAddResultsWithGarbeCollectionEvents(self):
+    # Thread time diagram:
+    #           1         2         3         4         5
+    # 012345678901234567890123456789012345678901234567890123456789
+    #  [                    x.y                                 ]
+    #    [            Interaction.Foo/is_fast                      ]
+    #    [ Idle ]           [Idle]             [Idle]
+    #      [ S ]     [S]     [ I ]      [I]     [MC ]     [MC]
+    renderer_thread_helper = RendererThreadHelper(
+        wall_start=1, wall_duration=57, thread_start=1, thread_duration=57)
+    renderer_thread_helper.AddInteraction(
+        logical_name='Foo',
+        wall_start=3, wall_duration=58, thread_start=3, thread_duration=58)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCIdleNotification', 3, 7, 3, 7)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCIdleNotification', 22, 5, 22, 5)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCIdleNotification', 41, 5, 41, 5)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCScavenger', 5, 4, 5, 4)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCScavenger', 15, 2, 15, 2)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCIncrementalMarking', 23, 4, 23,
+                                    4)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCIncrementalMarking', 34, 2, 34,
+                                    2)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCCompactor', 42, 4, 42, 4)
+    renderer_thread_helper.AddEvent('v8', 'V8.GCCompactor', 52, 3, 52, 3)
+
+    metric = fast_metric.FastMetric()
+    results = renderer_thread_helper.MeasureFakePage(metric)
+
+    expected_values = [
+        ('fast-cpu_time', 'ms', 55),  # thread overlap
+        ('fast-duration', 'ms', 58),  # total interaction wall duration
+        ('fast-idle_time', 'ms', 3),  # (3 + 58) - (1 + 57); interaction wall
+                                       # time outside of renderer wall time.
+        ('fast-incremental_marking', 'ms', 6.0),
+        ('fast-incremental_marking_outside_idle', 'ms', 2.0),
+        ('fast-mark_compactor', 'ms', 7.0),
+        ('fast-mark_compactor_outside_idle', 'ms', 3.0),
+        ('fast-scavenger', 'ms', 6.0),
+        ('fast-scavenger_outside_idle', 'ms', 2.0),
+        ('fast-total_garbage_collection', 'ms', 19.0),
+        ('fast-total_garbage_collection_outside_idle', 'ms', 7.0)
+        ]
+    self.assertEqual(expected_values, self.ActualValues(results))

tools/telemetry/telemetry/web_perf/metrics/v8_stats.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.
+
+class EventStats(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
+
+  @property
+  def thread_duration_outside_idle(self):
+    return self.thread_duration - self.thread_duration_inside_idle
+
+
+def _FindEventStats(event_stats_list, event_name):
+  for event_stats in event_stats_list:
+    if event_stats.src_event_name == event_name:
+      return event_stats
+  return None
+
+
+def _IsDescendentOfIdleNotification(event):
+  parent = event.parent_slice
+  while parent:
+    if parent.name == 'V8.GCIdleNotification':
+      return True
+    parent = parent.parent_slice
+  return False
+
+class V8Stats(object):
+  def __init__(self, renderer_thread, interaction_records):
+    self.all_event_stats = [
+        EventStats('V8.GCIncrementalMarking',
+                   'incremental_marking',
+                   'total thread duration spent in incremental marking steps'),
+        EventStats('V8.GCScavenger',
+                   'scavenger',
+                   'total thread duration spent in scavenges'),
+        EventStats('V8.GCCompactor',
+                   'mark_compactor',
+                   'total thread duration spent in mark-sweep-compactor')]
+
+    # Find all GC events contained in an interaction record
+    for event in renderer_thread.IterAllSlices():
+      event_stats = _FindEventStats(self.all_event_stats, event.name)
+      if not event_stats:
+        continue
+      for r in interaction_records:
+        if not r.GetBounds().ContainsInterval(event.start, event.end):
+          continue
+        event_stats.thread_duration += event.thread_duration
+        if _IsDescendentOfIdleNotification(event):
+          event_stats.thread_duration_inside_idle += event.thread_duration
+
+  @property
+  def total_gc_thread_duration(self):
+    return sum(x.thread_duration for x in self.all_event_stats)
+
+  @property
+  def total_gc_thread_duration_outside_idle(self):
+    return sum(x.thread_duration_outside_idle for x in self.all_event_stats)

tools/telemetry/telemetry/web_perf/timeline_based_measurement.py

@@ -10,6 +10,7 @@ from telemetry.page import page_test
 from telemetry.timeline import model as model_module
 from telemetry.value import trace
 from telemetry.web_perf import timeline_interaction_record as tir_module
+from telemetry.web_perf.metrics import fast_metric
 from telemetry.web_perf.metrics import responsiveness_metric
 from telemetry.web_perf.metrics import smoothness
 
@@ -18,16 +19,19 @@ from telemetry.web_perf.metrics import smoothness
 # overhead increases. The user of the measurement must therefore chose between
 # a few levels of instrumentation.
 NO_OVERHEAD_LEVEL = 'no-overhead'
+V8_OVERHEAD_LEVEL = 'v8-overhead'
 MINIMAL_OVERHEAD_LEVEL = 'minimal-overhead'
 DEBUG_OVERHEAD_LEVEL = 'debug-overhead'
 
 ALL_OVERHEAD_LEVELS = [
   NO_OVERHEAD_LEVEL,
+  V8_OVERHEAD_LEVEL,
   MINIMAL_OVERHEAD_LEVEL,
   DEBUG_OVERHEAD_LEVEL
 ]
 
 DEFAULT_METRICS = {
+  tir_module.IS_FAST: fast_metric.FastMetric,
   tir_module.IS_SMOOTH: smoothness.SmoothnessMetric,
   tir_module.IS_RESPONSIVE: responsiveness_metric.ResponsivenessMetric,
 }
@@ -138,8 +142,9 @@ class Options(object):
     and the tracing is filtered accordingly.
 
     overhead_level: Can either be a custom TracingCategoryFilter object or
-        one of NO_OVERHEAD_LEVEL, MINIMAL_OVERHEAD_LEVEL or
-        DEBUG_OVERHEAD_LEVEL.
+        one of NO_OVERHEAD_LEVEL, V8_OVERHEAD_LEVEL, MINIMAL_OVERHEAD_LEVEL,
+        or DEBUG_OVERHEAD_LEVEL. The v8 overhead level is a temporary solution
+        that may be removed.
     get_metrics_from_flags_callback: Callback function which returns a
         a list of metrics based on timeline record flags. See the default
         _GetMetricsFromFlags() as an example.
@@ -219,6 +224,11 @@ class TimelineBasedMeasurement(object):
 
       if self._tbm_options.overhead_level == NO_OVERHEAD_LEVEL:
         category_filter = tracing_category_filter.CreateNoOverheadFilter()
+      # TODO(ernstm): Remove this overhead level when benchmark relevant v8
+      # events become available in the 'benchmark' category.
+      elif self._tbm_options.overhead_level == V8_OVERHEAD_LEVEL:
+        category_filter = tracing_category_filter.CreateNoOverheadFilter()
+        category_filter.AddIncludedCategory('v8')
       elif self._tbm_options.overhead_level == MINIMAL_OVERHEAD_LEVEL:
         category_filter = tracing_category_filter.CreateMinimalOverheadFilter()
       else:

tools/telemetry/telemetry/web_perf/timeline_based_measurement_unittest.py

@@ -22,6 +22,16 @@ from telemetry.web_perf import timeline_interaction_record as tir_module
 from telemetry.web_perf.metrics import timeline_based_metric
 
 
+class FakeFastMetric(timeline_based_metric.TimelineBasedMetric):
+
+  def AddResults(self, model, renderer_thread, interaction_records, results):
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'FakeFastMetric', 'ms', 1))
+    results.AddValue(scalar.ScalarValue(
+        results.current_page, 'FastMetricRecords', 'count',
+        len(interaction_records)))
+
+
 class FakeSmoothMetric(timeline_based_metric.TimelineBasedMetric):
 
   def AddResults(self, model, renderer_thread, interaction_records, results):
@@ -43,6 +53,7 @@ class FakeLoadingMetric(timeline_based_metric.TimelineBasedMetric):
 
 
 FAKE_METRICS_METRICS = {
+  tir_module.IS_FAST: FakeFastMetric,
   tir_module.IS_SMOOTH: FakeSmoothMetric,
   tir_module.IS_RESPONSIVE: FakeLoadingMetric,
 }
@@ -126,7 +137,7 @@ class TimelineBasedMetricsTests(unittest.TestCase):
     d.AddInteraction(d.renderer_thread, ts=25, duration=5,
                      marker='Interaction.LogicalName2/is_responsive')
     d.AddInteraction(d.foo_thread, ts=50, duration=15,
-                     marker='Interaction.LogicalName3/is_smooth')
+                     marker='Interaction.LogicalName3/is_fast')
     d.FinalizeImport()
 
     self.assertEquals(2, len(d.threads_to_records_map))
@@ -147,7 +158,7 @@ class TimelineBasedMetricsTests(unittest.TestCase):
     self.assertIn(d.foo_thread, d.threads_to_records_map)
     interactions = d.threads_to_records_map[d.foo_thread]
     self.assertEquals(1, len(interactions))
-    self.assertTrue(interactions[0].is_smooth)
+    self.assertTrue(interactions[0].is_fast)
     self.assertEquals(50, interactions[0].start)
     self.assertEquals(65, interactions[0].end)
 
@@ -157,12 +168,16 @@ class TimelineBasedMetricsTests(unittest.TestCase):
                      marker='Interaction.LogicalName1/is_smooth')
     d.AddInteraction(d.foo_thread, ts=25, duration=5,
                      marker='Interaction.LogicalName2/is_responsive')
+    d.AddInteraction(d.renderer_thread, ts=50, duration=15,
+                     marker='Interaction.LogicalName3/is_fast')
     d.FinalizeImport()
     d.AddResults()
     self.assertEquals(1, len(d.results.FindAllPageSpecificValuesNamed(
         'LogicalName1-FakeSmoothMetric')))
     self.assertEquals(1, len(d.results.FindAllPageSpecificValuesNamed(
         'LogicalName2-FakeLoadingMetric')))
+    self.assertEquals(1, len(d.results.FindAllPageSpecificValuesNamed(
+        'LogicalName3-FakeFastMetric')))
 
   def testDuplicateInteractionsInDifferentThreads(self):
     d = TimelineBasedMetricTestData()
@@ -262,6 +277,44 @@ class TimelineBasedMeasurementTest(page_test_test_case.PageTestTestCase):
         'DrawerAnimation-frame_time_discrepancy')
     self.assertEquals(len(v), 1)
 
+  # This test is flaky when run in parallel on the mac: crbug.com/426676
+  # Also, fails on android: crbug.com/437057
+  @decorators.Disabled('android', 'mac')
+  def testFastTimelineBasedMeasurementForSmoke(self):
+    ps = self.CreateEmptyPageSet()
+    ps.AddUserStory(TestTimelinebasedMeasurementPage(
+        ps, ps.base_dir, trigger_slow=True))
+
+    tbm = tbm_module.TimelineBasedMeasurement(tbm_module.Options())
+    measurement = tbm_module.TimelineBasedPageTest(tbm)
+    results = self.RunMeasurement(measurement, ps, options=self._options)
+
+    self.assertEquals([], results.failures)
+    expected_names = set([
+        'SlowThreadJsRun-fast-duration',
+        'SlowThreadJsRun-fast-idle_time',
+        'SlowThreadJsRun-fast-incremental_marking',
+        'SlowThreadJsRun-fast-incremental_marking_outside_idle',
+        'SlowThreadJsRun-fast-mark_compactor',
+        'SlowThreadJsRun-fast-mark_compactor_outside_idle',
+        'SlowThreadJsRun-fast-scavenger',
+        'SlowThreadJsRun-fast-scavenger_outside_idle',
+        'SlowThreadJsRun-fast-total_garbage_collection',
+        'SlowThreadJsRun-fast-total_garbage_collection_outside_idle',
+        'trace',
+        ])
+    if platform.GetHostPlatform().GetOSName() != 'win':
+      # CPU metric is only supported non-Windows platforms.
+      expected_names.add('SlowThreadJsRun-fast-cpu_time')
+    self.assertEquals(
+        expected_names, set(v.name for v in results.all_page_specific_values))
+
+    # In interaction_enabled_page.html, the "slow" interaction executes
+    # a loop with window.performance.now() to wait 200ms.
+    # fast-duration measures wall time so its value should be at least 200ms.
+    v = results.FindAllPageSpecificValuesNamed('SlowThreadJsRun-fast-duration')
+    self.assertGreaterEqual(v[0].value, 200.0)
+
   # Disabled since mainthread_jank metric is not supported on windows platform.
   # Also, flaky on the mac when run in parallel: crbug.com/426676
   # Also, fails on android: crbug.com/437057

tools/telemetry/telemetry/web_perf/timeline_interaction_record.py

@@ -7,6 +7,8 @@ import re
 import telemetry.timeline.bounds as timeline_bounds
 from telemetry import decorators
 
+# Enables the fast metric for this interaction
+IS_FAST = 'is_fast'
 # Enables the responsiveness metric for this interaction
 IS_RESPONSIVE = 'is_responsive'
 # Enables the smoothness metric for this interaction
@@ -15,6 +17,7 @@ IS_SMOOTH = 'is_smooth'
 REPEATABLE = 'repeatable'
 
 METRICS = [
+    IS_FAST,
     IS_RESPONSIVE,
     IS_SMOOTH
 ]
@@ -85,7 +88,7 @@ class TimelineInteractionRecord(object):
   is currently done by pushing markers into the console.time/timeEnd API: this
   for instance can be issued in JS:
 
-     var str = 'Interaction.SendEmail/is_smooth,is_responsive';
+     var str = 'Interaction.SendEmail/is_smooth,is_responsive,is_fast';
      console.time(str);
      setTimeout(function() {
        console.timeEnd(str);
@@ -93,10 +96,11 @@ class TimelineInteractionRecord(object):
 
   When run with perf.measurements.timeline_based_measurement running, this will
   then cause a TimelineInteractionRecord to be created for this range with
-  smoothness and responsive metrics reported for the marked up 1000ms
+  smoothness, responsive, and fast metrics reported for the marked up 1000ms
   time-range.
 
   The valid interaction flags are:
+     * is_fast: Enables the fast metric
      * is_responsive: Enables the responsiveness metric
      * is_smooth: Enables the smoothness metric
      * repeatable: Allows other interactions to use the same label
@@ -123,6 +127,10 @@ class TimelineInteractionRecord(object):
   def end(self):
     return self._end
 
+  @property
+  def is_fast(self):
+    return IS_FAST in self._flags
+
   @property
   def is_responsive(self):
     return IS_RESPONSIVE in self._flags