To help guide development and track performance improvements in specific areas...

To help guide development and track performance improvements in specific areas this new metric will compile the top-10 slowest tasks across all the pages in a page-set.

Part of the scheduling effort is to move long-running tasks into 'idle' periods or refactor them to make them more nibble-able. Knowing which tasks we need to concentrate on is the first step in this.

It is hoped that this code will also be built-on to create a metric to find out which long-running tasks most frequently block high priority tasks (e.g. Does GC often block user input being processed?) so we can move them out of the way.

BUG=421434

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

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

tools/perf/benchmarks/task_execution_time.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 page_sets
+from measurements import task_execution_time
+from telemetry import benchmark
+
+
+@benchmark.Enabled('android')
+class TaskExecutionTimeKeyMobileSites(benchmark.Benchmark):
+  """Measures task execution statistics while scrolling down key mobile sites.
+  http://www.chromium.org/developers/design-documents/rendering-benchmarks"""
+  test = task_execution_time.TaskExecutionTime
+  page_set = page_sets.KeyMobileSitesPageSet
+
+
+@benchmark.Enabled('android')
+class TaskExecutionTimeToughSchedulingCases(benchmark.Benchmark):
+  """Measures task execution statistics while scrolling tough scheduling sites.
+  http://www.chromium.org/developers/design-documents/rendering-benchmarks"""
+  test = task_execution_time.TaskExecutionTime
+  page_set = page_sets.ToughSchedulingCasesPageSet

tools/perf/measurements/task_execution_time.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 telemetry.core.platform import tracing_category_filter
+from telemetry.core.platform import tracing_options
+from telemetry.timeline.model import TimelineModel
+from telemetry.page import page_test
+from telemetry.util import statistics
+from telemetry.value import scalar
+
+_CATEGORIES = ['webkit.console',
+              'blink.console',
+              'benchmark',
+              'toplevel',
+              'blink',
+              'cc',
+              'v8']
+
+class TaskExecutionTime(page_test.PageTest):
+
+  _TIME_OUT_IN_SECONDS = 60
+  _NUMBER_OF_RESULTS_TO_DISPLAY = 10
+
+  def __init__(self):
+    super(TaskExecutionTime, self).__init__('RunTaskExecutionTime')
+    self._renderer_thread = None
+
+  def WillNavigateToPage(self, page, tab):
+    category_filter = tracing_category_filter.TracingCategoryFilter()
+
+    for category in _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):
+    timeline_data = tab.browser.platform.tracing_controller.Stop()
+    timeline_model = TimelineModel(timeline_data=timeline_data)
+    self._renderer_thread = timeline_model.GetRendererThreadFromTabId(tab.id)
+
+  def ValidateAndMeasurePage(self, page, tab, results):
+    tasks = TaskExecutionTime.GetTasks(self._renderer_thread.parent)
+
+    sorted_tasks = sorted(tasks,
+      key=lambda slice: slice.median_self_duration, reverse=True)
+
+    for task in sorted_tasks[:self.GetExpectedResultCount()]:
+      results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        task.key,
+        'ms',
+        task.median_self_duration,
+        description = 'Slowest tasks'))
+
+  @staticmethod
+  def GetTasks(process):
+    task_dictionary = {}
+    depth = 1
+    for parent, task_slice in enumerate(
+          process.IterAllSlicesOfName('MessageLoop::RunTask')):
+      ProcessTasksForSlice(task_dictionary, task_slice, depth, parent)
+    # Return dictionary flattened into a list
+    return task_dictionary.values()
+
+  @staticmethod
+  def GetExpectedResultCount():
+    return TaskExecutionTime._NUMBER_OF_RESULTS_TO_DISPLAY
+
+
+class SliceData:
+  def __init__(self, key, self_duration, total_duration, depth, parent):
+    self.key = key
+    self.count = 1
+
+    self.self_durations = [self_duration]
+    self.min_self_duration = self_duration
+    self.max_self_duration = self_duration
+
+    self.total_durations = [total_duration]
+    self.min_total_duration = total_duration
+    self.max_total_duration = total_duration
+
+    self.tree_location = [(depth, parent)]
+
+  def Update(self, self_duration, total_duration, depth, parent):
+    self.count += 1
+
+    self.self_durations.append(self_duration)
+    self.min_self_duration = min(self.min_self_duration, self_duration)
+    self.max_self_duration = max(self.max_self_duration, self_duration)
+
+    self.total_durations.append(total_duration)
+    self.min_total_duration = min(self.min_total_duration, total_duration)
+    self.max_total_duration = max(self.max_total_duration, total_duration)
+
+    self.tree_location.append((depth, parent))
+
+  @property
+  def median_self_duration(self):
+    return statistics.Median(self.self_durations)
+
+
+def ProcessTasksForSlice(dictionary, task_slice, depth, parent):
+  # Deal with TRACE_EVENT_INSTANTs that have no duration
+  self_duration = task_slice.self_thread_time or 0.0
+  total_duration = task_slice.thread_duration or 0.0
+
+  # There is at least one task that is tracked as both uppercase and lowercase,
+  # forcing the name to lowercase coalesces both.
+  key = task_slice.name.lower()
+  if key in dictionary:
+    dictionary[key].Update(
+        self_duration, total_duration, depth, parent)
+  else:
+    dictionary[key] = SliceData(
+        key, self_duration, total_duration, depth, parent)
+
+  # Process sub slices recursively
+  for sub_slice in task_slice.sub_slices:
+    ProcessTasksForSlice(dictionary, sub_slice, depth + 1, parent)

tools/perf/measurements/task_execution_time_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.
+
+from measurements import task_execution_time
+from telemetry.core import wpr_modes
+from telemetry.page import page as page_module
+from telemetry.unittest import options_for_unittests
+from telemetry.unittest import page_test_test_case
+
+
+class TestTaskExecutionTimePage(page_module.Page):
+  def __init__(self, page_set, base_dir):
+    super(TestTaskExecutionTimePage, self).__init__(
+        'file://blank.html', page_set, base_dir)
+
+  def RunTaskExecutionTime(self, action_runner):
+    interaction = action_runner.BeginGestureInteraction(
+        'ScrollAction', is_smooth=True)
+    action_runner.ScrollPage()
+    interaction.End()
+
+
+class TaskExecutionTimeUnitTest(page_test_test_case.PageTestTestCase):
+  def setUp(self):
+    self._options = options_for_unittests.GetCopy()
+    self._options.browser_options.wpr_mode = wpr_modes.WPR_OFF
+
+  def testCorrectNumberOfResultsReturned(self):
+    ps = self.CreateEmptyPageSet()
+    ps.AddPage(TestTaskExecutionTimePage(ps, ps.base_dir))
+    measurement = task_execution_time.TaskExecutionTime()
+
+    results = self.RunMeasurement(measurement, ps, options=self._options)
+
+    self.assertEquals(
+        task_execution_time.TaskExecutionTime.GetExpectedResultCount(),
+        len(results.all_page_specific_values))
+
+  def testResultsAreDecreasing(self):
+    ps = self.CreateEmptyPageSet()
+    ps.AddPage(TestTaskExecutionTimePage(ps, ps.base_dir))
+    measurement = task_execution_time.TaskExecutionTime()
+
+    results = self.RunMeasurement(measurement, ps, options=self._options)
+
+    for first, second in zip(
+        results.all_page_specific_values, results.all_page_specific_values[1:]):
+      self.assertGreaterEqual(first.value, second.value)

tools/perf/page_sets/key_mobile_sites.py

@@ -10,7 +10,7 @@ class KeyMobileSitesPage(page_module.Page):
   def __init__(self, url, page_set, name=''):
     super(KeyMobileSitesPage, self).__init__(
         url=url, page_set=page_set, name=name,
-        credentials_path = 'data/credentials.json')
+        credentials_path='data/credentials.json')
     self.user_agent_type = 'mobile'
     self.archive_data_file = 'data/key_mobile_sites.json'
 
@@ -23,6 +23,12 @@ class KeyMobileSitesPage(page_module.Page):
   def RunRepaint(self, action_runner):
     action_runner.RepaintContinuously(seconds=5)
 
+  def RunTaskExecutionTime(self, action_runner):
+    interaction = action_runner.BeginGestureInteraction(
+        'ScrollAction', is_smooth=True)
+    action_runner.ScrollPage()
+    interaction.End()
+
 
 class Page1(KeyMobileSitesPage):
 

tools/perf/page_sets/tough_scheduling_cases.py

@@ -9,7 +9,7 @@ class ToughSchedulingCasesPage(page_module.Page):
 
   def __init__(self, url, page_set):
     super(ToughSchedulingCasesPage, self).__init__(
-        url=url, page_set=page_set, credentials_path = 'data/credentials.json')
+        url=url, page_set=page_set, credentials_path='data/credentials.json')
     self.user_agent_type = 'mobile'
     self.archive_data_file = 'data/tough_scheduling_cases.json'
 
@@ -19,6 +19,12 @@ class ToughSchedulingCasesPage(page_module.Page):
     action_runner.ScrollPage()
     interaction.End()
 
+  def RunTaskExecutionTime(self, action_runner):
+    interaction = action_runner.BeginGestureInteraction(
+        'ScrollAction', is_smooth=True)
+    action_runner.ScrollPage()
+    interaction.End()
+
 
 class Page1(ToughSchedulingCasesPage):