Support tracing metrics for measureTime & measureFrameTime method in blink_perf

tools/perf/benchmarks/blink_perf.py

 # Copyright 2013 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
 
 from core import path_util
 from core import perf_benchmark
 
 from telemetry import benchmark
 from telemetry import page as page_module
 from telemetry.page import legacy_page_test
 from telemetry.page import shared_page_state
 from telemetry import story
+from telemetry.timeline import bounds
+from telemetry.timeline import model as model_module
+from telemetry.timeline import tracing_config
+
 from telemetry.value import list_of_scalar_values
 from telemetry.value import scalar
+from telemetry.value import trace
+
 
 from benchmarks import pywebsocket_server
 from measurements import timeline_controller
 from page_sets import webgl_supported_shared_state
 
 
 BLINK_PERF_BASE_DIR = os.path.join(path_util.GetChromiumSrcDir(),
                                    'third_party', 'WebKit', 'PerformanceTests')
 SKIPPED_FILE = os.path.join(BLINK_PERF_BASE_DIR, 'Skipped')
 
@@ skipping 64 matching lines @@
         '--js-flags=--expose_gc',
         '--enable-experimental-web-platform-features',
         '--disable-gesture-requirement-for-media-playback',
         '--enable-experimental-canvas-features',
         # TODO(qinmin): After fixing crbug.com/592017, remove this command line.
         '--reduce-security-for-testing'
     ])
     if 'content-shell' in options.browser_type:
       options.AppendExtraBrowserArgs('--expose-internals-for-testing')
 
+  def _ContinueTestRunWithTracing(self, tab):
+    tracing_categories = tab.EvaluateJavaScript(
+        'testRunner.tracingCategories')
+    config = tracing_config.TracingConfig()
+    config.enable_chrome_trace = True
+    config.chrome_trace_config.category_filter.AddFilterString(
+        'blink.console')  # This is always required for js land trace event
+    config.chrome_trace_config.category_filter.AddFilterString(
+        tracing_categories)
+    tab.browser.platform.tracing_controller.StartTracing(config)
+    tab.EvaluateJavaScript('testRunner.scheduleTestRun()')
+    tab.WaitForJavaScriptCondition('testRunner.isDone')
+    return tab.browser.platform.tracing_controller.StopTracing()
+
+  def _ComputeTraceEventsThreadTime(self, trace_results,
+                                    trace_events_to_measure, tab_id):
+    trace_cpu_time_metrics = {}
+
+    # Collect the bounds of "blink_perf.runTest" events.
+    model = model_module.TimelineModel(trace_results)
+    renderer_thread = model.GetRendererThreadFromTabId(tab_id)
+    test_runs_bounds = []
+    for event in renderer_thread.async_slices:
+      if event.name == "blink_perf.runTest":
+        test_runs_bounds.append(bounds.Bounds.CreateFromEvent(event))
+    test_runs_bounds.sort(key=lambda b: b.min)
+
+    for t in trace_events_to_measure:
+      trace_cpu_time_metrics[t] = [0.0] * len(test_runs_bounds)
+
+    for event_name in trace_events_to_measure:
+      curr_test_runs_bound_index = 0
+      for event in renderer_thread.IterAllSlicesOfName(event_name):
+        while (curr_test_runs_bound_index < len(test_runs_bounds) and
+               event.start > test_runs_bounds[curr_test_runs_bound_index].max):
+          curr_test_runs_bound_index +=  1

[Xianzhu, 2017/04/21 01:31:51]

Nit: remove extra space before '1'.

[nednguyen, 2017/04/24 20:55:21]

Done.

+        if curr_test_runs_bound_index >= len(test_runs_bounds):
+          break
+        curr_test_bound = test_runs_bounds[curr_test_runs_bound_index]
+        intersect_wall_time = bounds.Bounds.GetOverlapBetweenBounds(
+            curr_test_bound, bounds.Bounds.CreateFromEvent(event))
+        intersect_cpu_time = (
+            intersect_wall_time * event.thread_duration / event.duration)
+        trace_cpu_time_metrics[event_name][curr_test_runs_bound_index] += (
+            intersect_cpu_time)
+
+    return trace_cpu_time_metrics
+
+  def PrintAndCollectTraceEventMetrics(self, trace_cpu_time_metrics, results):
+    unit = 'ms'
+    print
+    for trace_event_name, cpu_times in trace_cpu_time_metrics.iteritems():
+      print 'CPU times of trace event "%s":' % trace_event_name
+      cpu_times_string = ', '.join(['{0:.10f}'.format(t) for t in cpu_times])
+      print 'values %s %s' % (cpu_times_string, unit)
+      avg = 0.0
+      if cpu_times:
+        avg = sum(cpu_times)/len(cpu_times)
+      print 'avg', '{0:.10f}'.format(avg), unit
+      results.AddValue(list_of_scalar_values.ListOfScalarValues(
+          results.current_page, name=trace_event_name, units=unit,
+          values=cpu_times))
+      print
+    print '\n'
+
   def ValidateAndMeasurePage(self, page, tab, results):
-    tab.WaitForJavaScriptCondition('testRunner.isDone', timeout=600)
+    tab.WaitForJavaScriptCondition(
+    'testRunner.isDone || testRunner.isWaitingForTracingStart', timeout=600)

[Xianzhu, 2017/04/21 01:31:51]

Nit: indent

[nednguyen, 2017/04/24 20:55:21]

Done.

+    trace_cpu_time_metrics = {}
+    if tab.EvaluateJavaScript('testRunner.isWaitingForTracingStart'):
+      trace_result = self._ContinueTestRunWithTracing(tab)
+      trace_value = trace.TraceValue(page, trace_result)
+      results.AddValue(trace_value)
+      trace_events_to_measure = tab.EvaluateJavaScript(
+          'window.testRunner.traceEventsToMeasure')
+      trace_cpu_time_metrics = self._ComputeTraceEventsThreadTime(
+          trace_result, trace_events_to_measure, tab.id)
 
     log = tab.EvaluateJavaScript('document.getElementById("log").innerHTML')
 
     for line in log.splitlines():
       if line.startswith("FATAL: "):
         print line
         continue
       if not line.startswith('values '):
         continue
       parts = line.split()
       values = [float(v.replace(',', '')) for v in parts[1:-1]]
       units = parts[-1]
       metric = page.display_name.split('.')[0].replace('/', '_')
       results.AddValue(list_of_scalar_values.ListOfScalarValues(
           results.current_page, metric, units, values))
 
       break
 
     print log
 
+    self.PrintAndCollectTraceEventMetrics(trace_cpu_time_metrics, results)
+
 
 # TODO(wangxianzhu): Convert the paint benchmarks to use the new blink_perf
 # tracing once it's ready.
 class _BlinkPerfPaintMeasurement(_BlinkPerfMeasurement):
   """Also collects prePaint and paint timing from traces."""
 
   def __init__(self):
     super(_BlinkPerfPaintMeasurement, self).__init__()
     self._controller = None
 
@@ skipping 60 matching lines @@
 
   @classmethod
   def ShouldDisable(cls, possible_browser):
     # http://crbug.com/563979
     return (cls.IsSvelte(possible_browser)
       # http://crbug.com/653970
       or (possible_browser.browser_type == 'reference' and
         possible_browser.platform.GetOSName() == 'android'))
 
 
+#TODO(nednguyen): remove this before landing code
+class BlinkPerfTest(_BlinkPerfBenchmark):
+  tag = 'testing'
+  subdir = 'TestData'
+
+
 @benchmark.Enabled('content-shell')
 class BlinkPerfBlinkGC(_BlinkPerfBenchmark):
   tag = 'blink_gc'
   subdir = 'BlinkGC'
 
 
 @benchmark.Owner(emails=['rune@opera.com'])
 class BlinkPerfCSS(_BlinkPerfBenchmark):
   tag = 'css'
   subdir = 'CSS'
@@ skipping 109 matching lines @@
 
   def CreateStorySet(self, options):
     path = os.path.join(BLINK_PERF_BASE_DIR, self.subdir)
     return CreateStorySetFromPath(
         path, SKIPPED_FILE,
         shared_page_state_class=_SharedPywebsocketPageState)
 
   @classmethod
   def ShouldDisable(cls, possible_browser):
     return cls.IsSvelte(possible_browser)  # http://crbug.com/551950