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
+
+from telemetry.timeline import async_slice as async_slice_module
+from telemetry.timeline import slice as slice_module
+from telemetry.value import scalar
+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'
+
+FRAME_END_MARKER = ('gpu', 'GLES2DecoderImpl::DoSwapBuffers')

[epenner, 2015/01/16 01:17:59]

Two things on this trace:

First, is there no GPU-side trace for this? That would be the best, as there is
some latency between this and when this actually occurs on the GPU's timeline..
But over many frames it's fine, so not a big deal.

Second, I believe this is never called on some platforms. In thread-times, I
tried this, as well as adding "RealSwapBuffers" traces, but even that didn't
work on all platforms (now I'm having trouble remembering which, I think it was
Mac), so I switched to compositor swaps. You might want to do the same, or dig
into the remaining platforms to find an equivalent trace.

[vmiura, 2015/01/16 01:41:15]

We should be able to add a "DoSwapBuffers" gpu trace which drops into
gpu.service & gpu.device categories.

[David Yen, 2015/01/16 22:58:04]

Done here: https://codereview.chromium.org/799753009/

Will switch to use that instead once the CL lands.

[David Yen, 2015/01/20 19:37:26]

Done.

+
+TRACKED_NAMES = { 'RenderCompositor': 'render_compositor',
+                  'Compositor': 'compositor' }
+
+GPU_SERVICE_DEVICE_VARIANCE = 5

[epenner, 2015/01/16 01:17:59]

See below, I'm not sure this threshold is really needed. Perhaps it might reduce
some noise, but I don't believe we should fail if we exceed this. It seems to me
it will just cause the test to flake occasionally.

[vmiura, 2015/01/16 01:41:14]

Perhaps if we have the "swap" trace on the GPU we don't need to match CPU & GPU
tracks, and remove this matching.

[David Yen, 2015/01/16 22:58:04]

Yes, once the Swap trace is plumbed through we won't need this anymore.

[David Yen, 2015/01/20 19:37:26]

Done.

+
+
+class GPUTimelineMetric(timeline_based_metric.TimelineBasedMetric):
+  """Computes GPU based metrics."""
+
+  def __init__(self):
+    super(GPUTimelineMetric, self).__init__()
+
+  def AddResults(self, model, _, interaction_records, results):
+    service_times = self._CalculateGPUTimelineData(model)
+    for name, 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)
+
+      results.AddValue(scalar.ScalarValue(results.current_page,
+                                          name + '_max', 'ms', maximum))
+      results.AddValue(scalar.ScalarValue(results.current_page,
+                                          name + '_avg', 'ms', avg))
+      results.AddValue(scalar.ScalarValue(results.current_page,
+                                          name + '_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:
+         total_frame - Total time each frame is calculated to be.
+         total_gpu_service: Total time the GPU service took per frame.
+         total_gpu_device: Total time the GPU device took per frame.
+         TRACKED_NAMES_service: Using the TRACKED_NAMES dictionary, we include

[epenner, 2015/01/16 01:17:59]

It took me a minute to parse what these mean. Does total_frame mean the total
clock time for a frame? If so, I would call this 'mean_frame_time' for
consistency with other metrics.

Does 'service' mean the CPU time spent in chrome's GPU service? Or perhaps cpu
time in the driver? And does 'device' mean the real GPU time? If so, I would
find 'dispatch' or 'cpu-dispatch' or 'service-cpu' more clear.

Also, have you considered thread_duration instead of duration for the cpu-time
in the service? A clock duration will often lack meaning for anything but
mean_frame_time/fps, as several unrelated things contribute to it (descheduling
and blocking on the GPU).

[vmiura, 2015/01/16 01:41:14]

Currently the 'gpu.service' traces are using the the "asynchronous traces"
(TRACE_EVENT_COPY_ASYNC_BEGIN/TRACE_EVENT_COPY_ASYNC_END) which don't have the
'thread_duration' numbers.

We can look into making these normal traces.  It may violate trace stacking, but
I think Tracing can cope with that.

[David Yen, 2015/01/16 22:58:04]

I've changed the Traces to use normal traces instead of async traces here:
https://codereview.chromium.org/855653003/

After that lands I will use convert the values to use thread_duration.

I've also changed the names a bit to make it more clear.

[David Yen, 2015/01/20 19:37:26]

Done.

+                                service traces per frame for the tracked name.
+         TRACKED_NAMES_device: Using the TRACKED_NAMES dictionary, we include
+                               device traces per frame for the tracked name.
+    """
+    service_events = []
+    device_events = []
+    buffer_swap_events = []
+
+    for event in model.IterAllEvents():
+      if isinstance(event, slice_module.Slice):
+        if (event.category, event.name) == FRAME_END_MARKER:
+          buffer_swap_events.append(event)
+      elif isinstance(event, async_slice_module.AsyncSlice):
+        if event.thread_start:

[epenner, 2015/01/16 01:17:59]

This is the only use of thread_start, are you sure this is what you want?

[David Yen, 2015/01/16 22:58:04]

I was going to look into this later, but the AsyncSlices are inserted twice for
some reason. The only different was the thread_start is set for one of them, and
the other one is None. So this was only to filter out one of the extra ones. Now
that we are not using Async traces anymore this is irrelevant, but we should
still figure out why there are multiple async traces.

+          if event.args.get('gl_category', None) == TOPLEVEL_GL_CATEGORY:
+            if event.category == TOPLEVEL_SERVICE_CATEGORY:
+              service_events.append(event)
+            elif event.category == TOPLEVEL_DEVICE_CATEGORY:
+              device_events.append(event)
+
+    # Some platforms do not support GPU device tracing, fill in empty values.
+    no_device_traces = False
+    if service_events and not device_events:
+      device_events = [async_slice_module.AsyncSlice(TOPLEVEL_DEVICE_CATEGORY,
+                                                     event.name, 0)
+                       for event in service_events]
+      no_device_traces = True
+
+    # Allow some variance in the number of service and device events, depending
+    # on when the tracing stopped the device trace could not have come back yet.

[epenner, 2015/01/16 01:17:59]

Another reason for this could be that the device events are likely delayed by
1-2 frames, so if these events were previously clipped against a time-range, we
might lose 1-2 GPU frames at the right side. It's difficult to guarantee that
the traces will correlate exactly, so I'm inclined to just accept the noise.

[David Yen, 2015/01/16 22:58:04]

This is no longer relevant and will be removed once the new buffer swap traces
lands.

[David Yen, 2015/01/20 19:37:26]

Done.

+    if len(service_events) > len(device_events):
+      event_difference = len(service_events) - len(device_events)
+      if event_difference <= GPU_SERVICE_DEVICE_VARIANCE:
+        service_events = service_events[:-event_difference]
+
+    # Group together GPU events and validate that the markers match.
+    assert len(service_events) == len(device_events), (

[epenner, 2015/01/16 01:17:59]

It seems like we should either have a hard '==' in the assertion (without the
event_difference threshold), or just accept this as a small source of noise, and
add a comment somewhere about this limitation. I'm worried that this would flake
depending on the number of gpu events per frame.

[David Yen, 2015/01/16 22:58:04]

Before we were using the BufferSwap trace that only happens on the CPU so it was
important that the CPU/GPU traces matched up perfectly (if anything for the zip
call below). Once the SwapBuffer traces gets plumbed through to the device
traces most of this will be unnecessary though.

[David Yen, 2015/01/20 19:37:26]

Done.

+        'Mismatching number of GPU Service (%s) and Device events (%s).' %
+        (len(service_events), len(device_events)))
+
+    service_events_dict = collections.defaultdict(list)
+    for event in service_events:
+      service_events_dict[event.name].append(event)
+
+    device_events_dict = collections.defaultdict(list)
+    for event in device_events:
+      device_events_dict[event.name].append(event)
+
+    assert set(service_events_dict.keys()) == set(device_events_dict.keys()), (
+        'Mismatching event names between GPU Service and Device events.')
+
+    gpu_events = []
+    for event_name in service_events_dict:
+      service_events_list = service_events_dict[event_name]
+      device_events_list = device_events_dict[event_name]
+      assert len(service_events_list) == len(device_events_list), (
+          'GPU service event (%s) does not correspond with all device events.' %
+          (event_name))
+
+      gpu_events.extend(zip(service_events_list, device_events_list))
+
+    gpu_events.sort(key=lambda events: events[0].start)
+
+    # Utilize Swap Buffer event to separate out gpu events by frames.
+    gpu_events_by_frame = []
+    gpu_event_iter = iter(gpu_events)
+    current_frame = []
+    for buffer_swap_event in buffer_swap_events:

[epenner, 2015/01/16 01:17:59]

Couple minor things:

Firstly, this looks to be M*N. Perhaps not a big deal, but do we even need to
group gpu events into frames? Given the GPU's latency, the frame grouping don't
be perfect. Also, it seems like given the metrics you want, you just need
something simple like this?

time_per_frame = sum(times_events) / count(frame_events)

Or am I missing something else that you want to calculate by grouping all the
traces into frames?

[David Yen, 2015/01/16 22:58:04]

Before I only had SwapBuffer traces on the CPU side so it was impossible to
figure out the start and end for a frame on the GPU side. The grouping was just
to figure out the start and end of a frame on the GPU device side. After the
SwapBuffer trace CL lands this will be simplified and I can remove this grouping
step.

[David Yen, 2015/01/20 19:37:26]

This is all removed now.

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

I also just noticed that you calculate stats on the frames (min/max/ave/std-dev)
above, which is nice, and explains why you need a bit more processing. Cool.

+      for gpu_event in gpu_event_iter:
+        service_event, device_event = gpu_event
+        if service_event.end <= buffer_swap_event.end:
+          current_frame.append(gpu_event)
+        else:
+          if current_frame:
+            gpu_events_by_frame.append(current_frame)
+          current_frame = [gpu_event]
+          break
+
+    current_frame.extend([gpu_event for gpu_event in gpu_event_iter])
+    if current_frame:
+      gpu_events_by_frame.append(current_frame)
+
+    # Calculate service times that we care about.
+    total_frame_times = []
+    gpu_service_times = []
+    gpu_device_times = []
+    tracked_times = {}
+
+    tracked_times.update(dict([(value + "_service", [])
+                               for value in TRACKED_NAMES.itervalues()]))
+    tracked_times.update(dict([(value + "_device", [])
+                               for value in TRACKED_NAMES.itervalues()]))
+
+    if gpu_events:
+      first_service_event, _ = gpu_events[0]
+      prev_frame_end = first_service_event.start
+    else:
+      prev_frame_end = 0
+
+    for frame_gpu_events in gpu_events_by_frame:
+      last_service_in_frame, _ = frame_gpu_events[-1]
+
+      total_frame_time = last_service_in_frame.end - prev_frame_end
+      prev_frame_end = last_service_in_frame.end
+
+      total_gpu_service_time = 0
+      total_gpu_device_time = 0
+      tracked_markers = collections.defaultdict(lambda : 0)
+      for service_event, device_event in frame_gpu_events:
+        service_time = service_event.end - service_event.start
+        device_time = device_event.end - device_event.start
+        total_gpu_service_time += service_time
+        total_gpu_device_time += device_time
+
+        base_name = service_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)
+        if tracked_name:
+          tracked_markers[tracked_name + '_service'] += service_time
+          tracked_markers[tracked_name + '_device'] += device_time
+
+      total_frame_times.append(total_frame_time)
+      gpu_service_times.append(total_gpu_service_time)
+      gpu_device_times.append(total_gpu_device_time)
+
+      for tracked_name in TRACKED_NAMES.values():
+        service_name = tracked_name + '_service'
+        device_name = tracked_name + '_device'
+        tracked_times[service_name].append(tracked_markers[service_name])
+        tracked_times[device_name].append(tracked_markers[device_name])
+
+    # Create the service times dictionary.
+    service_times = { 'total_frame': total_frame_times,
+                      'total_gpu_service': gpu_service_times,
+                      'total_gpu_device': gpu_device_times }
+    service_times.update(tracked_times)
+
+    # Remove device metrics if no device traces were found.
+    if no_device_traces:
+      for device_name in [name
+                          for name in service_times.iterkeys()
+                          if name.endswith('_device')]:
+        service_times.pop(device_name)
+
+    return service_times