cc/metrics/average_lag_tracking_manager_unittest.cc

   1 // Copyright 2020 The Chromium Authors
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "cc/metrics/average_lag_tracking_manager.h"
   6
   7 #include <algorithm>
   8 #include <memory>
   9
  10 #include "base/test/metrics/histogram_tester.h"
  11 #include "components/viz/common/frame_timing_details.h"
  12 #include "testing/gmock/include/gmock/gmock.h"
  13 #include "testing/gtest/include/gtest/gtest.h"
  14
  15 namespace cc {
  16 namespace {
  17
  18 using base::Bucket;
  19 using testing::ElementsAre;
  20 using testing::IsEmpty;
  21
  22 // Helper for TimeTicks usage
  23 base::TimeTicks MillisecondsToTimeTicks(int t_ms) {
  24   return base::TimeTicks() + base::Milliseconds(t_ms);
  25 }
  26
  27 // Helper function returning a successful `FrameTimingDetails` for use in
  28 // `DidPresentCompositorFrame()`.
  29 viz::FrameTimingDetails PrepareFrameDetails(base::TimeTicks swap_time,
  30                                             base::TimeTicks presentation_time) {
  31   viz::FrameTimingDetails details;
  32   details.swap_timings.swap_start = swap_time;
  33   details.presentation_feedback.timestamp = presentation_time;
  34   return details;
  35 }
  36
  37 // Helper function returning a failed `FrameTimingDetails` for use in
  38 // `DidPresentCompositorFrame()`.
  39 viz::FrameTimingDetails PrepareFailedFrameDetails() {
  40   viz::FrameTimingDetails details;
  41   details.presentation_feedback = gfx::PresentationFeedback::Failure();
  42   return details;
  43 }
  44
  45 class AverageLagTrackingManagerTest : public testing::Test {
  46  protected:
  47   AverageLagTrackingManagerTest() = default;
  48
  49   // Creates a scroll event each |scroll_rate| (in ms) of |scroll_delta| px.
  50   // Collect events at the expected |gpu_swap_times|.
  51   void SimulateConstantScroll(const std::vector<int>& gpu_swap_times,
  52                               float scroll_delta,
  53                               int scroll_rate) {
  54     if (gpu_swap_times.empty() || gpu_swap_times[0] < scroll_rate)
  55       return;
  56
  57     // Creates 1st frame with scroll begin.
  58     int events_count = gpu_swap_times[0] / scroll_rate;
  59     EventMetricsSet events;
  60     base::TimeTicks event_time = MillisecondsToTimeTicks(scroll_rate);
  61     base::TimeDelta time_to_rwh = base::Milliseconds(1);
  62     events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
  63         ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, event_time,
  64         event_time + time_to_rwh, scroll_delta));
  65     for (int i = 1; i < events_count; i++) {
  66       event_time += base::Milliseconds(scroll_rate);
  67       events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
  68           ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, event_time,
  69           event_time + time_to_rwh, scroll_delta));
  70     }
  71     average_lag_tracking_manager_.CollectScrollEventsFromFrame(0, events);
  72
  73     // Creates remaining frames.
  74     for (size_t frame = 1; frame < gpu_swap_times.size(); frame++) {
  75       int time_delta = gpu_swap_times[frame] - gpu_swap_times[frame - 1];
  76       events_count = time_delta / scroll_rate;
  77       events.main_event_metrics.clear();
  78       for (int i = 0; i < events_count; i++) {
  79         event_time += base::Milliseconds(scroll_rate);
  80         events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
  81             ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, event_time,
  82             event_time + time_to_rwh, scroll_delta));
  83       }
  84       average_lag_tracking_manager_.CollectScrollEventsFromFrame(frame, events);
  85     }
  86   }
  87
  88   // Prepares an `ScrollUpdateEventMetrics` object for a scroll-update event.
  89   std::unique_ptr<ScrollUpdateEventMetrics> PrepareScrollUpdateEvent(
  90       ScrollUpdateEventMetrics::ScrollUpdateType scroll_update_type,
  91       base::TimeTicks event_time,
  92       base::TimeTicks arrived_in_browser_main_timestamp,
  93       float delta) {
  94     const bool kScrollIsNotInertial = false;
  95     return ScrollUpdateEventMetrics::Create(
  96         ui::ET_GESTURE_SCROLL_UPDATE, ui::ScrollInputType::kTouchscreen,
  97         kScrollIsNotInertial, scroll_update_type, delta, event_time,
  98         arrived_in_browser_main_timestamp);
  99   }
 100
 101   AverageLagTrackingManager average_lag_tracking_manager_;
 102 };
 103
 104 // Simulate a simple situation that generates events at every 10ms starting at
 105 // t=15ms and swaps frames at every 10ms, too, starting at t=20ms. Then tests
 106 // that we record one UMA for ScrollUpdate in one second. Tests usage of
 107 // `CollectScrollEventAtFrame()` (1 event per collection).
 108 TEST_F(AverageLagTrackingManagerTest, OneSecondInterval) {
 109   base::HistogramTester histogram_tester;
 110
 111   const float scroll_delta = 10.0f;
 112
 113   base::TimeTicks event_time = MillisecondsToTimeTicks(5);
 114   base::TimeTicks arrived_in_browser_main_timestamp =
 115       MillisecondsToTimeTicks(7);
 116   base::TimeTicks gpu_swap_time = MillisecondsToTimeTicks(10);
 117   base::TimeTicks presentation_time = MillisecondsToTimeTicks(13);
 118   int frame_id = 1;
 119
 120   // ScrollBegin
 121   event_time += base::Milliseconds(10);                         // 15ms
 122   arrived_in_browser_main_timestamp += base::Milliseconds(10);  // 17ms
 123   gpu_swap_time += base::Milliseconds(10);                      // 20ms
 124   presentation_time += base::Milliseconds(10);                  // 23ms
 125   EventMetricsSet events;
 126   events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
 127       ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, event_time,
 128       arrived_in_browser_main_timestamp, scroll_delta));
 129   average_lag_tracking_manager_.CollectScrollEventsFromFrame(frame_id, events);
 130   average_lag_tracking_manager_.DidPresentCompositorFrame(
 131       frame_id, PrepareFrameDetails(gpu_swap_time, presentation_time));
 132
 133   // Send 101 ScrollUpdate events to verify that there is 1 AverageLag recorded
 134   // per 1 second.
 135   const int kUpdates = 101;
 136   for (int i = 0; i < kUpdates; i++) {
 137     event_time += base::Milliseconds(10);
 138     arrived_in_browser_main_timestamp += base::Milliseconds(10);
 139     gpu_swap_time += base::Milliseconds(10);
 140     presentation_time += base::Milliseconds(10);
 141     // First 50 has positive delta, others negative delta.
 142     const int sign = (i < kUpdates / 2) ? 1 : -1;
 143
 144     events.main_event_metrics.clear();
 145     events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
 146         ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, event_time,
 147         arrived_in_browser_main_timestamp, sign * scroll_delta));
 148     average_lag_tracking_manager_.CollectScrollEventsFromFrame(frame_id,
 149                                                                events);
 150     average_lag_tracking_manager_.DidPresentCompositorFrame(
 151         frame_id, PrepareFrameDetails(gpu_swap_time, presentation_time));
 152   }
 153
 154   // ScrollBegin report time is at 20ms, so the next ScrollUpdate report time is
 155   // at 1020ms. The last event_time that finish this report should be later than
 156   // 1020ms.
 157   EXPECT_EQ(event_time, MillisecondsToTimeTicks(1025));
 158   EXPECT_EQ(arrived_in_browser_main_timestamp, MillisecondsToTimeTicks(1027));
 159   EXPECT_EQ(gpu_swap_time, MillisecondsToTimeTicks(1030));
 160   EXPECT_EQ(presentation_time, MillisecondsToTimeTicks(1033));
 161
 162   // Using the presentation time (25ms) instead of gpu swap (20ms) the expected
 163   // finger position is delta = 16px. Then (0.5*(10px+18px)*10ms)/10ms = 14px.
 164   histogram_tester.ExpectBucketCount(
 165       "Event.Latency.ScrollBegin.Touch.AverageLagPresentation", 14, 1);
 166
 167   // As the presentation times are at 80% of the gap between 2 scroll events,
 168   // the Lag Area between 2 frames is defined by the trapezoids: (time=event-2,
 169   // delta=8px), (time=event, delta=10px), (time=event+8, delta=18). This makes
 170   // 99 trapezoids with an area of 0.5*2*(8+10) + 0.5*8*(10+18) = 130px.
 171   // For scroll up/down frame, the Lag at the last frame swap is 2px, and Lag
 172   // at this frame swap is 12px. For the one changing direction, the Lag is
 173   // from 8 to 10 and down to 8 again. So total LagArea is 99 * 130, plus
 174   // 0.5*8*(10+2) + 0.5*2*(8+10) = 66. This makes 12,936, Caled by 1 sec.
 175   histogram_tester.ExpectBucketCount(
 176       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation", 12.936, 1);
 177   histogram_tester.ExpectBucketCount(
 178       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation."
 179       "PredictionPositive",
 180       0, 1);
 181   histogram_tester.ExpectTotalCount(
 182       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation."
 183       "PredictionNegative",
 184       0);
 185 }
 186
 187 // This test creates 3 frames in order to check the submission of ScrollBegin
 188 // and ScrollUpdate events sent using `CollectScrollEventsAtFrame()` (multiple
 189 // events per collection)
 190 TEST_F(AverageLagTrackingManagerTest, MultipleEventsInSameFrame) {
 191   base::HistogramTester histogram_tester;
 192
 193   std::vector<int> gpu_swap_times = {400, 1400, 1600};
 194   std::vector<int> presentation_times = {500, 1500, 1700};
 195   SimulateConstantScroll(gpu_swap_times, 10, 100);
 196   for (size_t frame = 0; frame < gpu_swap_times.size(); frame++) {
 197     average_lag_tracking_manager_.DidPresentCompositorFrame(
 198         frame, PrepareFrameDetails(
 199                    MillisecondsToTimeTicks(gpu_swap_times[frame]),
 200                    MillisecondsToTimeTicks(presentation_times[frame])));
 201   }
 202
 203   // As the first frame is the ScrollBegin frame, the average lag is, using the
 204   // presentation time, 0.5*(10 + 50) * 40 / 40 = 30.
 205   histogram_tester.ExpectBucketCount(
 206       "Event.Latency.ScrollBegin.Touch.AverageLagPresentation", 30, 1);
 207
 208   // Only the ScrollUpdate events from frame 2 are sent (as the frame 3 is
 209   // waiting for the next frame for sumission).
 210   // As there is a scroll update right at the same time as the frame submission,
 211   // using presentation time, frame 2 starts with 10 lag at 0.5s and finishes
 212   // with 110 at 1.5, thus: 0.5 * (10 + 110) = 60.
 213   histogram_tester.ExpectBucketCount(
 214       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation", 60, 1);
 215 }
 216
 217 // Tests that if failed presentations arrive out-of-order, they don't mark
 218 // previous pending frames as failed since they can still end up in a
 219 // successful presentation.
 220 TEST_F(AverageLagTrackingManagerTest, OutOfOrderPresentationFeedback) {
 221   base::HistogramTester histogram_tester;
 222
 223   const float scroll_delta = 100.0f;
 224
 225   std::vector<int> event_times = {500, 1500, 2500, 3500};
 226   std::vector<int> arrived_in_browser_main_timestamps = {700, 1700, 2700, 3700};
 227   std::vector<int> gpu_swap_times = {900, 1900, 2900, 3900};
 228   std::vector<int> presentation_times = {1000, 2000, 3000, 4000};
 229
 230   // Create a scroll-begin event. Submit frame 0 with updates from scroll-begin
 231   // event and present it successfully. No AverageLag metrics should be reported
 232   // yet.
 233   EventMetricsSet events;
 234   events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
 235       ScrollUpdateEventMetrics::ScrollUpdateType::kStarted,
 236       MillisecondsToTimeTicks(event_times[0]),
 237       MillisecondsToTimeTicks(arrived_in_browser_main_timestamps[0]),
 238       scroll_delta));
 239   average_lag_tracking_manager_.CollectScrollEventsFromFrame(0, events);
 240   average_lag_tracking_manager_.DidPresentCompositorFrame(
 241       0, PrepareFrameDetails(MillisecondsToTimeTicks(gpu_swap_times[0]),
 242                              MillisecondsToTimeTicks(presentation_times[0])));
 243   histogram_tester.ExpectTotalCount(
 244       "Event.Latency.ScrollBegin.Touch.AverageLagPresentation", 0);
 245   histogram_tester.ExpectTotalCount(
 246       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation", 0);
 247
 248   // Create the first scroll-update event. Submit frame 1 with updates from the
 249   // first scroll-update event, but don't present it yet. No AverageLag metrics
 250   // should be recorded.
 251   events.main_event_metrics.clear();
 252   events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
 253       ScrollUpdateEventMetrics::ScrollUpdateType::kContinued,
 254       MillisecondsToTimeTicks(event_times[1]),
 255       MillisecondsToTimeTicks(arrived_in_browser_main_timestamps[1]),
 256       scroll_delta));
 257   average_lag_tracking_manager_.CollectScrollEventsFromFrame(1, events);
 258   histogram_tester.ExpectTotalCount(
 259       "Event.Latency.ScrollBegin.Touch.AverageLagPresentation", 0);
 260   histogram_tester.ExpectTotalCount(
 261       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation", 0);
 262
 263   // Create the second scroll-update event. Submit frame 2 with updates from the
 264   // second scroll-update event, but fail to present it. No AverageLag metrics
 265   // should be reported.
 266   events.main_event_metrics.clear();
 267   events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
 268       ScrollUpdateEventMetrics::ScrollUpdateType::kContinued,
 269       MillisecondsToTimeTicks(event_times[2]),
 270       MillisecondsToTimeTicks(arrived_in_browser_main_timestamps[2]),
 271       scroll_delta));
 272   average_lag_tracking_manager_.CollectScrollEventsFromFrame(2, events);
 273   average_lag_tracking_manager_.DidPresentCompositorFrame(
 274       2, PrepareFailedFrameDetails());
 275   histogram_tester.ExpectTotalCount(
 276       "Event.Latency.ScrollBegin.Touch.AverageLagPresentation", 0);
 277   histogram_tester.ExpectTotalCount(
 278       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation", 0);
 279
 280   // Now present frame 1 successfully. This should report AverageLag metrics for
 281   // scroll-begin event of frame 0.
 282   average_lag_tracking_manager_.DidPresentCompositorFrame(
 283       1, PrepareFrameDetails(MillisecondsToTimeTicks(gpu_swap_times[1]),
 284                              MillisecondsToTimeTicks(presentation_times[1])));
 285   histogram_tester.ExpectBucketCount(
 286       "Event.Latency.ScrollBegin.Touch.AverageLagPresentation", 125, 1);
 287   histogram_tester.ExpectTotalCount(
 288       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation", 0);
 289
 290   // Create the third scroll-update event. Submit frame 3 with updates from the
 291   // second scroll-update (which failed to be presented in frame 2) and the
 292   // third scroll-update events. Since the failure of frame 2 should not have
 293   // affected events from frame 1, AverageLag metrics for scroll-update event of
 294   // frame 1 should be reported.
 295   events.main_event_metrics.push_back(PrepareScrollUpdateEvent(
 296       ScrollUpdateEventMetrics::ScrollUpdateType::kContinued,
 297       MillisecondsToTimeTicks(event_times[3]),
 298       MillisecondsToTimeTicks(arrived_in_browser_main_timestamps[3]),
 299       scroll_delta));
 300   average_lag_tracking_manager_.CollectScrollEventsFromFrame(3, events);
 301   average_lag_tracking_manager_.DidPresentCompositorFrame(
 302       3, PrepareFrameDetails(MillisecondsToTimeTicks(gpu_swap_times[3]),
 303                              MillisecondsToTimeTicks(presentation_times[3])));
 304   histogram_tester.ExpectBucketCount(
 305       "Event.Latency.ScrollBegin.Touch.AverageLagPresentation", 125, 1);
 306   histogram_tester.ExpectBucketCount(
 307       "Event.Latency.ScrollUpdate.Touch.AverageLagPresentation", 100, 1);
 308 }
 309
 310 }  // namespace
 311 }  // namespace cc