Add stale-frame metrics

This CL implements the stale-frame metrics that measure the undesirably
prolonged presentation time due to frame dropping. The metrics are
reported under the Graphics.Smoothness.Stale.* (staleness of each frame)
and Graphics.Smoothness.MaxStale.* (maximum staleness per interaction).

Bug: 1092949
Change-Id: Id2e3d616bfa4362fd8f4b6db4fedb23290d6cba6
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2490385Reviewed-by: Steven Holte <holte@chromium.org>
Reviewed-by: Jonathan Ross <jonross@chromium.org>
Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org>
Commit-Queue: Mingjing Zhang <mjzhang@chromium.org>
Cr-Commit-Position: refs/heads/master@{#827475}

cc/metrics/jank_metrics.cc

@@ -4,6 +4,7 @@
 
 #include "cc/metrics/jank_metrics.h"
 
+#include <algorithm>
 #include <memory>
 #include <string>
 #include <utility>
@@ -21,6 +22,13 @@ namespace {
 constexpr int kBuiltinSequenceNum =
     static_cast<int>(FrameSequenceTrackerType::kMaxType) + 1;
 constexpr int kMaximumJankHistogramIndex = 2 * kBuiltinSequenceNum;
+constexpr int kMaximumStaleHistogramIndex = kBuiltinSequenceNum;
+
+constexpr base::TimeDelta kStaleHistogramMin =
+    base::TimeDelta::FromMicroseconds(1);
+constexpr base::TimeDelta kStaleHistogramMax =
+    base::TimeDelta::FromMilliseconds(1000);
+constexpr int kStaleHistogramBucketCount = 200;
 
 constexpr bool IsValidJankThreadType(FrameSequenceMetrics::ThreadType type) {
   return type == FrameSequenceMetrics::ThreadType::kCompositor ||
@@ -51,6 +59,10 @@ int GetIndexForJankMetric(FrameSequenceMetrics::ThreadType thread_type,
   return static_cast<int>(type) + kBuiltinSequenceNum;
 }
 
+int GetIndexForStaleMetric(FrameSequenceTrackerType type) {
+  return static_cast<int>(type);
+}
+
 std::string GetJankHistogramName(FrameSequenceTrackerType type,
                                  const char* thread_name) {
   return base::StrCat(
@@ -58,6 +70,18 @@ std::string GetJankHistogramName(FrameSequenceTrackerType type,
        FrameSequenceTracker::GetFrameSequenceTrackerTypeName(type)});
 }
 
+std::string GetStaleHistogramName(FrameSequenceTrackerType type) {
+  return base::StrCat(
+      {"Graphics.Smoothness.Stale.",
+       FrameSequenceTracker::GetFrameSequenceTrackerTypeName(type)});
+}
+
+std::string GetMaxStaleHistogramName(FrameSequenceTrackerType type) {
+  return base::StrCat(
+      {"Graphics.Smoothness.MaxStale.",
+       FrameSequenceTracker::GetFrameSequenceTrackerTypeName(type)});
+}
+
 }  // namespace
 
 JankMetrics::JankMetrics(FrameSequenceTrackerType tracker_type,
@@ -139,8 +163,17 @@ void JankMetrics::AddPresentedFrame(
   base::TimeDelta current_frame_delta = current_presentation_timestamp -
                                         last_presentation_timestamp_ -
                                         no_update_time;
-  if (current_frame_delta < base::TimeDelta::FromMilliseconds(0))
-    current_frame_delta = base::TimeDelta::FromMilliseconds(0);
+  const base::TimeDelta zero_delta = base::TimeDelta::FromMilliseconds(0);
+
+  // Guard against the situation when the physical presentation interval is
+  // shorter than |no_update_time|. For example, consider two BeginFrames A and
+  // B separated by 5 vsync cycles of no-updates (i.e. |no_update_time| = 5
+  // vsync cycles); the Presentation of A occurs 2 vsync cycles after BeginFrame
+  // A, whereas Presentation B occurs in the same vsync cycle as BeginFrame B.
+  // In this situation, the physical presentation interval is shorter than 5
+  // vsync cycles and will result in a negative |current_frame_delta|.
+  if (current_frame_delta < zero_delta)
+    current_frame_delta = zero_delta;
 
   // Only start tracking jank if this function has already been
   // called at least once (so that |last_presentation_timestamp_|
@@ -151,7 +184,25 @@ void JankMetrics::AddPresentedFrame(
   // with small fluctuations. The 0.5 * |frame_interval| criterion
   // is chosen so that the jank detection is robust to those
   // fluctuations.
-  if (!last_presentation_timestamp_.is_null() && !prev_frame_delta_.is_zero() &&
+  if (!last_presentation_timestamp_.is_null()) {
+    base::TimeDelta staleness = current_frame_delta - frame_interval;
+    if (staleness < zero_delta)
+      staleness = zero_delta;
+
+    if (tracker_type_ != FrameSequenceTrackerType::kCustom) {
+      STATIC_HISTOGRAM_POINTER_GROUP(
+          GetStaleHistogramName(tracker_type_),
+          GetIndexForStaleMetric(tracker_type_), kMaximumStaleHistogramIndex,
+          AddTimeMillisecondsGranularity(staleness),
+          base::Histogram::FactoryTimeGet(
+              GetStaleHistogramName(tracker_type_), kStaleHistogramMin,
+              kStaleHistogramMax, kStaleHistogramBucketCount,
+              base::HistogramBase::kUmaTargetedHistogramFlag));
+      if (staleness > max_staleness_)
+        max_staleness_ = staleness;
+    }
+
+    if (!prev_frame_delta_.is_zero() &&
         current_frame_delta > prev_frame_delta_ + 0.5 * frame_interval) {
       jank_count_++;
 
@@ -164,6 +215,7 @@ void JankMetrics::AddPresentedFrame(
           current_presentation_timestamp, "tracker-type",
           FrameSequenceTracker::GetFrameSequenceTrackerTypeName(tracker_type_));
     }
+  }
   last_presentation_timestamp_ = current_presentation_timestamp;
   last_presentation_frame_id_ = presented_frame_id;
   prev_frame_delta_ = current_frame_delta;
@@ -184,11 +236,23 @@ void JankMetrics::ReportJankMetrics(int frames_expected) {
       base::LinearHistogram::FactoryGet(
           GetJankHistogramName(tracker_type_, jank_thread_name), 1, 100, 101,
           base::HistogramBase::kUmaTargetedHistogramFlag));
+
+  // Report the max staleness metrics
+  STATIC_HISTOGRAM_POINTER_GROUP(
+      GetMaxStaleHistogramName(tracker_type_),
+      GetIndexForStaleMetric(tracker_type_), kMaximumStaleHistogramIndex,
+      AddTimeMillisecondsGranularity(max_staleness_),
+      base::Histogram::FactoryTimeGet(
+          GetMaxStaleHistogramName(tracker_type_), kStaleHistogramMin,
+          kStaleHistogramMax, kStaleHistogramBucketCount,
+          base::HistogramBase::kUmaTargetedHistogramFlag));
 }
 
 void JankMetrics::Merge(std::unique_ptr<JankMetrics> jank_metrics) {
-  if (jank_metrics)
+  if (jank_metrics) {
     jank_count_ += jank_metrics->jank_count_;
+    max_staleness_ = std::max(max_staleness_, jank_metrics->max_staleness_);
+  }
 }
 
 }  // namespace cc

cc/metrics/jank_metrics.h

@@ -12,6 +12,16 @@
 #include "cc/metrics/frame_sequence_metrics.h"
 
 namespace cc {
+// This class reports 3 sets of metrics related to janks:
+// - Graphics.Smoothness.Jank.*: Percent of frames that have longer
+//                               presentation interval than its previous frame.
+//                               Reports one percentage number per tracker.
+// - Graphics.Smoothness.Stale.*: The difference between the real presentation
+//                                interval and its expected value. Reports one
+//                                TimeDelta per frame.
+// - Graphics.Smoothness.MaxStale.*: The maximum staleness value that occurred
+//                                   during the course of an interaction.
+//                                   Reports one TimeDelta per tracker.
 class CC_EXPORT JankMetrics {
  public:
   JankMetrics(FrameSequenceTrackerType tracker_type,
@@ -23,11 +33,12 @@ class CC_EXPORT JankMetrics {
 
   // Check if a jank occurs based on the timestamps of recent presentations.
   // If there is a jank, increment |jank_count_| and log a trace event.
+  // Graphics.Smoothness.Stale.* metrics are reported in this function.
   void AddPresentedFrame(uint32_t presented_frame_token,
                          base::TimeTicks current_presentation_timestamp,
                          base::TimeDelta frame_interval);
 
-  // Report the occurrence rate of janks as a UMA metric.
+  // Report Graphics.Smoothness.(Jank|MaxStale).* metrics.
   void ReportJankMetrics(int frames_expected);
 
   // Merge the current jank count with a previously unreported jank metrics.
@@ -70,6 +81,9 @@ class CC_EXPORT JankMetrics {
   // A queue storing {sequence number, frame interval} of unprocessed no-update
   // frames, in ascending order of sequence number.
   std::queue<std::pair<uint32_t, base::TimeDelta>> queue_frame_id_and_interval_;
+
+  // The maximum frame staleness that occurred during the tracker's lifetime.
+  base::TimeDelta max_staleness_;
 };
 
 }  // namespace cc

cc/metrics/jank_metrics_unittest.cc

@@ -158,6 +158,21 @@ TEST_F(JankMetricsTest, CompositorAnimationOneJankWithMildFluctuation) {
   EXPECT_THAT(histogram_tester.GetAllSamples(metric),
               testing::ElementsAre(base::Bucket(1, 1)));
 
+  // Stale-frame metrics
+  const char* stale_metric = "Graphics.Smoothness.Stale.CompositorAnimation";
+  const char* maxstale_metric =
+      "Graphics.Smoothness.MaxStale.CompositorAnimation";
+
+  histogram_tester.ExpectTotalCount(stale_metric, 3u);
+  EXPECT_THAT(
+      histogram_tester.GetAllSamples(stale_metric),
+      testing::ElementsAre(base::Bucket(0, 1), base::Bucket(16, 1),
+                           base::Bucket(24, 1) /*caused by +8ms fluctuation*/));
+
+  histogram_tester.ExpectTotalCount(maxstale_metric, 1u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(maxstale_metric),
+              testing::ElementsAre(base::Bucket(24, 1)));
+
   // No reporting for "Main".
   histogram_tester.ExpectTotalCount(invalid_metric, 0u);
 }
@@ -190,6 +205,19 @@ TEST_F(JankMetricsTest, MainThreadAnimationOneJankWithNoUpdate) {
 
   // No jank is reported for "Compositor"
   histogram_tester.ExpectTotalCount(invalid_metric, 0u);
+
+  // Stale-frame metrics
+  const char* stale_metric = "Graphics.Smoothness.Stale.MainThreadAnimation";
+  const char* maxstale_metric =
+      "Graphics.Smoothness.MaxStale.MainThreadAnimation";
+
+  histogram_tester.ExpectTotalCount(stale_metric, 3u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(stale_metric),
+              testing::ElementsAre(base::Bucket(0, 2), base::Bucket(33, 1)));
+
+  histogram_tester.ExpectTotalCount(maxstale_metric, 1u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(maxstale_metric),
+              testing::ElementsAre(base::Bucket(33, 1)));
 }
 
 TEST_F(JankMetricsTest, VideoManyJanksOver300ExpectedFrames) {
@@ -219,6 +247,19 @@ TEST_F(JankMetricsTest, VideoManyJanksOver300ExpectedFrames) {
 
   // No jank is reported for "Main"
   histogram_tester.ExpectTotalCount(invalid_metric, 0u);
+
+  // Stale-frame metrics
+  const char* stale_metric = "Graphics.Smoothness.Stale.Video";
+  const char* maxstale_metric = "Graphics.Smoothness.MaxStale.Video";
+
+  histogram_tester.ExpectTotalCount(stale_metric, 11u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(stale_metric),
+              testing::ElementsAre(base::Bucket(0, 4), base::Bucket(16, 3),
+                                   base::Bucket(33, 2), base::Bucket(50, 2)));
+
+  histogram_tester.ExpectTotalCount(maxstale_metric, 1u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(maxstale_metric),
+              testing::ElementsAre(base::Bucket(50, 1)));
 }
 
 TEST_F(JankMetricsTest, WheelScrollMainThreadNoJanksWithNoUpdates) {
@@ -247,6 +288,18 @@ TEST_F(JankMetricsTest, WheelScrollMainThreadNoJanksWithNoUpdates) {
               testing::ElementsAre(base::Bucket(0, 1)));
 
   histogram_tester.ExpectTotalCount(invalid_metric, 0u);
+
+  // Stale-frame metrics
+  const char* stale_metric = "Graphics.Smoothness.Stale.WheelScroll";
+  const char* maxstale_metric = "Graphics.Smoothness.MaxStale.WheelScroll";
+
+  histogram_tester.ExpectTotalCount(stale_metric, 5u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(stale_metric),
+              testing::ElementsAre(base::Bucket(0, 5)));
+
+  histogram_tester.ExpectTotalCount(maxstale_metric, 1u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(maxstale_metric),
+              testing::ElementsAre(base::Bucket(0, 1)));
 }
 
 TEST_F(JankMetricsTest, WheelScrollCompositorTwoJanksWithLargeFluctuation) {
@@ -278,6 +331,20 @@ TEST_F(JankMetricsTest, WheelScrollCompositorTwoJanksWithLargeFluctuation) {
 
   // No reporting for "Main".
   histogram_tester.ExpectTotalCount(invalid_metric, 0u);
+
+  // Stale-frame metrics
+  const char* stale_metric = "Graphics.Smoothness.Stale.WheelScroll";
+  const char* maxstale_metric = "Graphics.Smoothness.MaxStale.WheelScroll";
+
+  histogram_tester.ExpectTotalCount(stale_metric, 3u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(stale_metric),
+              testing::ElementsAre(
+                  base::Bucket(0, 1), base::Bucket(14, 1), /*-2ms fluctuation*/
+                  base::Bucket(25, 1) /*+7ms - (-2)ms = +9ms fluctuation*/));
+
+  histogram_tester.ExpectTotalCount(maxstale_metric, 1u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(maxstale_metric),
+              testing::ElementsAre(base::Bucket(25, 1)));
 }
 
 TEST_F(JankMetricsTest, TouchScrollCompositorThreadManyJanksLongLatency) {
@@ -291,11 +358,13 @@ TEST_F(JankMetricsTest, TouchScrollCompositorThreadManyJanksLongLatency) {
 
   // There are long delays from submit to presentations.
   SimulateFrameSequence(
-      &jank_reporter, {
+      &jank_reporter,
+      {
           /*submit   */ "abB-c--D--EFgH----------------------",
           /*noupdate */ "---*--------------------------------",
           /*present  */ "----------ab-B--c---D----E-----Fg--H",
-                      });
+      },
+      {{'F', -3.0 /*ms*/}});
   jank_reporter.ReportJankMetrics(120u);
 
   // Expect janks in the 5/120 ~= 4% bucket for "Compositor", and no jank
@@ -308,6 +377,21 @@ TEST_F(JankMetricsTest, TouchScrollCompositorThreadManyJanksLongLatency) {
               testing::ElementsAre(base::Bucket(4, 1)));
 
   histogram_tester.ExpectTotalCount(invalid_metric, 0u);
+
+  // Stale-frame metrics
+  const char* stale_metric = "Graphics.Smoothness.Stale.TouchScroll";
+  const char* maxstale_metric = "Graphics.Smoothness.MaxStale.TouchScroll";
+
+  histogram_tester.ExpectTotalCount(stale_metric, 8u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(stale_metric),
+              testing::ElementsAre(
+                  base::Bucket(0, 1), base::Bucket(3, 1), /* F to g */
+                  base::Bucket(16, 2), base::Bucket(33, 1), base::Bucket(50, 1),
+                  base::Bucket(66, 1), base::Bucket(80, 1) /* E to F */));
+
+  histogram_tester.ExpectTotalCount(maxstale_metric, 1u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(maxstale_metric),
+              testing::ElementsAre(base::Bucket(80, 1)));
 }
 
 // Test if the jank reporter can correctly merge janks from another jank
@@ -342,6 +426,19 @@ TEST_F(JankMetricsTest, RAFMergeJanks) {
               testing::ElementsAre(base::Bucket(6, 1)));
 
   histogram_tester.ExpectTotalCount(invalid_metric, 0u);
+
+  // Stale-frame metrics
+  const char* stale_metric = "Graphics.Smoothness.Stale.RAF";
+  const char* maxstale_metric = "Graphics.Smoothness.MaxStale.RAF";
+
+  histogram_tester.ExpectTotalCount(stale_metric, 12u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(stale_metric),
+              testing::ElementsAre(base::Bucket(0, 6), base::Bucket(16, 4),
+                                   base::Bucket(33, 2)));
+
+  histogram_tester.ExpectTotalCount(maxstale_metric, 1u);
+  EXPECT_THAT(histogram_tester.GetAllSamples(maxstale_metric),
+              testing::ElementsAre(base::Bucket(33, 1)));
 }
 
 // Test if jank reporting is correctly disabled for Custom trackers.
@@ -365,6 +462,10 @@ TEST_F(JankMetricsTest, CustomNotReported) {
   histogram_tester.ExpectTotalCount("Graphics.Smoothness.Jank.Main.Custom", 0u);
   histogram_tester.ExpectTotalCount(
       "Graphics.Smoothness.Jank.Compositor.Custom", 0u);
+
+  // Stale-frame metrics
+  histogram_tester.ExpectTotalCount("Graphics.Smoothness.Stale.Custom", 0u);
+  histogram_tester.ExpectTotalCount("Graphics.Smoothness.MaxStale.Custom", 0u);
 }
 
 }  // namespace cc

tools/metrics/histograms/histograms_xml/histogram_suffixes_list.xml

@@ -17603,6 +17603,7 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   <affected-histogram name="Graphics.Smoothness.FrameSequenceLength"/>
   <affected-histogram name="Graphics.Smoothness.Jank.Compositor"/>
   <affected-histogram name="Graphics.Smoothness.Jank.Main"/>
+  <affected-histogram name="Graphics.Smoothness.MaxStale"/>
   <affected-histogram
       name="Graphics.Smoothness.PercentDroppedFrames.CompositorThread"/>
   <affected-histogram
@@ -17622,6 +17623,7 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
       name="Graphics.Smoothness.PercentMissedDeadlineFrames.MainThread"/>
   <affected-histogram
       name="Graphics.Smoothness.PercentMissedDeadlineFrames.ScrollingThread"/>
+  <affected-histogram name="Graphics.Smoothness.Stale"/>
   <affected-histogram name="SingleThreadedCompositorLatency"/>
   <affected-histogram name="SingleThreadedCompositorLatency.MissedFrame"/>
   <affected-histogram

tools/metrics/histograms/histograms_xml/others/histograms.xml

@@ -5869,6 +5869,29 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="Graphics.Smoothness.MaxStale" units="ms"
+    expires_after="2021-11-01">
+  <owner>sadrul@chromium.org</owner>
+  <owner>mjzhang@chromium.org</owner>
+  <owner>graphics-dev@chromium.org</owner>
+  <summary>
+    Tracks the maximum staleness value for all presentations for a particular
+    sequence of frames (e.g. during scroll, animation, etc.). This is reported
+    in various sub-metrics with suffixes describing the type of the sequence
+    (e.g. TouchScroll etc.).
+
+    Typically, a frame presentation is expected to last at least one vsync
+    cycle, plus any number of additional vsync cycles if no updates are expected
+    duration that time. If the presentation interval is prolonged due to reasons
+    other than listed above, then that prolonged portion will be considered
+    staleness for that frame.
+
+    Note that this metric is reported only when there are sufficient number of
+    frames (&gt;= 100). If there are sequences with fewer frames, then these are
+    aggregated until there are enough frames to produce the metric.
+  </summary>
+</histogram>
+
 <histogram name="Graphics.Smoothness.PercentDroppedFrames" units="%"
     expires_after="2020-12-31">
   <owner>sadrul@chromium.org</owner>
@@ -6027,6 +6050,28 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="Graphics.Smoothness.Stale" units="ms"
+    expires_after="2021-11-01">
+  <owner>sadrul@chromium.org</owner>
+  <owner>mjzhang@chromium.org</owner>
+  <owner>graphics-dev@chromium.org</owner>
+  <summary>
+    Tracks the staleness value for each frame presentation for a particular
+    sequence of frames (e.g. during scroll, animation, etc.). This is reported
+    in various sub-metrics with suffixes describing the type of the sequence
+    (e.g. TouchScroll etc.).
+
+    Typically, a frame presentation is expected to last at least one vsync
+    cycle, plus any number of additional vsync cycles if no updates are expected
+    duration that time. If the presentation interval is prolonged due to reasons
+    other than listed above, then that prolonged portion will be considered
+    staleness.
+
+    Note that the reporting of this metric occurs as soon as a frame is
+    presented, and is not affected by the length of the frame sequence.
+  </summary>
+</histogram>
+
 <histogram name="GraphicsPipeline.ReceivedBeginFrame" units="microseconds"
     expires_after="M85">
   <obsolete>