Added GPU performance metrics.

tools/perf/metrics/gpu_timeline.py

+# Copyright 2015 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 collections
+import math
+import sys
+
+from telemetry.timeline import model as model_module
+from telemetry.value import scalar
+from telemetry.value import list_of_scalar_values
+from telemetry.web_perf.metrics import timeline_based_metric
+
+TOPLEVEL_GL_CATEGORY = 'gpu_toplevel'
+TOPLEVEL_SERVICE_CATEGORY = 'disabled-by-default-gpu.service'
+TOPLEVEL_DEVICE_CATEGORY = 'disabled-by-default-gpu.device'
+
+SERVICE_FRAME_END_MARKER = (TOPLEVEL_SERVICE_CATEGORY, 'SwapBuffer')
+DEVICE_FRAME_END_MARKER = (TOPLEVEL_DEVICE_CATEGORY, 'SwapBuffer')
+
+TRACKED_NAMES = { 'RenderCompositor': 'render_compositor',

[epenner, 2015/01/27 22:06:38]

Optional nit: Could this be something like TRACKED_GL_CONTEXT_NAMES? I was
briefly unclear whether we were looking at client-side traces.

[David Yen, 2015/01/27 22:31:27]

Done.

+                  'BrowserCompositor': 'browser_compositor',
+                  'Compositor': 'browser_compositor' }
+
+
+def CalculateFrameTimes(events_per_frame):
+  """Given a list of events per frame, returns a list of frame times."""
+  times_per_frame = []
+  for event_list in events_per_frame:
+    # Prefer to use thread_duration but use duration as fallback.
+    event_times = [(event.thread_duration or event.duration)

[epenner, 2015/01/27 22:06:38]

I'd be tempted to just not report anything if thread_duration isn't supported.
If you want to keep clock times, it would be good to:
- Report a different name when using clock times
- Check if thread_duration is 'None' instead (it's possible for thread_duration
to be zero and duration to be non-zero, since the clock granularity could be
different).
- Might be nice to add a sanity check that 'if any thread_duration is None, all
thread_durations are None'.

[David Yen, 2015/01/27 22:31:27]

This was to simplify the calculation of both synchronous and asynchronous
slices. Asynchronous slices do not have the thread_duration, only the duration.
This is why we need to fall back to the duration if the thread_duration does not
exist.

Currently the CPU side traces use synchronous markers and the GPU side traces
use asynchronous markers.

[epenner, 2015/01/27 22:59:02]

Minimally, any detection of thread_duration not existing should use
event.thread_duration == None as opposed to the current code which detects
either None or '0' I believe (and '0' might have non-zero clock duration).

Switching between thread_duration/duration changes the meaning of the result, so
IMO it would be better to have a different name, or for the result to not exist
when there is no thread_durations, or to just use clock duration all the time.
In terms of the current benchmark, isn't everything async slices delivered via
the command stream? When would CPU time actually be available?

Last, it seems like we could actually report thread_duration if the async slice
begins/ends on the same thread... No need for that now, but would that make this
consistently work with thread_durations?

[David Yen, 2015/01/27 23:20:00]

I've split this up into 2 functions now, so CPU events only use
event.thread_duration and GPU events only use event.duration. Does that sound
reasonable?

+                   for event in event_list]
+    times_per_frame.append(sum(event_times))
+  return times_per_frame
+
+
+def TimelineName(name, source_type, value_type):
+  """Constructs the standard name given in the timeline.
+
+  Args:
+    name: The name of the timeline, for example "total", or "render_compositor".
+    source_type: One of "cpu", "gpu" or None. None is only used for total times.
+    value_type: the type of value. For example "mean", "stddev"...etc.
+  """
+  if source_type:
+    return '%s_%s_%s_time' % (name, value_type, source_type)
+  else:
+    return '%s_%s_time' % (name, value_type)
+
+
+class GPUTimelineMetric(timeline_based_metric.TimelineBasedMetric):
+  """Computes GPU based metrics."""
+
+  def __init__(self):
+    super(GPUTimelineMetric, self).__init__()
+
+  def AddResults(self, model, _, interaction_records, results):
+    self.VerifyNonOverlappedRecords(interaction_records)
+    service_times = self._CalculateGPUTimelineData(model)
+    for value_item, durations in service_times.iteritems():
+      count = len(durations)
+      avg = 0.0
+      stddev = 0.0
+      maximum = 0.0
+      if count:
+        avg = sum(durations) / count
+        stddev = math.sqrt(sum((d - avg) ** 2 for d in durations) / count)
+        maximum = max(durations)
+
+      name, src = value_item
+
+      if src:
+        frame_times_name = '%s_%s_frame_times' % (name, src)
+      else:
+        frame_times_name = '%s_frame_times' % (name)
+
+      if durations:

[epenner, 2015/01/27 22:06:38]

Nit: Looks like we should either add or not add all results here. Can you make
it an empty list and still add it?

[David Yen, 2015/01/27 22:31:27]

list_of_scalar_values requires a non-empty list, I added this after I saw it was
throwing an exception.

+        results.AddValue(list_of_scalar_values.ListOfScalarValues(
+            results.current_page, frame_times_name, 'ms', durations))
+
+      results.AddValue(scalar.ScalarValue(results.current_page,
+                                          TimelineName(name, src, 'max'),
+                                          'ms', maximum))
+      results.AddValue(scalar.ScalarValue(results.current_page,
+                                          TimelineName(name, src, 'mean'),
+                                          'ms', avg))
+      results.AddValue(scalar.ScalarValue(results.current_page,
+                                          TimelineName(name, src, 'stddev'),
+                                          'ms', stddev))
+
+  def _CalculateGPUTimelineData(self, model):
+    """Uses the model and calculates the times for various values for each
+       frame. The return value will be a dictionary of the following format:
+         {
+           EVENT_NAME1: [FRAME0_TIME, FRAME1_TIME...etc.],
+           EVENT_NAME2: [FRAME0_TIME, FRAME1_TIME...etc.],
+         }
+
+       Event Names:
+         mean_frame - Mean time each frame is calculated to be.

[epenner, 2015/01/27 22:06:38]

Nit: I think this name might have changed in the code below.

[David Yen, 2015/01/27 22:31:28]

Updated description to match the new return values.

+         mean_gpu_service-cpu: Mean time the GPU service took per frame.
+         mean_gpu_device-gpu: Mean time the GPU device took per frame.
+         TRACKED_NAMES_service-cpu: Using the TRACKED_NAMES dictionary, we
+                                    include service traces per frame for the
+                                    tracked name.
+         TRACKED_NAMES_device-gpu: Using the TRACKED_NAMES dictionary, we
+                                   include device traces per frame for the
+                                   tracked name.
+    """
+    all_service_events = []
+    current_service_frame_end = sys.maxint
+    current_service_events = []
+
+    all_device_events = []
+    current_device_frame_end = sys.maxint
+    current_device_events = []
+
+    tracked_events = {}
+    tracked_events.update(dict([((value, 'cpu'), [])
+                                for value in TRACKED_NAMES.itervalues()]))
+    tracked_events.update(dict([((value, 'gpu'), [])
+                                for value in TRACKED_NAMES.itervalues()]))
+
+    current_tracked_service_events = collections.defaultdict(list)

[epenner, 2015/01/27 22:06:38]

Optional Nit: current_frame_service_events, or
current_frame_tracked_service_events or just a comment that these track the
traces within the current frame.

[David Yen, 2015/01/27 22:31:28]

Done.

+    current_tracked_device_events = collections.defaultdict(list)
+
+    event_iter = model.IterAllEvents(
+        event_type_predicate=model_module.IsSliceOrAsyncSlice)
+    for event in event_iter:
+      # Look for frame end markers
+      if (event.category, event.name) == SERVICE_FRAME_END_MARKER:
+        current_service_frame_end = event.end
+      elif (event.category, event.name) == DEVICE_FRAME_END_MARKER:
+        current_device_frame_end = event.end
+
+      # Track all other toplevel gl category markers
+      elif event.args.get('gl_category', None) == TOPLEVEL_GL_CATEGORY:
+        base_name = event.name
+        dash_index = base_name.rfind('-')
+        if dash_index != -1:
+          base_name = base_name[:dash_index]
+        tracked_name = TRACKED_NAMES.get(base_name, None)
+

[epenner, 2015/01/27 22:06:38]

Optional nit: The alternating if blocks are almost the same. Could it be less
code, like a for loop over two with variables in arrays, or a function? But if
you think it would make this less clear you can forget this.

[David Yen, 2015/01/27 22:31:27]

Yeah originally I had it trying to share more code but it got confusing pretty
quickly.

+        if event.category == TOPLEVEL_SERVICE_CATEGORY:
+          # Check if frame has ended.
+          if event.start >= current_service_frame_end:
+            if current_service_events:
+              all_service_events.append(current_service_events)
+              for value in TRACKED_NAMES.itervalues():
+                tracked_events[(value, 'cpu')].append(
+                    current_tracked_service_events[value])
+            current_service_events = []
+            current_service_frame_end = sys.maxint
+            current_tracked_service_events.clear()
+
+          current_service_events.append(event)
+          if tracked_name:
+            current_tracked_service_events[tracked_name].append(event)
+
+        elif event.category == TOPLEVEL_DEVICE_CATEGORY:
+          # Check if frame has ended.
+          if event.start >= current_device_frame_end:
+            if current_device_events:
+              all_device_events.append(current_device_events)
+              for value in TRACKED_NAMES.itervalues():
+                tracked_events[(value, 'gpu')].append(
+                    current_tracked_device_events[value])
+            current_device_events = []
+            current_device_frame_end = sys.maxint
+            current_tracked_device_events.clear()
+
+          current_device_events.append(event)
+          if tracked_name:
+            current_tracked_device_events[tracked_name].append(event)
+
+    # Append Data for Last Frame.
+    if current_service_events:
+      all_service_events.append(current_service_events)
+      for value in TRACKED_NAMES.itervalues():
+        tracked_events[(value, 'cpu')].append(
+            current_tracked_service_events[value])
+    if current_device_events:
+      all_device_events.append(current_device_events)
+      for value in TRACKED_NAMES.itervalues():
+        tracked_events[(value, 'gpu')].append(
+            current_tracked_device_events[value])
+
+    # Calculate Mean Frame Time for the CPU side.
+    frame_times = []
+    if all_service_events:
+      prev_frame_end = all_service_events[0][0].start
+      for event_list in all_service_events:
+        last_service_event_in_frame = event_list[-1]
+        frame_times.append(last_service_event_in_frame.end - prev_frame_end)
+        prev_frame_end = last_service_event_in_frame.end
+
+    # Create the timeline data dictionary for service side traces.
+    total_frame_value = ('swap', None)
+    cpu_frame_value = ('total', 'cpu')
+    gpu_frame_value = ('total', 'gpu')
+    timeline_data = {}
+    timeline_data[total_frame_value] = frame_times
+    timeline_data[cpu_frame_value] = CalculateFrameTimes(all_service_events)
+    for value in TRACKED_NAMES.itervalues():
+      cpu_value = (value, 'cpu')
+      timeline_data[cpu_value] = CalculateFrameTimes(tracked_events[cpu_value])
+
+    # Add in GPU side traces if it was supported (IE. device traces exist).
+    if all_device_events:
+      timeline_data[gpu_frame_value] = CalculateFrameTimes(all_device_events)
+      for value in TRACKED_NAMES.itervalues():
+        gpu_value = (value, 'gpu')
+        tracked_gpu_event = tracked_events[gpu_value]
+        timeline_data[gpu_value] = CalculateFrameTimes(tracked_gpu_event)
+
+    return timeline_data