cc/metrics/compositor_timing_history_unittest.cc

   1 // Copyright 2015 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/compositor_timing_history.h"
   6
   7 #include "base/logging.h"
   8 #include "base/memory/raw_ptr.h"
   9 #include "base/test/scoped_feature_list.h"
  10 #include "base/time/time.h"
  11 #include "cc/base/features.h"
  12 #include "cc/debug/rendering_stats_instrumentation.h"
  13 #include "cc/metrics/dropped_frame_counter.h"
  14 #include "testing/gtest/include/gtest/gtest.h"
  15
  16 namespace cc {
  17 namespace {
  18
  19 class CompositorTimingHistoryTest;
  20
  21 class TestCompositorTimingHistory : public CompositorTimingHistory {
  22  public:
  23   TestCompositorTimingHistory(CompositorTimingHistoryTest* test,
  24                               RenderingStatsInstrumentation* rendering_stats)
  25       : CompositorTimingHistory(false, RENDERER_UMA, rendering_stats),
  26         test_(test) {}
  27
  28   TestCompositorTimingHistory(const TestCompositorTimingHistory&) = delete;
  29   TestCompositorTimingHistory& operator=(const TestCompositorTimingHistory&) =
  30       delete;
  31
  32   const RollingTimeDeltaHistory& bmf_start_to_ready_to_commit_critical_history()
  33       const {
  34     return bmf_start_to_ready_to_commit_critical_history_;
  35   }
  36   const RollingTimeDeltaHistory&
  37   bmf_start_to_ready_to_commit_not_critical_history() const {
  38     return bmf_start_to_ready_to_commit_not_critical_history_;
  39   }
  40   const RollingTimeDeltaHistory& bmf_queue_to_activate_critical_history()
  41       const {
  42     return bmf_queue_to_activate_critical_history_;
  43   }
  44
  45  protected:
  46   base::TimeTicks Now() const override;
  47
  48   raw_ptr<CompositorTimingHistoryTest> test_;
  49 };
  50
  51 class CompositorTimingHistoryTest : public testing::Test {
  52  public:
  53   CompositorTimingHistoryTest()
  54       : feature_list(features::kDurationEstimatesInCompositorTimingHistory),
  55         rendering_stats_(RenderingStatsInstrumentation::Create()),
  56         timing_history_(this, rendering_stats_.get()) {
  57     AdvanceNowBy(base::Milliseconds(1));
  58     timing_history_.SetRecordingEnabled(true);
  59   }
  60
  61   void AdvanceNowBy(base::TimeDelta delta) { now_ += delta; }
  62
  63   base::TimeTicks Now() { return now_; }
  64
  65  protected:
  66   base::test::ScopedFeatureList feature_list;
  67   std::unique_ptr<RenderingStatsInstrumentation> rendering_stats_;
  68   TestCompositorTimingHistory timing_history_;
  69   base::TimeTicks now_;
  70   uint64_t sequence_number = 0;
  71   DroppedFrameCounter dropped_counter;
  72
  73   viz::BeginFrameArgs GetFakeBeginFrameArg(bool on_critical_path = true) {
  74     viz::BeginFrameArgs args = viz::BeginFrameArgs();
  75     const uint64_t kSourceId = 1;
  76     args.frame_id = {kSourceId, ++sequence_number};
  77     args.frame_time = Now();
  78     args.on_critical_path = on_critical_path;
  79     return args;
  80   }
  81 };
  82
  83 base::TimeTicks TestCompositorTimingHistory::Now() const {
  84   return test_->Now();
  85 }
  86
  87 TEST_F(CompositorTimingHistoryTest, AllSequential_Commit) {
  88   base::TimeDelta one_second = base::Seconds(1);
  89
  90   // Critical BeginMainFrames are faster than non critical ones,
  91   // as expected.
  92   base::TimeDelta begin_main_frame_queue_duration = base::Milliseconds(1);
  93   base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
  94       base::Milliseconds(1);
  95   base::TimeDelta prepare_tiles_duration = base::Milliseconds(2);
  96   base::TimeDelta prepare_tiles_end_to_ready_to_activate_duration =
  97       base::Milliseconds(1);
  98   base::TimeDelta commit_to_ready_to_activate_duration = base::Milliseconds(3);
  99   base::TimeDelta commit_duration = base::Milliseconds(1);
 100   base::TimeDelta activate_duration = base::Milliseconds(4);
 101   base::TimeDelta draw_duration = base::Milliseconds(5);
 102
 103   timing_history_.WillBeginMainFrame(GetFakeBeginFrameArg());
 104   AdvanceNowBy(begin_main_frame_queue_duration);
 105   timing_history_.BeginMainFrameStarted(Now());
 106   AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 107   timing_history_.NotifyReadyToCommit();
 108   timing_history_.WillCommit();
 109   AdvanceNowBy(commit_duration);
 110   timing_history_.DidCommit();
 111   timing_history_.WillPrepareTiles();
 112   AdvanceNowBy(prepare_tiles_duration);
 113   timing_history_.DidPrepareTiles();
 114   AdvanceNowBy(prepare_tiles_end_to_ready_to_activate_duration);
 115   timing_history_.ReadyToActivate();
 116   // Do not count idle time between notification and actual activation.
 117   AdvanceNowBy(one_second);
 118   timing_history_.WillActivate();
 119   AdvanceNowBy(activate_duration);
 120   timing_history_.DidActivate();
 121   // Do not count idle time between activate and draw.
 122   AdvanceNowBy(one_second);
 123   timing_history_.WillDraw();
 124   AdvanceNowBy(draw_duration);
 125   timing_history_.DidDraw(true, false);
 126
 127   EXPECT_EQ(begin_main_frame_queue_duration,
 128             timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
 129   EXPECT_EQ(begin_main_frame_queue_duration,
 130             timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
 131
 132   EXPECT_EQ(
 133       begin_main_frame_start_to_ready_to_commit_duration,
 134       timing_history_.BeginMainFrameStartToReadyToCommitDurationEstimate());
 135   EXPECT_EQ(commit_duration, timing_history_.CommitDurationEstimate());
 136   EXPECT_EQ(commit_to_ready_to_activate_duration,
 137             timing_history_.CommitToReadyToActivateDurationEstimate());
 138   EXPECT_EQ(prepare_tiles_duration,
 139             timing_history_.PrepareTilesDurationEstimate());
 140   EXPECT_EQ(activate_duration, timing_history_.ActivateDurationEstimate());
 141   EXPECT_EQ(draw_duration, timing_history_.DrawDurationEstimate());
 142 }
 143
 144 TEST_F(CompositorTimingHistoryTest, AllSequential_BeginMainFrameAborted) {
 145   base::TimeDelta one_second = base::Seconds(1);
 146
 147   base::TimeDelta begin_main_frame_queue_duration = base::Milliseconds(1);
 148   base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
 149       base::Milliseconds(1);
 150   base::TimeDelta prepare_tiles_duration = base::Milliseconds(2);
 151   base::TimeDelta prepare_tiles_end_to_ready_to_activate_duration =
 152       base::Milliseconds(1);
 153   base::TimeDelta activate_duration = base::Milliseconds(4);
 154   base::TimeDelta draw_duration = base::Milliseconds(5);
 155
 156   viz::BeginFrameArgs args_ = GetFakeBeginFrameArg(false);
 157   timing_history_.WillBeginMainFrame(args_);
 158   AdvanceNowBy(begin_main_frame_queue_duration);
 159   timing_history_.BeginMainFrameStarted(Now());
 160   AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 161   // BeginMainFrameAborted counts as a commit complete.
 162   timing_history_.BeginMainFrameAborted();
 163   timing_history_.WillPrepareTiles();
 164   AdvanceNowBy(prepare_tiles_duration);
 165   timing_history_.DidPrepareTiles();
 166   AdvanceNowBy(prepare_tiles_end_to_ready_to_activate_duration);
 167   // Do not count idle time between notification and actual activation.
 168   AdvanceNowBy(one_second);
 169   timing_history_.WillActivate();
 170   AdvanceNowBy(activate_duration);
 171   timing_history_.DidActivate();
 172   // Do not count idle time between activate and draw.
 173   AdvanceNowBy(one_second);
 174   timing_history_.WillDraw();
 175   AdvanceNowBy(draw_duration);
 176   timing_history_.DidDraw(false, false);
 177
 178   EXPECT_EQ(base::TimeDelta(),
 179             timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
 180   EXPECT_EQ(begin_main_frame_queue_duration,
 181             timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
 182
 183   EXPECT_EQ(prepare_tiles_duration,
 184             timing_history_.PrepareTilesDurationEstimate());
 185   EXPECT_EQ(activate_duration, timing_history_.ActivateDurationEstimate());
 186   EXPECT_EQ(draw_duration, timing_history_.DrawDurationEstimate());
 187 }
 188
 189 TEST_F(CompositorTimingHistoryTest, BeginMainFrame_CriticalFaster) {
 190   // Critical BeginMainFrames are faster than non critical ones.
 191   base::TimeDelta begin_main_frame_queue_duration_critical =
 192       base::Milliseconds(1);
 193   base::TimeDelta begin_main_frame_queue_duration_not_critical =
 194       base::Milliseconds(2);
 195   base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
 196       base::Milliseconds(1);
 197
 198   viz::BeginFrameArgs args_ = GetFakeBeginFrameArg();
 199   timing_history_.WillBeginMainFrame(args_);
 200   AdvanceNowBy(begin_main_frame_queue_duration_critical);
 201   timing_history_.BeginMainFrameStarted(Now());
 202   AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 203   timing_history_.BeginMainFrameAborted();
 204
 205   args_ = GetFakeBeginFrameArg(false);
 206   timing_history_.WillBeginMainFrame(args_);
 207   AdvanceNowBy(begin_main_frame_queue_duration_not_critical);
 208   timing_history_.BeginMainFrameStarted(Now());
 209   AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 210   timing_history_.BeginMainFrameAborted();
 211
 212   // Since the critical BeginMainFrames are faster than non critical ones,
 213   // the expectations are straightforward.
 214   EXPECT_EQ(begin_main_frame_queue_duration_critical,
 215             timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
 216   EXPECT_EQ(begin_main_frame_queue_duration_not_critical,
 217             timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
 218 }
 219
 220 TEST_F(CompositorTimingHistoryTest, BeginMainFrames_OldCriticalSlower) {
 221   // Critical BeginMainFrames are slower than non critical ones,
 222   // which is unexpected, but could occur if one type of frame
 223   // hasn't been sent for a significant amount of time.
 224   base::TimeDelta begin_main_frame_queue_duration_critical =
 225       base::Milliseconds(2);
 226   base::TimeDelta begin_main_frame_queue_duration_not_critical =
 227       base::Milliseconds(1);
 228   base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
 229       base::Milliseconds(1);
 230
 231   // A single critical frame that is slow.
 232   viz::BeginFrameArgs args_ = GetFakeBeginFrameArg();
 233   timing_history_.WillBeginMainFrame(args_);
 234   AdvanceNowBy(begin_main_frame_queue_duration_critical);
 235   timing_history_.BeginMainFrameStarted(Now());
 236   AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 237   // BeginMainFrameAborted counts as a commit complete.
 238   timing_history_.BeginMainFrameAborted();
 239
 240   // A bunch of faster non critical frames that are newer.
 241   for (int i = 0; i < 100; i++) {
 242     args_ = GetFakeBeginFrameArg(false);
 243     timing_history_.WillBeginMainFrame(args_);
 244     AdvanceNowBy(begin_main_frame_queue_duration_not_critical);
 245     timing_history_.BeginMainFrameStarted(Now());
 246     AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 247     // BeginMainFrameAborted counts as a commit complete.
 248     timing_history_.BeginMainFrameAborted();
 249   }
 250
 251   // Recent fast non critical BeginMainFrames should result in the
 252   // critical estimate also being fast.
 253   EXPECT_EQ(begin_main_frame_queue_duration_not_critical,
 254             timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
 255   EXPECT_EQ(begin_main_frame_queue_duration_not_critical,
 256             timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
 257 }
 258
 259 TEST_F(CompositorTimingHistoryTest, BeginMainFrames_NewCriticalSlower) {
 260   // Critical BeginMainFrames are slower than non critical ones,
 261   // which is unexpected, but could occur if one type of frame
 262   // hasn't been sent for a significant amount of time.
 263   base::TimeDelta begin_main_frame_queue_duration_critical =
 264       base::Milliseconds(2);
 265   base::TimeDelta begin_main_frame_queue_duration_not_critical =
 266       base::Milliseconds(1);
 267   base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
 268       base::Milliseconds(1);
 269
 270   // A single non critical frame that is fast.
 271   viz::BeginFrameArgs args_ = GetFakeBeginFrameArg(false);
 272   timing_history_.WillBeginMainFrame(args_);
 273   AdvanceNowBy(begin_main_frame_queue_duration_not_critical);
 274   timing_history_.BeginMainFrameStarted(Now());
 275   AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 276   timing_history_.BeginMainFrameAborted();
 277
 278   // A bunch of slower critical frames that are newer.
 279   for (int i = 0; i < 100; i++) {
 280     args_ = GetFakeBeginFrameArg();
 281     timing_history_.WillBeginMainFrame(args_);
 282     AdvanceNowBy(begin_main_frame_queue_duration_critical);
 283     timing_history_.BeginMainFrameStarted(Now());
 284     AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
 285     timing_history_.BeginMainFrameAborted();
 286   }
 287
 288   // Recent slow critical BeginMainFrames should result in the
 289   // not critical estimate also being slow.
 290   EXPECT_EQ(begin_main_frame_queue_duration_critical,
 291             timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
 292   EXPECT_EQ(begin_main_frame_queue_duration_critical,
 293             timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
 294 }
 295
 296 TEST_F(CompositorTimingHistoryTest, BeginMainFrameToActivateDuration) {
 297   viz::BeginFrameArgs args_ = GetFakeBeginFrameArg(true);
 298   timing_history_.WillBeginMainFrame(args_);
 299   AdvanceNowBy(base::Milliseconds(1));
 300   timing_history_.BeginMainFrameStarted(Now());
 301   AdvanceNowBy(base::Milliseconds(2));
 302   timing_history_.NotifyReadyToCommit();
 303   AdvanceNowBy(base::Milliseconds(3));
 304   timing_history_.WillCommit();
 305   AdvanceNowBy(base::Milliseconds(4));
 306   timing_history_.DidCommit();
 307   AdvanceNowBy(base::Milliseconds(5));
 308   timing_history_.ReadyToActivate();
 309   AdvanceNowBy(base::Milliseconds(6));
 310   timing_history_.WillActivate();
 311   AdvanceNowBy(base::Milliseconds(7));
 312   timing_history_.DidActivate();
 313   EXPECT_EQ(
 314       1u,
 315       timing_history_.bmf_queue_to_activate_critical_history().sample_count());
 316   EXPECT_EQ(
 317       base::Milliseconds(1 + 2 + 3 + 4 + 5 + 6 + 7),
 318       timing_history_.bmf_queue_to_activate_critical_history().Percentile(0.));
 319 }
 320
 321 TEST_F(CompositorTimingHistoryTest, OnCriticalPath) {
 322   viz::BeginFrameArgs bmf_args = GetFakeBeginFrameArg(true);
 323   timing_history_.WillBeginMainFrame(bmf_args);
 324   AdvanceNowBy(base::Milliseconds(1));
 325   timing_history_.BeginMainFrameStarted(Now());
 326   AdvanceNowBy(base::Milliseconds(1));
 327   timing_history_.NotifyReadyToCommit();
 328   AdvanceNowBy(base::Milliseconds(1));
 329   timing_history_.WillCommit();
 330   AdvanceNowBy(base::Milliseconds(1));
 331   timing_history_.DidCommit();
 332   AdvanceNowBy(base::Milliseconds(1));
 333   timing_history_.ReadyToActivate();
 334   AdvanceNowBy(base::Milliseconds(1));
 335
 336   // The previous frame should still be treated as on_critical_path
 337   bmf_args = GetFakeBeginFrameArg(false);
 338   timing_history_.WillBeginMainFrame(bmf_args);
 339
 340   timing_history_.WillActivate();
 341   AdvanceNowBy(base::Milliseconds(1));
 342   timing_history_.DidActivate();
 343
 344   EXPECT_EQ(1u, timing_history_.bmf_start_to_ready_to_commit_critical_history()
 345                     .sample_count());
 346   EXPECT_EQ(base::Milliseconds(2),
 347             timing_history_.bmf_start_to_ready_to_commit_critical_history()
 348                 .Percentile(0.));
 349   EXPECT_EQ(0u,
 350             timing_history_.bmf_start_to_ready_to_commit_not_critical_history()
 351                 .sample_count());
 352   EXPECT_EQ(
 353       1u,
 354       timing_history_.bmf_queue_to_activate_critical_history().sample_count());
 355   EXPECT_EQ(
 356       base::Milliseconds(7),
 357       timing_history_.bmf_queue_to_activate_critical_history().Percentile(0.));
 358
 359   timing_history_.BeginMainFrameStarted(Now());
 360   AdvanceNowBy(base::Milliseconds(1));
 361   timing_history_.NotifyReadyToCommit();
 362   AdvanceNowBy(base::Milliseconds(1));
 363   timing_history_.WillCommit();
 364   AdvanceNowBy(base::Milliseconds(1));
 365   timing_history_.DidCommit();
 366   AdvanceNowBy(base::Milliseconds(1));
 367   timing_history_.ReadyToActivate();
 368   AdvanceNowBy(base::Milliseconds(1));
 369   timing_history_.WillActivate();
 370   AdvanceNowBy(base::Milliseconds(1));
 371
 372   // The previous frame should still be treated as not on_critical_path
 373   bmf_args = GetFakeBeginFrameArg(true);
 374   timing_history_.WillBeginMainFrame(bmf_args);
 375   timing_history_.DidActivate();
 376
 377   EXPECT_EQ(1u, timing_history_.bmf_start_to_ready_to_commit_critical_history()
 378                     .sample_count());
 379   EXPECT_EQ(1u,
 380             timing_history_.bmf_start_to_ready_to_commit_not_critical_history()
 381                 .sample_count());
 382   EXPECT_EQ(
 383       1u,
 384       timing_history_.bmf_queue_to_activate_critical_history().sample_count());
 385 }
 386
 387 TEST_F(CompositorTimingHistoryTest, BeginMainFrameQueueDuration) {
 388   viz::BeginFrameArgs args_ = GetFakeBeginFrameArg(true);
 389   timing_history_.WillBeginMainFrame(args_);
 390   AdvanceNowBy(base::Milliseconds(1));
 391   timing_history_.BeginMainFrameStarted(Now());
 392   AdvanceNowBy(base::Milliseconds(2));
 393   timing_history_.NotifyReadyToCommit();
 394   AdvanceNowBy(base::Milliseconds(3));
 395   timing_history_.WillCommit();
 396   AdvanceNowBy(base::Milliseconds(4));
 397   timing_history_.DidCommit();
 398   AdvanceNowBy(base::Milliseconds(5));
 399   timing_history_.ReadyToActivate();
 400   AdvanceNowBy(base::Milliseconds(6));
 401   timing_history_.WillBeginMainFrame(args_);
 402   AdvanceNowBy(base::Milliseconds(7));
 403   timing_history_.BeginMainFrameStarted(Now());
 404   AdvanceNowBy(base::Milliseconds(8));
 405   timing_history_.BeginMainFrameAborted();
 406   AdvanceNowBy(base::Milliseconds(9));
 407   timing_history_.WillActivate();
 408   AdvanceNowBy(base::Milliseconds(10));
 409   timing_history_.DidActivate();
 410   EXPECT_EQ(
 411       1u,
 412       timing_history_.bmf_queue_to_activate_critical_history().sample_count());
 413   // The bmf queueing duration should be 1ms, not the 7ms for the aborted frame.
 414   EXPECT_EQ(
 415       base::Milliseconds(1 + 2 + 3 + 4 + 5 + 6 + 7 + 8 + 9 + 10),
 416       timing_history_.bmf_queue_to_activate_critical_history().Percentile(0.));
 417 }
 418
 419 TEST_F(CompositorTimingHistoryTest, MainFrameBeforeCommit) {
 420   // Start first BMF
 421   timing_history_.WillBeginMainFrame(GetFakeBeginFrameArg(true));
 422   AdvanceNowBy(base::Milliseconds(1));
 423   timing_history_.BeginMainFrameStarted(Now());
 424   AdvanceNowBy(base::Milliseconds(1));
 425   timing_history_.NotifyReadyToCommit();
 426   AdvanceNowBy(base::Milliseconds(1));
 427
 428   // Start second BMF
 429   timing_history_.WillBeginMainFrame(GetFakeBeginFrameArg(false));
 430   AdvanceNowBy(base::Milliseconds(1));
 431
 432   // Advance first BMF
 433   timing_history_.WillCommit();
 434   AdvanceNowBy(base::Milliseconds(1));
 435   timing_history_.DidCommit();
 436   AdvanceNowBy(base::Milliseconds(1));
 437
 438   // Second BMF ready to commit
 439   timing_history_.BeginMainFrameStarted(Now());
 440   AdvanceNowBy(base::Milliseconds(1));
 441   timing_history_.NotifyReadyToCommit();
 442   AdvanceNowBy(base::Milliseconds(1));
 443
 444   // Start third BMF and abort it
 445   timing_history_.WillBeginMainFrame(GetFakeBeginFrameArg(false));
 446   AdvanceNowBy(base::Milliseconds(1));
 447   timing_history_.BeginMainFrameAborted();
 448   AdvanceNowBy(base::Milliseconds(1));
 449
 450   // Activate first tree
 451   timing_history_.ReadyToActivate();
 452   AdvanceNowBy(base::Milliseconds(1));
 453   timing_history_.WillActivate();
 454   AdvanceNowBy(base::Milliseconds(1));
 455   timing_history_.DidActivate();
 456   AdvanceNowBy(base::Milliseconds(1));
 457
 458   // Commit and activate second tree
 459   timing_history_.WillCommit();
 460   AdvanceNowBy(base::Milliseconds(1));
 461   timing_history_.DidCommit();
 462   AdvanceNowBy(base::Milliseconds(1));
 463   timing_history_.ReadyToActivate();
 464   AdvanceNowBy(base::Milliseconds(1));
 465   timing_history_.WillActivate();
 466   AdvanceNowBy(base::Milliseconds(1));
 467   timing_history_.DidActivate();
 468   AdvanceNowBy(base::Milliseconds(1));
 469
 470   // Should have one critical and one not-critical frame sample.
 471   EXPECT_EQ(
 472       1u,
 473       timing_history_.bmf_queue_to_activate_critical_history().sample_count());
 474   EXPECT_EQ(1u, timing_history_.bmf_start_to_ready_to_commit_critical_history()
 475                     .sample_count());
 476   EXPECT_EQ(1u,
 477             timing_history_.bmf_start_to_ready_to_commit_not_critical_history()
 478                 .sample_count());
 479 }
 480
 481 }  // namespace
 482 }  // namespace cc