tools/perf/measurements/task_execution_time.py

   1 # Copyright 2014 The Chromium Authors. All rights reserved.
   2 # Use of this source code is governed by a BSD-style license that can be
   3 # found in the LICENSE file.
   4
   5 from telemetry.page import page_test
   6 from telemetry.timeline.model import TimelineModel
   7 from telemetry.timeline import tracing_category_filter
   8 from telemetry.timeline import tracing_options
   9 from telemetry.util import statistics
  10 from telemetry.value import scalar
  11
  12
  13 class TaskExecutionTime(page_test.PageTest):
  14
  15   IDLE_SECTION_TRIGGER = 'SingleThreadIdleTaskRunner::RunTask'
  16   IDLE_SECTION = 'IDLE'
  17   NORMAL_SECTION = 'NORMAL'
  18
  19   _TIME_OUT_IN_SECONDS = 60
  20   _NUMBER_OF_RESULTS_TO_DISPLAY = 10
  21   _BROWSER_THREADS = ['Chrome_ChildIOThread',
  22                       'Chrome_IOThread']
  23   _RENDERER_THREADS = ['Chrome_ChildIOThread',
  24                        'Chrome_IOThread',
  25                        'CrRendererMain']
  26   _CATEGORIES = ['benchmark',
  27                  'blink',
  28                  'blink.console',
  29                  'blink_gc',
  30                  'cc',
  31                  'gpu',
  32                  'ipc',
  33                  'renderer.scheduler',
  34                  'toplevel',
  35                  'v8',
  36                  'webkit.console']
  37
  38   def __init__(self):
  39     super(TaskExecutionTime, self).__init__()
  40     self._renderer_process = None
  41     self._browser_process = None
  42     self._results = None
  43
  44   def WillNavigateToPage(self, page, tab):
  45     category_filter = tracing_category_filter.TracingCategoryFilter()
  46
  47     for category in self._CATEGORIES:
  48       category_filter.AddIncludedCategory(category)
  49
  50     options = tracing_options.TracingOptions()
  51     options.enable_chrome_trace = True
  52
  53     tab.browser.platform.tracing_controller.Start(
  54         options, category_filter, self._TIME_OUT_IN_SECONDS)
  55
  56   def ValidateAndMeasurePage(self, page, tab, results):
  57     trace_data = tab.browser.platform.tracing_controller.Stop()
  58     timeline_model = TimelineModel(trace_data)
  59
  60     self._renderer_process = timeline_model.GetRendererProcessFromTabId(tab.id)
  61     self._browser_process = timeline_model.browser_process
  62     self._AddResults(results)
  63
  64   def _AddResults(self, results):
  65     self._results = results
  66
  67     for thread in self._BROWSER_THREADS:
  68       self._AddTasksFromThreadToResults(self._browser_process, thread)
  69
  70     for thread in self._RENDERER_THREADS:
  71       self._AddTasksFromThreadToResults(self._renderer_process, thread)
  72
  73   def _AddTasksFromThreadToResults(self, process, thread_name):
  74     if process is None:
  75       return
  76
  77     sections = TaskExecutionTime._GetSectionsForThread(process, thread_name)
  78
  79     self._ReportSectionPercentages(sections.values(),
  80                                    '%s:%s' % (process.name, thread_name))
  81
  82     # Create list with top |_NUMBER_OF_RESULTS_TO_DISPLAY| for each section.
  83     for section in sections.itervalues():
  84       if section.name == TaskExecutionTime.IDLE_SECTION:
  85         # Skip sections we don't report.
  86         continue
  87       self._AddSlowestTasksToResults(section.tasks.values())
  88
  89   def _AddSlowestTasksToResults(self, tasks):
  90     sorted_tasks = sorted(
  91         tasks,
  92         key=lambda slice: slice.median_self_duration,
  93         reverse=True)
  94
  95     for task in sorted_tasks[:self.GetExpectedResultCount()]:
  96       self._results.AddValue(scalar.ScalarValue(
  97           self._results.current_page,
  98           task.name,
  99           'ms',
 100           task.median_self_duration,
 101           description='Slowest tasks'))
 102
 103   def _ReportSectionPercentages(self, section_values, metric_prefix):
 104     all_sectionstotal_duration = sum(
 105         section.total_duration for section in section_values)
 106
 107     if not all_sectionstotal_duration:
 108       # Nothing was recorded, so early out.
 109       return
 110
 111     for section in section_values:
 112       section_name = section.name or TaskExecutionTime.NORMAL_SECTION
 113       section_percentage_of_total = (
 114           (section.total_duration * 100.0) / all_sectionstotal_duration)
 115       self._results.AddValue(scalar.ScalarValue(
 116           self._results.current_page,
 117           '%s:Section_%s' % (metric_prefix, section_name),
 118           '%',
 119           section_percentage_of_total,
 120           description='Idle task percentage'))
 121
 122   @staticmethod
 123   def _GetSectionsForThread(process, target_thread):
 124     sections = {}
 125
 126     for thread in process.threads.itervalues():
 127       if thread.name != target_thread:
 128         continue
 129       for task_slice in thread.IterAllSlices():
 130         _ProcessTasksForThread(
 131             sections,
 132             '%s:%s' % (process.name, thread.name),
 133             task_slice)
 134
 135     return sections
 136
 137   @staticmethod
 138   def GetExpectedResultCount():
 139     return TaskExecutionTime._NUMBER_OF_RESULTS_TO_DISPLAY
 140
 141
 142 def _ProcessTasksForThread(
 143     sections,
 144     thread_name,
 145     task_slice,
 146     section_name=None):
 147   if task_slice.self_thread_time is None:
 148     # Early out if this slice is a TRACE_EVENT_INSTANT, as it has no duration.
 149     return
 150
 151   # Note: By setting a different section below we split off this task into
 152   # a different sorting bucket. Too add extra granularity (e.g. tasks executed
 153   # during page loading) add logic to set a different section name here. The
 154   # section name is set before the slice's data is recorded so the triggering
 155   # event will be included in its own section (i.e. the idle trigger will be
 156   # recorded as an idle event).
 157
 158   if task_slice.name == TaskExecutionTime.IDLE_SECTION_TRIGGER:
 159     section_name = TaskExecutionTime.IDLE_SECTION
 160
 161   # Add the thread name and section (e.g. 'Idle') to the test name
 162   # so it is human-readable.
 163   reported_name = thread_name + ':'
 164   if section_name:
 165     reported_name += section_name + ':'
 166
 167   if 'src_func' in task_slice.args:
 168     # Data contains the name of the timed function, use it as the name.
 169     reported_name += task_slice.args['src_func']
 170   elif 'line' in task_slice.args:
 171     # Data contains IPC class and line numbers, use these as the name.
 172     reported_name += 'IPC_Class_' + str(task_slice.args['class'])
 173     reported_name += ':Line_' + str(task_slice.args['line'])
 174   else:
 175     # Fallback to use the name of the task slice.
 176     reported_name += task_slice.name.lower()
 177
 178   # Replace any '.'s with '_'s as V8 uses them and it confuses the dashboard.
 179   reported_name = reported_name.replace('.', '_')
 180
 181   # If this task is in a new section create a section object and add it to the
 182   # section dictionary.
 183   if section_name not in sections:
 184     sections[section_name] = Section(section_name)
 185
 186   sections[section_name].AddTask(reported_name, task_slice.self_thread_time)
 187
 188   # Process sub slices recursively, passing the current section down.
 189   for sub_slice in task_slice.sub_slices:
 190     _ProcessTasksForThread(
 191         sections,
 192         thread_name,
 193         sub_slice,
 194         section_name)
 195
 196
 197 class NameAndDurations(object):
 198
 199   def __init__(self, name, self_duration):
 200     self.name = name
 201     self.self_durations = [self_duration]
 202
 203   def Update(self, self_duration):
 204     self.self_durations.append(self_duration)
 205
 206   @property
 207   def median_self_duration(self):
 208     return statistics.Median(self.self_durations)
 209
 210
 211 class Section(object):
 212
 213   def __init__(self, name):
 214     # A section holds a dictionary, keyed on task name, of all the tasks that
 215     # exist within it and the total duration of those tasks.
 216     self.name = name
 217     self.tasks = {}
 218     self.total_duration = 0
 219
 220   def AddTask(self, name, duration):
 221     if name in self.tasks:
 222       # section_tasks already contains an entry for this (e.g. from an earlier
 223       # slice), add the new duration so we can calculate a median value later.
 224       self.tasks[name].Update(duration)
 225     else:
 226       # This is a new task so create a new entry for it.
 227       self.tasks[name] = NameAndDurations(name, duration)
 228     # Accumulate total duration for all tasks in this section.
 229     self.total_duration += duration