[telemetry] Implement first version of timeline based measurement

TimelineBasedMeasurement lets us compute a variety of different metrics for pages that do complex sequences of interactions. Whereas traditional telemetry measurements focus on reporting a single type of value for many pages, this lets a page decide what types of metrics it emits based on the behaviors its page actually performs.

The contract is that the page emits
console.time/timeEnd calls of a certain format describing when it is doing
something worth noting, and what kind fo interaction it is doing. For instance,
if a drawer animation is runnign, it would emit:
  MeasurementRequest.Drawer/smoothness

This tells the timelineBasedMeasurement that the timeline data generated during this time
should be analyzed for smoothness information, with results benig reported as things like
Drawer.frame_time.

Depends on https://codereview.chromium.org/177093013

BUG=345922
NOTRY=True

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

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@255434 0039d316-1c4b-4281-b951-d872f2087c98

tools/perf/measurements/timeline_based_measurement.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.
+
+from metrics import timeline as timeline_module
+from metrics import timeline_interaction_record as tir_module
+from telemetry.page import page_measurement
+from telemetry.core.timeline import model as model_module
+
+
+
+# TimelineBasedMeasurement considers all instrumentation as producing a single
+# timeline. But, depending on the amount of instrumentation that is enabled,
+# overhead increases. The user of the measurement must therefore chose between
+# a few levels of instrumentation.
+NO_OVERHEAD_LEVEL = 'no-overhead'
+MINIMAL_OVERHEAD_LEVEL = 'minimal-overhead'
+DEBUG_OVERHEAD_LEVEL = 'debug-overhead'
+
+ALL_OVERHEAD_LEVELS = [
+  NO_OVERHEAD_LEVEL,
+  MINIMAL_OVERHEAD_LEVEL,
+  DEBUG_OVERHEAD_LEVEL
+]
+
+
+class _TimelineBasedMetrics(object):
+  def __init__(self, model, renderer_thread):
+    self._model = model
+    self._renderer_thread = renderer_thread
+
+  def FindTimelineInteractionRecords(self):
+    # TODO(nduca): Add support for page-load interaction record.
+    return [tir_module.TimelineInteractionRecord(event) for
+            event in self._renderer_thread.IterAllAsyncSlices()
+            if tir_module.IsTimelineInteractionRecord(event.name)]
+
+  def CreateMetricsForTimelineInteractionRecord(self, interaction):
+    res = []
+    if interaction.is_smooth:
+      pass # TODO(nduca): res.append smoothness metric instance.
+    return res
+
+  def AddResults(self, results):
+    interactions = self.FindTimelineInteractionRecords()
+    if len(interactions) == 0:
+      raise Exception('Expected at least one Interaction on the page')
+    for interaction in interactions:
+      metrics = self.CreateMetricsForTimelineInteractionRecord(interaction)
+      for m in metrics:
+        m.AddResults(self._model, self._renderer_thread,
+                     interaction, results)
+
+
+class TimelineBasedMeasurement(page_measurement.PageMeasurement):
+  """Collects multiple metrics pages based on their interaction records.
+
+  A timeline measurement shifts the burden of what metrics to collect onto the
+  page under test, or the pageset running that page. Instead of the measurement
+  having a fixed set of values it collects about the page, the page being tested
+  issues (via javascript) an Interaction record into the user timing API that
+  describing what the page is doing at that time, as well as a standardized set
+  of flags describing the semantics of the work being done. The
+  TimelineBasedMeasurement object collects a trace that includes both these
+  interaction recorsd, and a user-chosen amount of performance data using
+  Telemetry's various timeline-producing APIs, tracing especially.
+
+  It then passes the recorded timeline to different TimelineBasedMetrics based
+  on those flags. This allows a single run through a page to produce load timing
+  data, smoothness data, critical jank information and overall cpu usage
+  information.
+
+  For information on how to mark up a page to work with
+  TimelineBasedMeasurement, refer to the
+  perf.metrics.timeline_interaction_record module.
+
+  """
+  def __init__(self):
+    super(TimelineBasedMeasurement, self).__init__('smoothness')
+
+  def AddCommandLineOptions(self, parser):
+    parser.add_option(
+        '--overhead-level', type='choice',
+        choices=ALL_OVERHEAD_LEVELS,
+        default=NO_OVERHEAD_LEVEL,
+        help='How much overhead to incur during the measurement.')
+
+  def CanRunForPage(self, page):
+    return hasattr(page, 'smoothness')
+
+  def WillNavigateToPage(self, page, tab):
+    if not tab.browser.supports_tracing:
+      raise Exception('Not supported')
+    assert self.options.overhead_level in ALL_OVERHEAD_LEVELS
+    if self.options.overhead_level == NO_OVERHEAD_LEVEL:
+      categories = timeline_module.MINIMAL_TRACE_CATEGORIES
+    elif self.options.overhead_level == \
+        MINIMAL_OVERHEAD_LEVEL:
+      categories = ''
+    else:
+      categories = '*,disabled-by-default-cc.debug'
+    tab.browser.StartTracing(categories)
+
+  def MeasurePage(self, page, tab, results):
+    """ Collect all possible metrics and added them to results. """
+    trace_result = tab.browser.StopTracing()
+    model = model_module.TimelineModel(trace_result)
+    renderer_thread = model.GetRendererThreadFromTab(tab)
+    meta_metrics = _TimelineBasedMetrics(model, renderer_thread)
+    meta_metrics.AddResults(results)

tools/perf/measurements/timeline_based_measurement_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 os
+import unittest
+
+from measurements import timeline_based_measurement as tbm_module
+from metrics import timeline_based_metric
+from telemetry.core import wpr_modes
+from telemetry.core.timeline import model as model_module
+from telemetry.core.timeline import async_slice
+from telemetry.page import page_measurement_results
+from telemetry.page import page_measurement_unittest_base
+from telemetry.page import page_set
+from telemetry.unittest import options_for_unittests
+
+class TimelineBasedMetricsTests(unittest.TestCase):
+  def setUp(self):
+    model = model_module.TimelineModel()
+    renderer_thread = model.GetOrCreateProcess(1).GetOrCreateThread(2)
+    renderer_thread.name = 'CrRendererMain'
+
+    # [      X       ]
+    #      [  Y  ]
+    renderer_thread.BeginSlice('cat1', 'x.y', 10, 0)
+    renderer_thread.EndSlice(20, 20)
+
+    renderer_thread.async_slices.append(async_slice.AsyncSlice(
+        'cat', 'Interaction.LogicalName1/is_smooth',
+        timestamp=0, duration=20,
+        start_thread=renderer_thread, end_thread=renderer_thread))
+    renderer_thread.async_slices.append(async_slice.AsyncSlice(
+        'cat', 'Interaction.LogicalName2/is_loading_resources',
+        timestamp=25, duration=5,
+        start_thread=renderer_thread, end_thread=renderer_thread))
+    model.FinalizeImport()
+
+    self.model = model
+    self.renderer_thread = renderer_thread
+
+  def testFindTimelineInteractionRecords(self):
+    metric = tbm_module._TimelineBasedMetrics( # pylint: disable=W0212
+        self.model, self.renderer_thread)
+    interactions = metric.FindTimelineInteractionRecords()
+    self.assertEquals(2, len(interactions))
+    self.assertTrue(interactions[0].is_smooth)
+    self.assertEquals(0, interactions[0].start)
+    self.assertEquals(20, interactions[0].end)
+
+    self.assertTrue(interactions[1].is_loading_resources)
+    self.assertEquals(25, interactions[1].start)
+    self.assertEquals(30, interactions[1].end)
+
+  def testAddResults(self):
+    results = page_measurement_results.PageMeasurementResults()
+    class FakeSmoothMetric(timeline_based_metric.TimelineBasedMetric):
+      def AddResults(self, model, renderer_thread,
+                     interaction_record, results):
+        results.Add(
+            interaction_record.GetResultNameFor('FakeSmoothMetric'), 'ms', 1)
+
+    class FakeLoadingMetric(timeline_based_metric.TimelineBasedMetric):
+      def AddResults(self, model, renderer_thread,
+                     interaction_record, results):
+        assert interaction_record.logical_name == 'LogicalName2'
+        results.Add(
+            interaction_record.GetResultNameFor('FakeLoadingMetric'), 'ms', 2)
+
+    class TimelineBasedMetricsWithFakeMetricHandler(
+        tbm_module._TimelineBasedMetrics): # pylint: disable=W0212
+      def CreateMetricsForTimelineInteractionRecord(self, interaction):
+        res = []
+        if interaction.is_smooth:
+          res.append(FakeSmoothMetric())
+        if interaction.is_loading_resources:
+          res.append(FakeLoadingMetric())
+        return res
+
+    metric = TimelineBasedMetricsWithFakeMetricHandler(
+        self.model, self.renderer_thread)
+    ps = page_set.PageSet.FromDict({
+      "description": "hello",
+      "archive_path": "foo.wpr",
+      "pages": [
+        {"url": "http://www.bar.com/"}
+      ]
+    }, os.path.dirname(__file__))
+    results.WillMeasurePage(ps.pages[0])
+    metric.AddResults(results)
+    results.DidMeasurePage()
+
+    v = results.FindAllPageSpecificValuesNamed('LogicalName1/FakeSmoothMetric')
+    self.assertEquals(len(v), 1)
+    v = results.FindAllPageSpecificValuesNamed('LogicalName2/FakeLoadingMetric')
+    self.assertEquals(len(v), 1)
+
+
+class TimelineBasedMeasurementTest(
+      page_measurement_unittest_base.PageMeasurementUnitTestBase):
+  def setUp(self):
+    self._options = options_for_unittests.GetCopy()
+    self._options.browser_options.wpr_mode = wpr_modes.WPR_OFF
+
+  def testTimelineBasedForSmoke(self):
+    ps = self.CreatePageSetFromFileInUnittestDataDir(
+        'interaction_enabled_page.html')
+    setattr(ps.pages[0], 'smoothness', {'action': 'wait',
+                                        'javascript': 'window.animationDone'})
+    measurement = tbm_module.TimelineBasedMeasurement()
+    results = self.RunMeasurement(measurement, ps,
+                                  options=self._options)
+    self.assertEquals(0, len(results.failures))

tools/perf/metrics/timeline_based_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.
+
+class TimelineBasedMetric(object):
+  def __init__(self):
+    """Computes metrics from a telemetry.core.timeline Model and a range
+
+    """
+    super(TimelineBasedMetric, self).__init__()
+
+  def AddResults(self, model, renderer_thread,
+                 interaction_record, results):
+    """Computes and adds metrics for the interaction_record's time range.
+
+    The override of this method should compute results on the data **only**
+    within the interaction_record's start and end time.
+
+    model is an instance of telemetry.core.timeline.model.TimelineModel.
+    interaction_record is an instance of TimelineInteractionRecord.
+    results is an instance of page.PageTestResults.
+
+    """
+    raise NotImplementedError()

tools/perf/metrics/timeline_interaction_record.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 re
+
+
+def IsTimelineInteractionRecord(event_name):
+  return event_name.startswith('Interaction.')
+
+
+class TimelineInteractionRecord(object):
+  """Represents an interaction that took place during a timeline recording.
+
+  As a page runs, typically a number of different (simulated) user interactions
+  take place. For instance, a user might click a button in a mail app causing a
+  popup to animate in. Then they might press another button that sends data to a
+  server and simultaneously closes the popup without an animation. These are two
+  interactions.
+
+  From the point of view of the page, each interaction might have a different
+  logical name: ClickComposeButton and SendEmail, for instance. From the point
+  of view of the benchmarking harness, the names aren't so interesting as what
+  the performance expectations are for that interaction: was it loading
+  resources from the network? was there an animation?
+
+  Determining these things is hard to do, simply by observing the state given to
+  a page from javascript. There are hints, for instance if network requests are
+  sent, or if a CSS animation is pending. But this is by no means a complete
+  story.
+
+  Instead, we expect pages to mark up the timeline what they are doing, with
+  logical names, and flags indicating the semantics of that interaction. This
+  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_loading_resources';
+     console.time(str);
+     setTimeout(function() {
+       console.timeEnd(str);
+     }, 1000);
+
+  When run with perf.measurements.timeline_based_measurement running, this will
+  then cause a TimelineInteractionRecord to be created for this range and both
+  smoothness and network metrics to be reported for the marked up 1000ms
+  time-range.
+
+  """
+  def __init__(self, event):
+    self.start = event.start
+    self.end = event.end
+
+    m = re.match('Interaction\.(.+)\/(.+)', event.name)
+    if m:
+      self.logical_name = m.group(1)
+      if m.group(1) != '':
+        flags = m.group(2).split(',')
+      else:
+        flags = []
+    else:
+      m = re.match('Interaction\.(.+)', event.name)
+      assert m
+      self.logical_name = m.group(1)
+      flags = []
+
+    for f in flags:
+      if not f in ('is_smooth', 'is_loading_resources'):
+        raise Exception(
+          'Unrecognized flag in timeline Interaction record: %s' % f)
+    self.is_smooth = 'is_smooth' in flags
+    self.is_loading_resources = 'is_loading_resources' in flags
+
+  def GetResultNameFor(self, result_name):
+    return "%s/%s" % (self.logical_name, result_name)

tools/perf/metrics/timeline_interaction_record_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 unittest
+
+from metrics import timeline_interaction_record
+from telemetry.core.timeline import async_slice
+
+
+class ParseTests(unittest.TestCase):
+  def testParse(self):
+    self.assertTrue(timeline_interaction_record.IsTimelineInteractionRecord(
+        'Interaction.Foo'))
+    self.assertTrue(timeline_interaction_record.IsTimelineInteractionRecord(
+        'Interaction.Foo/Bar'))
+    self.assertFalse(timeline_interaction_record.IsTimelineInteractionRecord(
+        'SomethingRandom'))
+
+  def CreateRecord(self, event_name):
+    s = async_slice.AsyncSlice(
+      'cat', event_name,
+      timestamp=1, duration=2)
+    return timeline_interaction_record.TimelineInteractionRecord(s)
+
+  def testCreate(self):
+    r = self.CreateRecord('Interaction.LogicalName')
+    self.assertEquals('LogicalName', r.logical_name)
+    self.assertEquals(False, r.is_smooth)
+    self.assertEquals(False, r.is_loading_resources)
+
+    r = self.CreateRecord('Interaction.LogicalName/is_smooth')
+    self.assertEquals('LogicalName', r.logical_name)
+    self.assertEquals(True, r.is_smooth)
+    self.assertEquals(False, r.is_loading_resources)
+
+    r = self.CreateRecord('Interaction.LogicalNameWith/Slash/is_smooth')
+    self.assertEquals('LogicalNameWith/Slash', r.logical_name)
+    self.assertEquals(True, r.is_smooth)
+    self.assertEquals(False, r.is_loading_resources)
+
+    r = self.CreateRecord(
+        'Interaction.LogicalNameWith/Slash/is_smooth,is_loading_resources')
+    self.assertEquals('LogicalNameWith/Slash', r.logical_name)
+    self.assertEquals(True, r.is_smooth)
+    self.assertEquals(True, r.is_loading_resources)

tools/telemetry/telemetry/core/backends/chrome/tracing_timeline_data.py

@@ -32,5 +32,7 @@ class TracingTimelineData(TimelineData):
     for key, value in self._tab_to_marker_mapping.iteritems():
       timeline_markers = timeline.FindTimelineMarkers(value)
       assert(len(timeline_markers) == 1)
-      renderer_process = timeline_markers[0].start_thread.parent
-      timeline.AddCoreObjectToContainerMapping(key, renderer_process)
+      assert(timeline_markers[0].start_thread ==
+             timeline_markers[0].end_thread)
+      renderer_thread = timeline_markers[0].start_thread
+      timeline.AddCoreObjectToContainerMapping(key, renderer_thread)

tools/telemetry/telemetry/core/timeline/async_slice.py

@@ -9,12 +9,13 @@ class AsyncSlice(event.TimelineEvent):
   asynchronous operation is in progress. An AsyncSlice consumes no CPU time
   itself and so is only associated with Threads at its start and end point.
   '''
-  def __init__(self, category, name, timestamp, args=None):
+  def __init__(self, category, name, timestamp, args=None,
+               duration=0, start_thread=None, end_thread=None):
     super(AsyncSlice, self).__init__(
-        category, name, timestamp, duration=0, args=args)
+        category, name, timestamp, duration=duration, args=args)
     self.parent_slice = None
-    self.start_thread = None
-    self.end_thread = None
+    self.start_thread = start_thread
+    self.end_thread = end_thread
     self.sub_slices = []
     self.id = None
 

tools/telemetry/telemetry/core/timeline/model.py

@@ -233,6 +233,9 @@ class TimelineModel(object):
     return events
 
   def GetRendererProcessFromTab(self, tab):
+    return self._core_object_to_timeline_container_map[tab].parent
+
+  def GetRendererThreadFromTab(self, tab):
     return self._core_object_to_timeline_container_map[tab]
 
   def AddCoreObjectToContainerMapping(self, core_object, container):

tools/telemetry/unittest_data/interaction_enabled_page.html

+<!doctype html>
+<html>
+  <head>
+    <style type="text/css">
+      body { height: 1500px; }
+      #center {
+         position: fixed;
+         left: 40%;;
+         width: 50%;
+         height: 250px;
+         top: 25%;
+         background-color: grey;
+         -webkit-transform: scale(0.25, 0.25);
+         -webkit-transition: -webkit-transform 1s;
+      }
+
+      #drawer {
+         position: fixed;
+         top: 0;
+         left: 0;
+         height: 100%;
+         width: 120px;
+         background-color: red;
+         -webkit-transform: translate3d(-1000px, 0, 0);
+         -webkit-transition: -webkit-transform 1s;
+      }
+
+    </style>
+    <script>
+    'use strict';
+    window.animationDone = false;
+    window.addEventListener('load', function() {
+      var centerEl = document.querySelector('#center');
+      centerEl.style.webkitTransform = 'scale(1.0, 1.0)';
+      console.time('Interaction.CenterAnimation/is_smooth');
+      centerEl.addEventListener('transitionend', function() {
+        console.timeEnd('Interaction.CenterAnimation/is_smooth');
+        var drawerEl = document.querySelector('#drawer');
+        drawerEl.style.webkitTransform = 'translate3D(0, 0, 0)';
+        console.time('Interaction.DrawerAnimation/is_smooth');
+        drawerEl.addEventListener('transitionend', function() {
+          console.timeEnd('Interaction.DrawerAnimation/is_smooth');
+          window.animationDone = true;
+        });
+      });
+    });
+    </script>
+  </head>
+  <body>
+    <div id="center">
+      This is something in the middle.
+    </div>
+    <div id="drawer">
+      This is a drawer.
+    </div>
+  </body>
+</html>