Task Execution Duration metrics added as a new benchmark

tools/perf/measurements/task_execution_time.py

+# Copyright 2013 The Chromium Authors. All rights reserved.

[petrcermak, 2014/10/08 14:01:48]

Again should be "2014".

[Sami, 2014/10/08 14:51:53]

Ditto about the copyright year.

+# 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.value import scalar
+from telemetry.value import skip
+
+CATEGORIES = ['webkit.console',

[Sami, 2014/10/08 14:51:52]

Assuming these constants aren't meant to be public, prepend an underscore to
their names.

[picksi1, 2014/10/08 15:58:26]

Done.

+              'blink.console',
+              'benchmark',
+              'toplevel',
+              'blink',
+              'cc',
+              'v8']
+
+TIME_OUT_IN_SECONDS = 60
+NUMBER_OF_RESULTS_TO_DISPLAY = 10
+
+class TaskExecutionTime(page_test.PageTest):
+

[Sami, 2014/10/08 14:51:53]

I don't think we generally have blank lines between function declarations and
bodies, so I'd follow the existing style here.

+  def __init__(self):
+    super(TaskExecutionTime, self).__init__('RunTaskExecutionTime')

[Sami, 2014/10/08 14:51:53]

Why not reuse RunSmoothness for this?

[picksi1, 2014/10/08 15:58:27]

I guess these are currently the same; I made a separate version so we could
diverge if needed. Maybe a case of YAGNI?

+    self._renderer_thread = None
+
+  def WillNavigateToPage(self, page, tab):
+

[alexclarke, 2014/10/08 13:28:28]

nit: I assume we don't want blank lines after a function definition?

[picksi1, 2014/10/08 13:47:54]

Yes, you're right. My eyes prefer it with spaces, but the other files don't do
this, so I'll remove them. 

+    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, TIME_OUT_IN_SECONDS)

[Sami, 2014/10/08 14:51:53]

indent +2

+
+
+  def DidRunActions(self, page, tab):

[petrcermak, 2014/10/08 14:01:48]

Is there any reason for double blank lines around this method?

[picksi1, 2014/10/08 15:01:38]

I've removed the blank lines after the function definition now. I'm putting
double blanks lines between all function definitions, which is wrong :) I'll fix
it.

+
+    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 = self.GetTasks(self._renderer_thread.parent)
+
+    sorted_tasks = sorted(tasks,
+      key = lambda slice: slice.meanSelfDuration, reverse=True)

[Sami, 2014/10/08 14:51:53]

nit: No spaces around "=" for named parameters.

[picksi1, 2014/10/08 15:58:27]

Done.

+
+    # Tell summary code to not generate results for single pages as it makes
+    # the results page difficult to read
+    results.AddValue(skip.SkipValue.SetOnlyShowingSummaries(page))

[Sami, 2014/10/08 14:51:52]

Instead of this trick, could we just report the summary values ourselves? You
can pass in None to ScalarValue to indicate that it's not associated with a
single page.

[picksi1, 2014/10/08 15:58:26]

We can't accumulate values between separate executions on different pages (e.g.
Garbage collection on Bing + TheVerge); this is done at a higher level by the
code in summary.py.

Passing None as a page makes the code fall over, did I misunderstand your
suggestion?

[Sami, 2014/10/09 10:28:13]

The documentation for Value suggests that the page could be None:
https://code.google.com/p/chromium/codesearch#chromium/src/tools/telemetry/te...

Is there some postprocessor hook we could use to make the results look like what
we want? This skip value seems a little odd to me.

[picksi1, 2014/10/09 13:02:20]

As discussed offline, I'll look into a way to change the UI of the benchmark
viewer and leave the data alone.

+
+    max_tasks = min(NUMBER_OF_RESULTS_TO_DISPLAY, len(sorted_tasks))
+    count = 0
+    while count < max_tasks:

[petrcermak, 2014/10/08 14:01:48]

"for count in xrange(max_tasks):" is more suited for this. An even more elegant
solution would be "for task in sorted_tasks[:NUMBER_OF_RESULTS_TO_DISPLAY]:".

[Sami, 2014/10/08 14:51:53]

nit: could also be written as:

  for task in sorted_tasks[:NUMBER_OF_RESULTS_TO_DISPLAY]:
     [...]

[picksi1, 2014/10/08 15:01:38]

Nice... Done!

[picksi1, 2014/10/08 15:58:27]

Petr made this observation too. Done.

+      task = sorted_tasks.pop(0)

[petrcermak, 2014/10/08 14:01:48]

Popping from the beginning of a list is quite costly. Why not "task =
sorted_tasks[count]"?

[picksi1, 2014/10/08 15:01:38]

Not needed any more with your earlier suggestion.

+      results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        task.key,
+        "ms",

[Sami, 2014/10/08 14:51:53]

' instead of "

[picksi1, 2014/10/08 15:58:26]

Done.

+        task.meanSelfDuration,
+        description="Slowest tasks"))

[Sami, 2014/10/08 14:51:53]

' instead of "

[picksi1, 2014/10/08 15:58:26]

Done.

+      count = count + 1
+
+
+  def GetTasks(self, process):

[Sami, 2014/10/08 14:51:52]

Does this need to be a member or could it be a free function?

[picksi1, 2014/10/08 15:58:26]

It could be free. Is it not best to encapsulate it (to the extent that anything
is encapsulated in Python)?

[Sami, 2014/10/09 10:28:14]

Encapsulation is fine, but it could still be a @classmethod or a @staticmethod.

+
+    task_dictionary = {}
+
+    parent = 0
+    depth = 1

[petrcermak, 2014/10/08 14:01:48]

depth is a constant (you don't change it anywhere in this method). Perhaps the
corresponding argument of ProcessTasksForSlice should be the last one and have a
default value 1.

[picksi1, 2014/10/08 15:01:38]

I made it a constant to give it a name, rather than passing a naked '1' into the
function. I'm not keen on default values as you need to seek out the function
definition to know what it' doing.

+
+    for task_slice in process.IterAllSlicesOfName('MessageLoop::RunTask'):

[petrcermak, 2014/10/08 14:01:48]

for parent, task_slice in
enumerate(process.IterAllSlicesOfName('MessageLoop::RunTask')):

+      ProcessTasksForSlice(task_dictionary, task_slice, depth, parent)
+      parent = parent + 1
+
+    # Flatten dictionary into a list
+    tasks = [sliceData for key, sliceData in task_dictionary.items()]

[petrcermak, 2014/10/08 14:01:48]

return task_dictionary.values()

[Sami, 2014/10/08 14:51:53]

nit: Same as writing task_dictionary.values()

[picksi1, 2014/10/08 15:01:38]

Done.

+
+    return tasks
+
+
+class SliceData:
+
+  def __init__(self, key, self_duration, total_duration, depth, parent):
+
+    self.key = key
+    self.count = 1
+
+    self.sum_self_duration = self_duration

[petrcermak, 2014/10/08 14:01:48]

Shouldn't there be some systematic order (e.g. sum, sum, min, min, max, max)?

[picksi1, 2014/10/08 15:01:38]

Good call. I've re-ordered them.

+    self.sum_total_duration = total_duration
+
+    self.min_self_duration = self_duration
+    self.max_self_duration = self_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 = self.count + 1

[petrcermak, 2014/10/08 14:01:48]

self.count += 1

+
+    self.sum_self_duration = (self.sum_self_duration + self_duration)

[petrcermak, 2014/10/08 14:01:48]

Again, I would suggest using the += operator instead and imposing an order.

[picksi1, 2014/10/08 15:01:38]

Done.

+    self.sum_total_duration = (self.sum_self_duration + total_duration)
+
+    self.min_self_duration = min(self.min_self_duration, self_duration)
+    self.max_self_duration = max(self.max_self_duration, self_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) )

[petrcermak, 2014/10/08 14:01:48]

Extra whitespace around the tuple.

[Sami, 2014/10/08 14:51:53]

nit: no spaces outside the parens.

+
+  @property
+  def meanSelfDuration(self):

[Sami, 2014/10/08 14:51:52]

mean_self_duration.

Do we want mean or median? The latter could be less prone to outliers.

[picksi1, 2014/10/08 15:58:26]

Done

+
+    if self.count == 0:

[Sami, 2014/10/08 14:51:53]

If count starts at 1, does this ever happen?

[picksi1, 2014/10/08 15:58:26]

Ha! You are correct... old habits die hard! This is gone with the change to
Median anyway.

+      return 0
+
+    return self.sum_self_duration / self.count
+
+
+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)

[Sami, 2014/10/08 14:51:53]

nit: add spaces around the '+'