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.core.platform import tracing_category_filter
   6 from telemetry.core.platform import tracing_options
   7 from telemetry.page import page_test
   8 from telemetry.timeline.model import TimelineModel
   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 DidRunActions(self, page, tab):
  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
  63   def ValidateAndMeasurePage(self, page, tab, results):
  64     self._results = results
  65
  66     for thread in self._BROWSER_THREADS:
  67       self._AddTasksFromThreadToResults(self._browser_process, thread)
  68
  69     for thread in self._RENDERER_THREADS:
  70       self._AddTasksFromThreadToResults(self._renderer_process, thread)
  71
  72   def _AddTasksFromThreadToResults(self, process, thread_name):
  73     if process is None:
  74       return
  75
  76     sections = TaskExecutionTime._GetSectionsForThread(process, thread_name)
  77
  78     self._ReportSectionPercentages(sections.values(),
  79                                    '%s:%s' % (process.name, thread_name))
  80
  81     # Create list with top |_NUMBER_OF_RESULTS_TO_DISPLAY| for each section.
  82     for section in sections.itervalues():
  83       if section.name == TaskExecutionTime.IDLE_SECTION:
  84         # Skip sections we don't report.
  85         continue
  86       self._AddSlowestTasksToResults(section.tasks.values())
  87
  88   def _AddSlowestTasksToResults(self, tasks):
  89     sorted_tasks = sorted(
  90         tasks,
  91         key=lambda slice: slice.median_self_duration,
  92         reverse=True)
  93
  94     for task in sorted_tasks[:self.GetExpectedResultCount()]:
  95       self._results.AddValue(scalar.ScalarValue(
  96           self._results.current_page,
  97           task.name,
  98           'ms',
  99           task.median_self_duration,
 100           description='Slowest tasks'))
 101
 102   def _ReportSectionPercentages(self, section_values, metric_prefix):
 103     all_sectionstotal_duration = sum(
 104         section.total_duration for section in section_values)
 105
 106     if not all_sectionstotal_duration:
 107       # Nothing was recorded, so early out.
 108       return
 109
 110     for section in section_values:
 111       section_name = section.name or TaskExecutionTime.NORMAL_SECTION
 112       section_percentage_of_total = (
 113           (section.total_duration * 100.0) / all_sectionstotal_duration)
 114       self._results.AddValue(scalar.ScalarValue(
 115           self._results.current_page,
 116           '%s:Section_%s' % (metric_prefix, section_name),
 117           '%',
 118           section_percentage_of_total,
 119           description='Idle task percentage'))
 120
 121   @staticmethod
 122   def _GetSectionsForThread(process, target_thread):
 123     sections = {}
 124
 125     for thread in process.threads.itervalues():
 126       if thread.name != target_thread:
 127         continue
 128       for task_slice in thread.IterAllSlices():
 129         _ProcessTasksForThread(
 130             sections,
 131             '%s:%s' % (process.name, thread.name),
 132             task_slice)
 133
 134     return sections
 135
 136   @staticmethod
 137   def GetExpectedResultCount():
 138     return TaskExecutionTime._NUMBER_OF_RESULTS_TO_DISPLAY
 139
 140
 141 def _ProcessTasksForThread(
 142     sections,
 143     thread_name,
 144     task_slice,
 145     section_name=None):
 146   if task_slice.self_thread_time is None:
 147     # Early out if this slice is a TRACE_EVENT_INSTANT, as it has no duration.
 148     return
 149
 150   # Note: By setting a different section below we split off this task into
 151   # a different sorting bucket. Too add extra granularity (e.g. tasks executed
 152   # during page loading) add logic to set a different section name here. The
 153   # section name is set before the slice's data is recorded so the triggering
 154   # event will be included in its own section (i.e. the idle trigger will be
 155   # recorded as an idle event).
 156
 157   if task_slice.name == TaskExecutionTime.IDLE_SECTION_TRIGGER:
 158     section_name = TaskExecutionTime.IDLE_SECTION
 159
 160   # Add the thread name and section (e.g. 'Idle') to the test name
 161   # so it is human-readable.
 162   reported_name = thread_name + ':'
 163   if section_name:
 164     reported_name += section_name + ':'
 165
 166   if 'src_func' in task_slice.args:
 167     # Data contains the name of the timed function, use it as the name.
 168     reported_name += task_slice.args['src_func']
 169   elif 'line' in task_slice.args:
 170     # Data contains IPC class and line numbers, use these as the name.
 171     reported_name += 'IPC_Class_' + str(task_slice.args['class'])
 172     reported_name += ':Line_' + str(task_slice.args['line'])
 173   else:
 174     # Fallback to use the name of the task slice.
 175     reported_name += task_slice.name.lower()
 176
 177   # Replace any '.'s with '_'s as V8 uses them and it confuses the dashboard.
 178   reported_name = reported_name.replace('.', '_')
 179
 180   # If this task is in a new section create a section object and add it to the
 181   # section dictionary.
 182   if section_name not in sections:
 183     sections[section_name] = Section(section_name)
 184
 185   sections[section_name].AddTask(reported_name, task_slice.self_thread_time)
 186
 187   # Process sub slices recursively, passing the current section down.
 188   for sub_slice in task_slice.sub_slices:
 189     _ProcessTasksForThread(
 190         sections,
 191         thread_name,
 192         sub_slice,
 193         section_name)
 194
 195
 196 class NameAndDurations(object):
 197
 198   def __init__(self, name, self_duration):
 199     self.name = name
 200     self.self_durations = [self_duration]
 201
 202   def Update(self, self_duration):
 203     self.self_durations.append(self_duration)
 204
 205   @property
 206   def median_self_duration(self):
 207     return statistics.Median(self.self_durations)
 208
 209
 210 class Section(object):
 211
 212   def __init__(self, name):
 213     # A section holds a dictionary, keyed on task name, of all the tasks that
 214     # exist within it and the total duration of those tasks.
 215     self.name = name
 216     self.tasks = {}
 217     self.total_duration = 0
 218
 219   def AddTask(self, name, duration):
 220     if name in self.tasks:
 221       # section_tasks already contains an entry for this (e.g. from an earlier
 222       # slice), add the new duration so we can calculate a median value later.
 223       self.tasks[name].Update(duration)
 224     else:
 225       # This is a new task so create a new entry for it.
 226       self.tasks[name] = NameAndDurations(name, duration)
 227     # Accumulate total duration for all tasks in this section.
 228     self.total_duration += duration