Add responsiveness_metric for timeline_based_measurement

tools/telemetry/telemetry/web_perf/metrics/mainthread_jank.py

+# Copyright 2014 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
+
+from telemetry.web_perf.metrics import timeline_based_metric
+from telemetry.web_perf import timeline_interaction_record as tir_module
+
+# A top slice (defined below) of a main thread can cause the webapp to behave
+# unresponsively if its thread duration is greater than or equals to
+# USER_PERCEIVABLE_DELAY_THRESHOLD_MS. Human eyes can perceive delay at low as
+# 100ms, but since we use thread time instead of wall-time, we reduce the
+# threshold further to 50ms to make room for other OS's activity.
+USER_PERCEIVABLE_DELAY_THRESHOLD_MS = 50
+
+
+def _IsTopSlice(event):
+  """Whether event refers to a top MessageLoop task, i.e: there is no
+  other MessageLoop task on top of this task and contains it.
+
+  Returns:
+      True if this timeline event refers to the top MesssageLoop task.
+      False otherwise.
+  """
+  return event.name == 'MessageLoop::RunTask' and event.category == 'toplevel'
+
+
+class _MainthreadJankStat(object):
+  """A small wrapper class for storing stats related to mainthread jank."""
+
+  def __init__(self):
+    self.num_big_top_slices = 0
+    self.sum_top_slices_thread_time = 0
+    self.sum_big_top_slices_thread_time = 0
+    self.biggest_top_slice_thread_time = 0
+
+
+def _ComputeMainthreadJankStats(renderer_thread, record):
+  """Computes the mainthread jank stat on the record range.
+
+  Returns:
+      An instance of _MainthreadJankStat, which has:
+
+      num_big_top_slices is the number of top slices whose thread time ranges
+      overlapped with (thread_start, thread_end) and the overlapped thread
+      duration is greater than or equal USER_PERCEIVABLE_DELAY_THRESHOLD_MS.
+
+      sum_top_slices_thread_time is the total thread duration of all top slices
+      whose thread time ranges overlapped with the (thread_start, thread_end)
+      time of record.
+
+      sum_big_top_slices_thread_time is the total thread duration of all top
+      slices whose thread time ranges overlapped with (thread_start, thread_end)
+      and the overlapped thread duration is greater than or equal
+      USER_PERCEIVABLE_DELAY_THRESHOLD_MS.
+
+      biggest_top_slice_thread_time is the biggest thread duration of all
+      top slices whose thread time ranges overlapped with
+      (thread_start, thread_end).
+
+      Note: thread duration of each slices is computed using overlapped range
+      with (thread_start, thread_end).
+  """
+  stat = _MainthreadJankStat()
+  # If a slice overlaps with record in thread time, it will also overlap with
+  # the record in wall-time. Hence we can iterate through all slices that
+  # overlap with record's start & end in wall time.
+  for s in renderer_thread.IterAllSlicesOverlappedWithTimeRange(
+      record.start, record.end):
+    if not _IsTopSlice(s):

[nduca, 2014/05/29 23:33:12]

so we have "toplevel slices" on a thread that are the ones at the top of the
nesting stack. please make iterallslices use that array instead of using this
istopslice thing and making assumptions about trace event names. some tasks dont
have messageloop as the top and its a fragile assumption

[nednguyen, 2014/05/30 16:38:26]

Done. I just iterate through all the top slices. If they don't overlap,
jank_thread_duration is 0 and it works fine for the metrics.

In term of run time performance, it's always O(n) even if we can use binary
search to get the start & end, and I believe the number of top_slices is not
that big.

FYI, I still keep the IterAllSlicesOverlappedWithTimeRange in thread.py since I
think all timeline based metrics should handle the corner case of overlaps on
the left & right.

+      continue
+    jank_thread_duration = record.GetOverlappedThreadTimeForSlice(s)
+    stat.sum_top_slices_thread_time += jank_thread_duration
+    stat.biggest_top_slice_thread_time = max(
+        stat.biggest_top_slice_thread_time, jank_thread_duration)
+    if jank_thread_duration >= USER_PERCEIVABLE_DELAY_THRESHOLD_MS:
+      stat.num_big_top_slices += 1
+      stat.sum_big_top_slices_thread_time += jank_thread_duration
+  return stat
+
+
+class MainthreadJankMetric(timeline_based_metric.TimelineBasedMetric):
+  """Computes the mainthread jank metrics on the record ranges.
+
+      num_big_mainthread_jank is the number of top slices whose thread time
+      ranges overlapped with any thread time ranges of the records and the
+      overlapped thread duration is greater than or equal
+      USER_PERCEIVABLE_DELAY_THRESHOLD_MS.
+
+      total_mainthread_jank_thread_time is the total thread duration of all top
+      slices whose thread time ranges overlapped with any thread time ranges of
+      the records.
+
+      total_big_jank_thread_time is the total thread duration of all top
+      slices whose thread time ranges overlapped with any thread time ranges of
+      the records and the overlapped thread duration is greater than or equal
+      USER_PERCEIVABLE_DELAY_THRESHOLD_MS.
+
+      biggest_jank_thread_time is the biggest thread duration of all
+      top slices whose thread time ranges overlapped with any of records' thread
+      time ranges.
+  """
+
+  def __init__(self):
+    super(MainthreadJankMetric, self).__init__()
+
+  def AddResults(self, _, renderer_thread, interaction_records, results):
+    self.VerifyNonOverlappedRecords(interaction_records)
+    num_big_janks = 0
+    total_mainthread_jank_thread_time = 0
+    total_big_jank_thread_time = 0
+    biggest_jank_thread_time = 0
+
+    try:
+      for record in interaction_records:
+        record_jank_stat = _ComputeMainthreadJankStats(renderer_thread, record)
+        num_big_janks += record_jank_stat.num_big_top_slices
+        total_mainthread_jank_thread_time += (
+            record_jank_stat.sum_top_slices_thread_time)
+        total_big_jank_thread_time += (
+            record_jank_stat.sum_big_top_slices_thread_time)
+        biggest_jank_thread_time = (
+            max(biggest_jank_thread_time,
+                record_jank_stat.biggest_top_slice_thread_time))
+    # TODO(nednguyen): maybe fall back to use wall-time for computing the
+    # metrics.
+    except tir_module.NoThreadTimeDataException as e:
+      logging.warning(
+          'Main thread jank metrics cannot be computed since trace does not '

[nduca, 2014/05/29 23:33:12]

this is going to spam the console hugely... can you come up with a solution that
prints once?

[nednguyen, 2014/05/30 16:38:26]

By hugely, do you mean one log line per list of records? I think it wouldn't be
too bad since with timeline_based_measurement, this maps to the number of
records on the timeline, and we already get stdout result for each record with
timeline_based_measurement anyway. 

In addition, I just add some more helpful debugging information.

+          'contain thread time data. %s', repr(e))
+      return
+
+    results.Add('num_big_mainthread_janks', 'score', num_big_janks)

[nduca, 2014/05/29 23:33:12]

are these all important? can you please pick 1 that is important and pass
'unimportant' as the data type for the others?

[nednguyen, 2014/05/30 16:38:26]

I think num_big_mainthread_janks and total_big_jank_thread_time are both
important. The former tells us how many times users get the annoying perceivable
delay, whereas the latter tells us the total amount of time that users are
"unhappy". wdyt?

+    results.Add('total_mainthread_jank_thread_time', 'ms',
+                total_mainthread_jank_thread_time)
+    results.Add('total_big_jank_thread_time', 'ms',
+                total_big_jank_thread_time)
+    results.Add('biggest_jank_thread_time', 'ms', biggest_jank_thread_time)