Telemetry Test for WebRTC Rendering.

tools/telemetry/telemetry/web_perf/metrics/webrtc_rendering_timeline.py

Index: tools/telemetry/telemetry/web_perf/metrics/webrtc_rendering_timeline.py
diff --git a/tools/telemetry/telemetry/web_perf/metrics/webrtc_rendering_timeline.py b/tools/telemetry/telemetry/web_perf/metrics/webrtc_rendering_timeline.py
new file mode 100644
index 0000000000000000000000000000000000000000..8cf695569ebe432881301b65646d8491130aef15
--- /dev/null
+++ b/tools/telemetry/telemetry/web_perf/metrics/webrtc_rendering_timeline.py
@@ -0,0 +1,351 @@
+# 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 logging
+
+import numpy
+
+from telemetry.value import list_of_scalar_values
+from telemetry.value import list_of_string_values
+from telemetry.value import scalar
+from telemetry.web_perf.metrics import timeline_based_metric
+
+WEB_MEDIA_PLAYER_MS_EVENT = 'WebMediaPlayerMS::UpdateCurrentFrame'
+
+DISPLAY_HERTZ = 60.0
+VSYNC_DURATION = 1e6 / DISPLAY_HERTZ
+# When to consider a frame frozen (in VSYNC units):
+# meaning 1 initial frame + 5 repeats of that frame.
+FROZEN_THRESHOLD = 6
+# Severity factor.
+SEVERITY = 3
+
+
+class WebMediaPlayerMsRenderingStats(object):

[phoglund_chromium, 2015/09/17 11:23:58]

Move this to its own file? Also I would love a unit test for this class; there's
a lot of logic in it. See for instance here how I wrote a unit test for the
WebRTC stats parser:
https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/metrics....

[cpaulin (no longer in chrome), 2015/09/17 23:58:55]

Done.

+  """Analyzes events of WebMediaPlayerMs type."""
+
+  def __init__(self, events):
+    """Save relevant events."""
+    self.events = {}
+    self.relevant_events = []
+    for event in events:

[phoglund_chromium, 2015/09/17 11:23:58]

This algorithm is a bit hard to read. So it's

for each event that has args defined and contains the arg 'Serial'
  sort event into buckets on serial

To make the algorithm clearer you can separate the notion of what events we
throw away, and how we sort those that are left.

for event in events:
  if not event.args or not 'Serial' in event.args:
    # This event isn't interesting because xyz...
    continue
  event_serial_number = event.args['Serial']
  if event_serial_number in self.serial_to_events:
    self.serial_to_events[event_serial_number].append(event)
  else:
    self.serial_to_events[event_serial_number] = [event]

I find it a LOT easier to read what's going on in the above, and it should be
equivalent.

Note, you can even use setdefault to get rid of the second if. setdefault
returns the value pointed to by the key, except if that key isn't mapped yet by
the dict (in which case it returns the default). In that case,

  ...
  event_serial_number = event.args['Serial']
  bucket = self.serial_to_events.setdefault(event_serial_number, default=[])
  bucket.append(event)

Nice, right?

To further improve readability I'd move the whole algorithm into a helper
function so you just have

self.serial_to_events = _MapEventsToSerial(events)

For that matter, what the hell is the serial anyway? Try to explain this in the
code or comments as well.

[cpaulin (no longer in chrome), 2015/09/17 23:58:55]

Done.

+      if (event.args and 'Serial' in event.args
+          and event.args['Serial'] in self.events):
+        self.events[event.args['Serial']].append(event)
+      elif event.args and 'Serial' in event.args:
+        self.events[event.args['Serial']] = [event]
+
+  def InferCadence(self):
+    """Calculate the apparent cadence of the rendering."""
+    # Term 'cadence' loosely used here for lack of a better word.
+    cadence = []
+    frame_persistence = 0
+    old_ideal_render = 0
+    for event in self.relevant_events:
+      if (event.args and 'Ideal Render Instant' in event.args

[phoglund_chromium, 2015/09/17 11:23:58]

consider

ideal_render_instant = 'Ideal Render Instant' to avoid having to duplicate the
string so much. That should make it a bit more resistant to bugs. Note, don't
make it a global constant, a variable is fine (since it's only used by this
function).

[cpaulin (no longer in chrome), 2015/09/17 23:58:55]

Acknowledged.

+          and event.args['Ideal Render Instant'] == old_ideal_render):
+        frame_persistence += 1
+      elif event.args and 'Ideal Render Instant' in event.args:
+        cadence.append(frame_persistence)
+        frame_persistence = 1
+        old_ideal_render = event.args['Ideal Render Instant']
+    cadence.append(frame_persistence)
+    cadence.pop(0)
+    return cadence
+
+  def Bucketize(self, cadence):

[phoglund_chromium, 2015/09/17 11:23:58]

"Bucketize" isn't a great name, what about ComputeSourceToOutputDistribution?

+    """Create distribution for the cadence frame display values."""
+    # If the overall display distribution is A1:A2:..:An,
+    # this will tell us how many times a frame
+    # stays displayed during Ak vsync duration (i.e. Ak/DISPLAY_HERTZ)
+    # also known as 'source to output' distribution.
+    bucket = {}
+    for ticks in cadence:
+      if ticks in bucket:
+        bucket[ticks] += 1
+      else:
+        bucket[ticks] = 1
+    return bucket
+
+  def InferFpsFromCadence(self, bucket):
+    """Calculate the apparent FPS from cadence pattern."""
+    # The mean ratio is the barycenter
+    number_frames = sum([bucket[ticks] for ticks in bucket])
+    number_vsyncs = sum([ticks * bucket[ticks] for ticks in bucket])
+    mean_ratio = float(number_vsyncs) / number_frames
+    fps = DISPLAY_HERTZ / mean_ratio
+    return fps
+
+  def InferFrozenFramesEvents(self, bucket):
+    """Find evidence of frozen frames in distribution."""
+    # For simplicity we count as freezing the frames
+    # that appear at least five times in a row
+    # counted from 'Ideal Render Instant' perspective.
+    frozen_frames = []
+    for ticks in bucket:
+      if ticks >= FROZEN_THRESHOLD:
+        logging.error('%s frames not updated after %s vsyncs',
+            bucket[ticks], ticks)
+        frozen_frames.append(
+            {'frozen_frames': ticks -1,
+             'occurences': bucket[ticks]})
+    return frozen_frames
+
+  def FrozenPenaltyWeight(self, number_frozen_frames):
+    """Returns the weighted penalty for a number of frozen frames."""
+    # As mentioned earlier, we count for frozen anything above 6 vsync
+    # display duration for the same 'Initial Render Instant'.
+    penalty = {
+      0: 0,
+      1: 0,
+      2: 0,
+      3: 0,
+      4: 0,
+      5: 1,
+      6: 5,
+      7: 15,
+      8: 25
+    }
+    weight = penalty.get(number_frozen_frames,
+        8 * (number_frozen_frames - 4))
+    return weight
+
+  def IsRemoteStream(self, stream):
+    """Determines if a stream is remote or local."""
+    return stream[0] == '1'
+
+
+  def InferTimeStats(self):

[phoglund_chromium, 2015/09/17 11:23:58]

You're going to have to rewrite this one quite a bit before I'm happy. I suggest
you write a unit test and try to cover the most important parts first, it's
going to help a lot when you do the refactoring!

[cpaulin (no longer in chrome), 2015/09/17 23:58:55]

Acknowledged.

+    """Calculate time stamp stats for all events."""
+    stats = {}
+    for stream in self.events:
+      self.relevant_events = self.events[stream]

[phoglund_chromium, 2015/09/17 11:23:58]

Ugh, don't do this - get rid of self.relevant.events.

It has multiple problems:
  * It's used in this method, and in InferCadence. This puts a very implicit
assumption on InferCadence - it looks like a nice public method, but it won't
work unless it's called from this method or some other method that helpfully
sets up the relevant events for it. This is bad design. Firstly, InferCadence
should be _InferCadence to signify it's an internal helper method. Second, it
should take the relevant events as an argument instead of reading from self.
Then it's suddenly very clear that it works on a set of relevant events provided
by someone else. Also, your code will not quietly stop inferring cadence if
someone moves where the relevant events are set. Instead, you will get a clean
error saying the relevant events are not defined.
* The constructor states it "sorts the relevant events", but relevant events are
never populated there, just self.events. This is very confusing.

Just make relevant_events a local variable here, and pass as an argument to
InferCadence. In general, something should only be put in self if it's part of
the object's state - something that mutates over time and intrinsically belongs
to the class. The less events you have, the better.

[cpaulin (no longer in chrome), 2015/09/17 23:58:55]

Acknowledged.

+      if not self.IsRemoteStream(stream):
+        logging.info('Skipping processing of local stream: %s', stream)
+        continue
+      cadence = self.InferCadence()
+      bucket = self.Bucketize(cadence)
+      fps = self.InferFpsFromCadence(bucket)
+      frozen_frames = self.InferFrozenFramesEvents(bucket)
+      # Drift time between Ideal Render Instant and Actual Render Begin.

[phoglund_chromium, 2015/09/17 11:23:58]

The method really gets off to a good start, with clean helper methods to compute
cadence, fps and so on. The rest of it really needs to be broken up. A good
guideline is that a method should never be longer than 30 lines; otherwise it's
doing too much. This method in particular is a mess of interlocking local
variables, continue statements etc that make it impossible to reason about what
it's doing. Can you promise me to never again write a method that's longer than
30 lines? :)

You should be able to move lines 131 to 151 or so into a helper method. It
should take relevant events as input and return the drift time list and the
rendering length error. If your local variables trip you up, try moving
computations that don't depend on each other so you can extract a clean helper
method. You can return multiple returns values in Python fortunately.

For the continue on line 150: Try to check this earlier, if possible on line
123. In that case you can pass the *ideal_render variables as arguments to your
new helper method. Or is there some other, easier way of finding out if we only
have one event?

+      drift_time = []
+      old_ideal_render = 0
+      discrepancy = []
+      index = 0
+      for event in self.relevant_events:
+        current_ideal_render = event.args['Ideal Render Instant']
+        if current_ideal_render == old_ideal_render:
+          continue
+        drift_time.append(
+                event.args['Actual Render Begin'] - current_ideal_render)
+        discrepancy.append(abs(current_ideal_render - old_ideal_render
+                - VSYNC_DURATION * cadence[index]))
+        old_ideal_render = current_ideal_render
+        index += 1
+      discrepancy.pop(0)
+      last_ideal_render = self.relevant_events[-1].args['Ideal Render Instant']
+      first_ideal_render = self.relevant_events[0].args['Ideal Render Instant']
+      if last_ideal_render == first_ideal_render:
+        logging.error('Found a stream=%s with just one event', stream)
+        continue
+      rendering_length_error = 100.0 * (sum([x for x in discrepancy]) /
+          (last_ideal_render - first_ideal_render))
+      # Some stats on drift time.
+      mean_drift_time = numpy.mean(drift_time)
+      std_dev_drift_time = numpy.std(drift_time)
+      norm_drift_time = [abs(x - mean_drift_time) for x in drift_time]
+      # How many times is a frame later/earlier than T=2/DISPLAY_HERTZ.
+      # Time is in microseconds.
+      frames_severely_out_of_sync = len(
+          [x for x in norm_drift_time if abs(x) > 2 * VSYNC_DURATION])
+      percent_badly_oos = (
+          100.0 * frames_severely_out_of_sync / len(norm_drift_time))
+      # How many times is a frame later/earlier than 1/DISPLAY_HERTZ.
+      frames_out_of_sync = len(
+          [x for x in norm_drift_time if abs(x) > VSYNC_DURATION])
+      percent_out_of_sync = (
+          100.0 * frames_out_of_sync / len(norm_drift_time))
+
+      frames_oos_only_once = frames_out_of_sync - frames_severely_out_of_sync
+      # For safety I don't use number_vsyncs = len(self.relevant_events) just
+      # in case other events are added later.
+      number_vsyncs = sum([n * bucket[n] for n in bucket])
+      # Calculate smoothness metric.
+      # From the formula, we can see that smoothness score can be negative.
+      smoothness_score = 100.0 - 100.0*(frames_oos_only_once +
+          SEVERITY * frames_severely_out_of_sync) / len(norm_drift_time)
+      # Calculate freezing metric.
+      # Freezing metric can be negative if things are really bad.
+      freezing_score = 100.0
+      for frozen_report in frozen_frames:
+        weight = self.FrozenPenaltyWeight(frozen_report['frozen_frames'])
+        freezing_score -= (
+            100.0 * frozen_report['occurences'] / number_vsyncs * weight)
+      # negative scores are meaningless, so zero them
+      if freezing_score < 0:
+        freezing_score = 0
+      if smoothness_score < 0:
+        smoothness_score = 0
+

[phoglund_chromium, 2015/09/17 11:23:58]

Here is how I would ideally want this method to look:

drift_time = ComputeDriftTime(relevant_events)
mean_drift_time = numpy.mean(drift_time)
norm_drift_time = [...]
percent_badly_oos = ComputePercentBadlyOutOfSync(norm_drift_time)

That is, try to keep the computations out of the main method as much as
possible. All that should remain is the management of how data depend on each
other. In this case, for instance, percent_badly_oos depends on drift_time
through a couple intermediaries. That's legit to express is in this function,
but there's too much computation obstructing the interesting parts.

[cpaulin (no longer in chrome), 2015/09/17 23:58:55]

Patrik, I have grouped the stats by logical units:
__ComputeDrifTimeStats : everything directly derived from drift_time, including
rendering_length_error
__ComputeSmoothnesStats : everything directly involved in smoothness score
calculation like the out of sync frames
__ComputeFreezingScore : everythin that has to do with frozen frames

I think it make sense to keep the related stats together and adds meaning.

+      stats = {
+          'drift_time': drift_time,
+          'mean_drift_time': mean_drift_time,
+          'std_dev_drift_time': std_dev_drift_time,
+          'percent_badly_out_of_sync': percent_badly_oos,
+          'percent_out_of_sync': percent_out_of_sync,
+          'smoothness_score': smoothness_score,
+          'freezing_score': freezing_score,
+          'rendering_length_error': rendering_length_error,
+          'fps': fps,
+          'bucket': bucket}
+      print "Stats for remote stream {0}: {1}".format(stream, stats)
+    return stats
+
+
+class WebRtcRenderingTimelineMetric(timeline_based_metric.TimelineBasedMetric):
+  """WebrtcRenderingTimelineMetric calculates metric for WebMediaPlayerMS.
+
+  The following metrics are added to the results:
+    WebRtcRendering_drift_time usec
+    WebRTCRendering_std_dev_drift_time usec
+    WebRTCRendering_percent_badly_out_of_sync %
+    WebRTCRendering_percent_out_of_sync %
+    WebRTCRendering_fps FPS
+    WebRTCRendering_smoothness_score %
+    WebRTCRendering_freezing_score %
+    WebRTCRendering_rendering_length_error %
+  """
+
+  def __init__(self):
+    super(WebRtcRenderingTimelineMetric, self).__init__()
+
+  @staticmethod
+  def IsMediaPlayerMSEvent(event):
+    """Verify that the event is a webmediaplayerMS event."""
+    return event.name == WEB_MEDIA_PLAYER_MS_EVENT
+
+  @staticmethod
+  def IsEventInInteraction(event, interaction):
+    """Verify that the event belong to the gbiven interaction."""
+    return interaction[0].start <= event.start <= interaction[0].end
+
+  def AddResults(self, model, renderer_thread, interactions, results):
+    """Adding metrics to the results."""
+    assert interactions
+    found_events = []
+    for event in renderer_thread.parent.IterAllEvents(
+        event_predicate=self.IsMediaPlayerMSEvent):
+      if self.IsEventInInteraction(event, interactions):
+        found_events.append(event)
+    stats_parser = WebMediaPlayerMsRenderingStats(found_events)
+    rendering_stats = stats_parser.InferTimeStats()
+    none_reason = None
+    if not rendering_stats:
+      rendering_stats = dict.fromkeys([
+          'drift_time'
+          'mean_drift_time',
+          'std_dev_drift_time',
+          'percent_badly_out_of_sync',
+          'percent_out_of_sync',
+          'smoothness_score',
+          'freezing_score',
+          'rendering_length_error',
+          'fps',
+          'bucket'])
+      none_reason = "No WebMediaPlayerMS::UpdateCurrentFrame event found"
+    logging.info('rendering stats : %s', rendering_stats)
+    results.AddValue(list_of_scalar_values.ListOfScalarValues(
+        results.current_page,
+        'WebRtcRendering_drift_time',
+        'usec',
+        rendering_stats['drift_time'],
+        important=True,
+        description='Drift time for a rendered frame',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_mean_drift_time',
+        'usec',
+        rendering_stats['mean_drift_time'],
+        important=True,
+        description='Mean drift time for frames',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_std_dev_drift_time',
+        'usec',
+        rendering_stats['std_dev_drift_time'],
+        important=True,
+        description='Standard deviation of drift time for frames',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_percent_badly_out_of_sync',
+        '%',
+        rendering_stats['percent_badly_out_of_sync'],
+        important=True,
+        description='Percentage of frame which drifted more than 2 VSYNC',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_percent_out_of_sync',
+        '%',
+        rendering_stats['percent_out_of_sync'],
+        important=True,
+        description='Percentage of frame which drifted more than 1 VSYNC',
+        none_value_reason=none_reason))
+
+    # make the output distribution a list since
+    # no facilities for dict values exist (yet)
+    bucket_list = []
+    for key, value in rendering_stats['bucket'].iteritems():
+      temp = '%s:%s' % (key, value)
+      bucket_list.append(temp)
+    results.AddValue(list_of_string_values.ListOfStringValues(
+        results.current_page,
+        'WebRtcRendering_bucket',
+        'frames:occurences',
+        bucket_list,
+        important=True,
+        description='Output distribution of frames',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_fps',
+        'FPS',
+        rendering_stats['fps'],
+        important=True,
+        description='Calculated Frame Rate of video rendering',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_smoothness_score',
+        '%',
+        rendering_stats['smoothness_score'],
+        important=True,
+        description='Smoothness score of rendering',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_freezing_score',
+        '%',
+        rendering_stats['freezing_score'],
+        important=True,
+        description='Freezing score of rendering',
+        none_value_reason=none_reason))
+
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        'WebRTCRendering_rendering_length_error',
+        '%',
+        rendering_stats['rendering_length_error'],
+        important=True,
+        description='Rendering length error rate',
+        none_value_reason=none_reason))