Support total and per-second task/threadtime timeline metrics

The current threadtime timeline measurement only supports per-frame
metrics. Generalize this to support total and per-second  metrics for
threadtimes and tasks.

BUG=466213
CQ_EXTRA_TRYBOTS=tryserver.chromium.perf:mac_perf_bisect;tryserver.chromium.perf:android_nexus5_perf_bisect

Review URL: https://codereview.chromium.org/1084533005

Cr-Commit-Position: refs/heads/master@{#329322}

tools/perf/benchmarks/thread_times.py

@@ -18,6 +18,11 @@ class _ThreadTimes(benchmark.Benchmark):
   def Name(cls):
     return 'thread_times'
 
+  @classmethod
+  def ValueCanBeAddedPredicate(cls, value, _):
+    # Default to only reporting per-frame metrics.
+    return 'per_second' not in value.name
+
   def CreatePageTest(self, options):
     return thread_times.ThreadTimes(options.report_silk_details)
 

tools/perf/measurements/thread_times_unittest.py

@@ -35,10 +35,11 @@ class ThreadTimesUnitTest(page_test_test_case.PageTestTestCase):
     results = self.RunMeasurement(measurement, ps, options = timeline_options)
     self.assertFalse(len(results.failures), results.failures)
 
-    for category in timeline.TimelineThreadCategories.values():
-      cpu_time_name = timeline.ThreadCpuTimeResultName(category)
-      cpu_time = results.FindAllPageSpecificValuesNamed(cpu_time_name)
-      self.assertEquals(len(cpu_time), 1)
+    for interval in timeline.IntervalNames:
+      for category in timeline.TimelineThreadCategories.values():
+        cpu_time_name = timeline.ThreadCpuTimeResultName(category, interval)
+        cpu_time = results.FindAllPageSpecificValuesNamed(cpu_time_name)
+        self.assertEquals(len(cpu_time), 1)
 
   def testBasicForPageWithNoGesture(self):
     ps = self.CreateEmptyPageSet()
@@ -49,10 +50,11 @@ class ThreadTimesUnitTest(page_test_test_case.PageTestTestCase):
     results = self.RunMeasurement(measurement, ps, options = timeline_options)
     self.assertEquals(0, len(results.failures))
 
-    for category in timeline.TimelineThreadCategories.values():
-      cpu_time_name = timeline.ThreadCpuTimeResultName(category)
-      cpu_time = results.FindAllPageSpecificValuesNamed(cpu_time_name)
-      self.assertEquals(len(cpu_time), 1)
+    for interval in timeline.IntervalNames:
+      for category in timeline.TimelineThreadCategories.values():
+        cpu_time_name = timeline.ThreadCpuTimeResultName(category, interval)
+        cpu_time = results.FindAllPageSpecificValuesNamed(cpu_time_name)
+        self.assertEquals(len(cpu_time), 1)
 
   @decorators.Disabled('chromeos')  # crbug.com/483212
   def testWithSilkDetails(self):
@@ -63,10 +65,12 @@ class ThreadTimesUnitTest(page_test_test_case.PageTestTestCase):
 
     main_thread = "renderer_main"
     expected_trace_categories = ["blink", "cc", "idle"]
-    for trace_category in expected_trace_categories:
-      value_name = timeline.ThreadDetailResultName(main_thread, trace_category)
-      values = results.FindAllPageSpecificValuesNamed(value_name)
-      self.assertEquals(len(values), 1)
+    for interval in timeline.IntervalNames:
+      for trace_category in expected_trace_categories:
+        value_name = timeline.ThreadDetailResultName(
+            main_thread, interval, trace_category)
+        values = results.FindAllPageSpecificValuesNamed(value_name)
+        self.assertEquals(len(values), 1)
 
   def testCleanUpTrace(self):
     self.TestTracingCleanedUp(thread_times.ThreadTimes, self._options)

tools/perf/metrics/timeline.py

@@ -101,6 +101,8 @@ OverheadTraceName = "overhead"
 FrameTraceName = "::SwapBuffers"
 FrameTraceThreadName = "renderer_compositor"
 
+IntervalNames = ["frame", "second"]
+
 def Rate(numerator, denominator):
   return DivideIfPossibleOrZero(numerator, denominator)
 
@@ -127,19 +129,37 @@ def ThreadCategoryName(thread_name):
     thread_category = TimelineThreadCategories[thread_name]
   return thread_category
 
-def ThreadCpuTimeResultName(thread_category):
+def ThreadCpuTimeResultName(thread_category, interval_name):
   # This isn't a good name, but I don't want to change it and lose continuity.
-  return "thread_" + thread_category + "_cpu_time_per_frame"
+  return "thread_" + thread_category + "_cpu_time_per_" + interval_name
 
-def ThreadTasksResultName(thread_category):
-  return "tasks_per_frame_" + thread_category
+def ThreadTasksResultName(thread_category, interval_name):
+  return "tasks_per_" + interval_name + "_" + thread_category
 
 def ThreadMeanFrameTimeResultName(thread_category):
   return "mean_frame_time_" + thread_category
 
-def ThreadDetailResultName(thread_category, detail):
+def ThreadDetailResultName(thread_category, interval_name, detail):
   detail_sanitized = detail.replace('.','_')
-  return "thread_" + thread_category + "|" + detail_sanitized
+  interval_sanitized = ""
+  # Special-case per-frame detail names to preserve continuity.
+  if interval_name == "frame":
+    interval_sanitized = ""
+  else:
+    interval_sanitized = "_per_" + interval_name
+  return (
+      "thread_" + thread_category + interval_sanitized + "|" + detail_sanitized)
+
+def ThreadCpuTimeUnits(interval_name):
+  if interval_name == "second":
+    return "%"
+  return "ms"
+
+def ThreadCpuTimeValue(ms_cpu_time_per_interval, interval_name):
+  # When measuring seconds of CPU time per second of system time, report a %.
+  if interval_name == "second":
+    return (ms_cpu_time_per_interval / 1000.0) * 100.0
+  return ms_cpu_time_per_interval
 
 
 class ResultsForThread(object):
@@ -188,28 +208,21 @@ class ResultsForThread(object):
     self.all_slices.extend(self.SlicesInActions(thread.all_slices))
     self.toplevel_slices.extend(self.SlicesInActions(thread.toplevel_slices))
 
-  # Currently we report cpu-time per frame, tasks per frame, and possibly
-  # the mean frame (if there is a trace specified to find it).
-  def AddResults(self, num_frames, results):
-    cpu_per_frame = Rate(self.cpu_time, num_frames)
-    tasks_per_frame = Rate(len(self.toplevel_slices), num_frames)
+  # Reports cpu-time per interval and tasks per interval.
+  def AddResults(self, num_intervals, interval_name, results):
+    cpu_per_interval = Rate(self.cpu_time, num_intervals)
+    tasks_per_interval = Rate(len(self.toplevel_slices), num_intervals)
     results.AddValue(scalar.ScalarValue(
-        results.current_page, ThreadCpuTimeResultName(self.name),
-        'ms', cpu_per_frame))
+        results.current_page,
+        ThreadCpuTimeResultName(self.name, interval_name),
+        ThreadCpuTimeUnits(interval_name),
+        ThreadCpuTimeValue(cpu_per_interval, interval_name)))
     results.AddValue(scalar.ScalarValue(
-        results.current_page, ThreadTasksResultName(self.name),
-        'tasks', tasks_per_frame))
-    # Report mean frame time if this is the thread we are using for normalizing
-    # other results. We could report other frame rates (eg. renderer_main) but
-    # this might get confusing.
-    if self.name == FrameTraceThreadName:
-      num_frames = self.CountTracesWithName(FrameTraceName)
-      mean_frame_time = Rate(self.all_action_time, num_frames)
-      results.AddValue(scalar.ScalarValue(
-          results.current_page, ThreadMeanFrameTimeResultName(self.name),
-          'ms', mean_frame_time))
+        results.current_page,
+        ThreadTasksResultName(self.name, interval_name),
+        'tasks', tasks_per_interval))
 
-  def AddDetailedResults(self, num_frames, results):
+  def AddDetailedResults(self, num_intervals, interval_name, results):
     slices_by_category = collections.defaultdict(list)
     for s in self.all_slices:
       slices_by_category[s.category].append(s)
@@ -217,16 +230,20 @@ class ResultsForThread(object):
     for category, slices_in_category in slices_by_category.iteritems():
       self_time = sum([x.self_time for x in slices_in_category])
       all_self_times.append(self_time)
-      self_time_result = (float(self_time) / num_frames) if num_frames else 0
+      self_time_per_interval = Rate(self_time, num_intervals)
       results.AddValue(scalar.ScalarValue(
-          results.current_page, ThreadDetailResultName(self.name, category),
-          'ms', self_time_result))
+          results.current_page,
+          ThreadDetailResultName(self.name, interval_name, category),
+          ThreadCpuTimeUnits(interval_name),
+          ThreadCpuTimeValue(self_time_per_interval, interval_name)))
     all_measured_time = sum(all_self_times)
     idle_time = max(0, self.all_action_time - all_measured_time)
-    idle_time_result = (float(idle_time) / num_frames) if num_frames else 0
+    idle_time_per_interval = Rate(idle_time, num_intervals)
     results.AddValue(scalar.ScalarValue(
-        results.current_page, ThreadDetailResultName(self.name, "idle"),
-        'ms', idle_time_result))
+        results.current_page,
+        ThreadDetailResultName(self.name, interval_name, "idle"),
+        ThreadCpuTimeUnits(interval_name),
+        ThreadCpuTimeValue(idle_time_per_interval, interval_name)))
 
   def CountTracesWithName(self, substring):
     count = 0
@@ -235,6 +252,7 @@ class ResultsForThread(object):
         count += 1
     return count
 
+
 class ThreadTimesTimelineMetric(timeline_based_metric.TimelineBasedMetric):
   def __init__(self):
     super(ThreadTimesTimelineMetric, self).__init__()
@@ -247,7 +265,7 @@ class ThreadTimesTimelineMetric(timeline_based_metric.TimelineBasedMetric):
     thread_category_results = {}
     for name in TimelineThreadCategories.values():
       thread_category_results[name] = ResultsForThread(
-        model, [r.GetBounds() for r in interaction_records], name)
+          model, [r.GetBounds() for r in interaction_records], name)
 
     # Group the slices by their thread category.
     for thread in model.GetAllThreads():
@@ -263,15 +281,30 @@ class ThreadTimesTimelineMetric(timeline_based_metric.TimelineBasedMetric):
       if ThreadCategoryName(thread.name) in FastPathThreads:
         thread_category_results['total_fast_path'].AppendThreadSlices(thread)
 
-    # Calculate the number of frames.
+    # Calculate the interaction's number of frames.
     frame_rate_thread = thread_category_results[FrameTraceThreadName]
     num_frames = frame_rate_thread.CountTracesWithName(FrameTraceName)
 
-    # Report the desired results and details.
-    for thread_results in thread_category_results.values():
-      if thread_results.name in self.results_to_report:
-        thread_results.AddResults(num_frames, results)
-      # TOOD(nduca): When generic results objects are done, this special case
-      # can be replaced with a generic UI feature.
-      if thread_results.name in self.details_to_report:
-        thread_results.AddDetailedResults(num_frames, results)
+    # Calculate the interaction's duration.
+    all_threads = thread_category_results['total_all']
+    num_seconds = all_threads.all_action_time / 1000.0
+
+    # Report the desired results and details for each interval type.
+    intervals = [('frame', num_frames), ('second', num_seconds)]
+    for (interval_name, num_intervals) in intervals:
+      for thread_results in thread_category_results.values():
+        if thread_results.name in self.results_to_report:
+          thread_results.AddResults(num_intervals, interval_name, results)
+        # TOOD(nduca): When generic results objects are done, this special case
+        # can be replaced with a generic UI feature.
+        if thread_results.name in self.details_to_report:
+          thread_results.AddDetailedResults(
+              num_intervals, interval_name, results)
+
+    # Report mean frame time for the frame rate thread. We could report other
+    # frame rates (eg. renderer_main) but this might get confusing.
+    mean_frame_time = Rate(frame_rate_thread.all_action_time, num_frames)
+    results.AddValue(scalar.ScalarValue(
+        results.current_page,
+        ThreadMeanFrameTimeResultName(FrameTraceThreadName),
+        'ms', mean_frame_time))

tools/perf/metrics/timeline_unittest.py

@@ -109,14 +109,16 @@ class ThreadTimesTimelineMetricUnittest(unittest.TestCase):
 
     # Test that all result thread categories exist
     for name in timeline.TimelineThreadCategories.values():
-      results.GetPageSpecificValueNamed(timeline.ThreadCpuTimeResultName(name))
+      results.GetPageSpecificValueNamed(
+          timeline.ThreadCpuTimeResultName(name, 'frame'))
 
   def testBasic(self):
     model = model_module.TimelineModel()
     renderer_main = model.GetOrCreateProcess(1).GetOrCreateThread(2)
     renderer_main.name = 'CrRendererMain'
 
-    # Create two frame swaps (Results times should be divided by two)
+    # Create two frame swaps (Results times should be divided by two) for
+    # an interaction that lasts 20 milliseconds.
     cc_main = model.GetOrCreateProcess(1).GetOrCreateThread(3)
     cc_main.name = 'Compositor'
     cc_main.BeginSlice('cc_cat', timeline.FrameTraceName, 10, 10)
@@ -144,12 +146,25 @@ class ThreadTimesTimelineMetricUnittest(unittest.TestCase):
     main_thread = "renderer_main"
     cc_thread = 'renderer_compositor'
     assert_results = [
-      (timeline.ThreadCpuTimeResultName(main_thread), 'ms', 9.75),
-      (timeline.ThreadTasksResultName(main_thread), 'tasks', 0.5),
       (timeline.ThreadMeanFrameTimeResultName(cc_thread), 'ms', 10.0),
-      (timeline.ThreadDetailResultName(main_thread,'cat1'), 'ms', 9.5),
-      (timeline.ThreadDetailResultName(main_thread,'cat2'), 'ms', 0.5),
-      (timeline.ThreadDetailResultName(main_thread,'idle'), 'ms', 0)
+      (timeline.ThreadTasksResultName(main_thread, 'frame'), 'tasks', 0.5),
+      (timeline.ThreadTasksResultName(main_thread, 'second'), 'tasks', 50.0),
+      (timeline.ThreadTasksResultName(cc_thread, 'frame'), 'tasks', 1.0),
+      (timeline.ThreadTasksResultName(cc_thread, 'second'), 'tasks', 100.0),
+      (timeline.ThreadCpuTimeResultName(main_thread, 'frame'), 'ms', 9.75),
+      (timeline.ThreadCpuTimeResultName(main_thread, 'second'), '%', 97.5),
+      (timeline.ThreadCpuTimeResultName(cc_thread, 'frame'), 'ms', 1.0),
+      (timeline.ThreadCpuTimeResultName(cc_thread, 'second'), '%', 10.0),
+      (timeline.ThreadDetailResultName(main_thread, 'frame', 'cat1'),
+       'ms', 9.5),
+      (timeline.ThreadDetailResultName(main_thread, 'second', 'cat1'),
+       '%', 95.0),
+      (timeline.ThreadDetailResultName(main_thread, 'frame', 'cat2'),
+       'ms', 0.5),
+      (timeline.ThreadDetailResultName(main_thread, 'second', 'cat2'),
+       '%', 5.0),
+      (timeline.ThreadDetailResultName(main_thread, 'frame', 'idle'), 'ms', 0),
+      (timeline.ThreadDetailResultName(main_thread, 'second', 'idle'), '%', 0)
     ]
     for name, unit, value in assert_results:
       results.AssertHasPageSpecificScalarValue(name, unit, value)
@@ -182,8 +197,9 @@ class ThreadTimesTimelineMetricUnittest(unittest.TestCase):
                               [_GetInteractionRecord(10, 30)])
 
     # Test a couple specific results.
-    assert_results = {
-      timeline.ThreadCpuTimeResultName('renderer_main') : 9.0,
-    }
-    for name, value in assert_results.iteritems():
-      results.AssertHasPageSpecificScalarValue(name, 'ms', value)
+    assert_results = [
+      (timeline.ThreadCpuTimeResultName('renderer_main', 'frame') , 'ms', 9.0),
+      (timeline.ThreadCpuTimeResultName('renderer_main', 'second') , '%', 45.0),
+    ]
+    for name, unit, value in assert_results:
+      results.AssertHasPageSpecificScalarValue(name, unit, value)