cc/metrics/compositor_timing_history.cc

   1 // Copyright 2014 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 <stddef.h>
   8 #include <stdint.h>
   9
  10 #include <algorithm>
  11 #include <utility>
  12 #include <vector>
  13
  14 #include "base/memory/ptr_util.h"
  15 #include "base/metrics/field_trial_params.h"
  16 #include "base/metrics/histogram_macros.h"
  17 #include "base/notreached.h"
  18 #include "base/trace_event/trace_event.h"
  19 #include "cc/base/features.h"
  20 #include "cc/debug/rendering_stats_instrumentation.h"
  21
  22 namespace cc {
  23
  24 class CompositorTimingHistory::UMAReporter {
  25  public:
  26   virtual ~UMAReporter() = default;
  27
  28   // Throughput measurements
  29   virtual void AddDrawInterval(base::TimeDelta interval) = 0;
  30
  31   // Latency measurements
  32   virtual void AddBeginImplFrameLatency(base::TimeDelta delta) = 0;
  33   virtual void AddDrawDuration(base::TimeDelta duration) = 0;
  34
  35   // crbug.com/758439: the following functions are used to report timing in
  36   // certain conditions targeting blink / compositor animations.
  37   // Only the renderer would get the meaningful data.
  38   virtual void AddDrawIntervalWithCustomPropertyAnimations(
  39       base::TimeDelta duration) = 0;
  40
  41   virtual void AddImplFrameDeadlineType(
  42       CompositorTimingHistory::DeadlineMode deadline_mode) = 0;
  43 };
  44
  45 namespace {
  46
  47 // Used to generate a unique id when emitting the "Long Draw Interval" trace
  48 // event.
  49 int g_num_long_draw_intervals = 0;
  50
  51 // The threshold to emit a trace event is the 99th percentile
  52 // of the histogram on Windows Stable as of Feb 26th, 2020.
  53 constexpr base::TimeDelta kDrawIntervalTraceThreshold =
  54     base::Microseconds(34478);
  55
  56 // Using the 90th percentile will disable latency recovery
  57 // if we are missing the deadline approximately ~6 times per
  58 // second.
  59 // TODO(brianderson): Fine tune the percentiles below.
  60 const size_t kDurationHistorySize = 60;
  61 const double kBeginMainFrameQueueDurationEstimationPercentile = 90.0;
  62 const double kBeginMainFrameQueueDurationCriticalEstimationPercentile = 90.0;
  63 const double kBeginMainFrameQueueDurationNotCriticalEstimationPercentile = 90.0;
  64 const double kBeginMainFrameStartToReadyToCommitEstimationPercentile = 90.0;
  65 const double kCommitEstimatePercentile = 90.0;
  66 const double kCommitToReadyToActivateEstimationPercentile = 90.0;
  67 const double kPrepareTilesEstimationPercentile = 90.0;
  68 const double kActivateEstimationPercentile = 90.0;
  69 const double kDrawEstimationPercentile = 90.0;
  70
  71 double BeginMainFrameStartToReadyToCommitCriticalPercentile() {
  72   if (base::FeatureList::IsEnabled(
  73           features::kDurationEstimatesInCompositorTimingHistory)) {
  74     double result = base::GetFieldTrialParamByFeatureAsDouble(
  75         features::kDurationEstimatesInCompositorTimingHistory,
  76         "BMFStartCritialPercentile", -1.0);
  77     if (result > 0)
  78       return result;
  79   }
  80   return 90.0;
  81 }
  82
  83 double BeginMainFrameStartToReadyToCommitNonCriticalPercentile() {
  84   if (base::FeatureList::IsEnabled(
  85           features::kDurationEstimatesInCompositorTimingHistory)) {
  86     double result = base::GetFieldTrialParamByFeatureAsDouble(
  87         features::kDurationEstimatesInCompositorTimingHistory,
  88         "BMFStartNonCritialPercentile", -1.0);
  89     if (result > 0)
  90       return result;
  91   }
  92   return 90.0;
  93 }
  94
  95 double BeginMainFrameQueueToActivateCriticalPercentile() {
  96   if (base::FeatureList::IsEnabled(
  97           features::kDurationEstimatesInCompositorTimingHistory)) {
  98     double result = base::GetFieldTrialParamByFeatureAsDouble(
  99         features::kDurationEstimatesInCompositorTimingHistory,
 100         "BMFQueueCritialPercentile", -1.0);
 101     if (result > 0)
 102       return result;
 103   }
 104   return 90.0;
 105 }
 106
 107 // This macro is deprecated since its bucket count uses too much bandwidth.
 108 // It also has sub-optimal range and bucket distribution.
 109 // TODO(brianderson): Delete this macro and associated UMAs once there is
 110 // sufficient overlap with the re-bucketed UMAs.
 111 #define UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(name, sample)                     \
 112   UMA_HISTOGRAM_CUSTOM_COUNTS(name, sample.InMicroseconds(),                \
 113                               kUmaDurationMinMicros, kUmaDurationMaxMicros, \
 114                               kUmaDurationBucketCount);
 115
 116 // ~90 VSync aligned UMA buckets.
 117 const int kUMAVSyncBuckets[] = {
 118     // Powers of two from 0 to 2048 us @ 50% precision
 119     1,
 120     2,
 121     4,
 122     8,
 123     16,
 124     32,
 125     64,
 126     128,
 127     256,
 128     512,
 129     1024,
 130     2048,
 131     // Every 8 Hz from 256 Hz to 128 Hz @ 3-6% precision
 132     3906,
 133     4032,
 134     4167,
 135     4310,
 136     4464,
 137     4630,
 138     4808,
 139     5000,
 140     5208,
 141     5435,
 142     5682,
 143     5952,
 144     6250,
 145     6579,
 146     6944,
 147     7353,
 148     // Every 4 Hz from 128 Hz to 64 Hz @ 3-6% precision
 149     7813,
 150     8065,
 151     8333,
 152     8621,
 153     8929,
 154     9259,
 155     9615,
 156     10000,
 157     10417,
 158     10870,
 159     11364,
 160     11905,
 161     12500,
 162     13158,
 163     13889,
 164     14706,
 165     // Every 2 Hz from 64 Hz to 32 Hz @ 3-6% precision
 166     15625,
 167     16129,
 168     16667,
 169     17241,
 170     17857,
 171     18519,
 172     19231,
 173     20000,
 174     20833,
 175     21739,
 176     22727,
 177     23810,
 178     25000,
 179     26316,
 180     27778,
 181     29412,
 182     // Every 1 Hz from 32 Hz to 1 Hz @ 3-33% precision
 183     31250,
 184     32258,
 185     33333,
 186     34483,
 187     35714,
 188     37037,
 189     38462,
 190     40000,
 191     41667,
 192     43478,
 193     45455,
 194     47619,
 195     50000,
 196     52632,
 197     55556,
 198     58824,
 199     62500,
 200     66667,
 201     71429,
 202     76923,
 203     83333,
 204     90909,
 205     100000,
 206     111111,
 207     125000,
 208     142857,
 209     166667,
 210     200000,
 211     250000,
 212     333333,
 213     500000,
 214     // Powers of two from 1s to 32s @ 50% precision
 215     1000000,
 216     2000000,
 217     4000000,
 218     8000000,
 219     16000000,
 220     32000000,
 221 };
 222
 223 // ~50 UMA buckets with high precision from ~100 us to 1s.
 224 const int kUMADurationBuckets[] = {
 225     // Powers of 2 from 1 us to 64 us @ 50% precision.
 226     1,
 227     2,
 228     4,
 229     8,
 230     16,
 231     32,
 232     64,
 233     // 1.25^20, 1.25^21, ..., 1.25^62 @ 20% precision.
 234     87,
 235     108,
 236     136,
 237     169,
 238     212,
 239     265,
 240     331,
 241     414,
 242     517,
 243     646,
 244     808,
 245     1010,
 246     1262,
 247     1578,
 248     1972,
 249     2465,
 250     3081,
 251     3852,
 252     4815,
 253     6019,
 254     7523,
 255     9404,
 256     11755,
 257     14694,
 258     18367,
 259     22959,
 260     28699,
 261     35873,
 262     44842,
 263     56052,
 264     70065,
 265     87581,
 266     109476,
 267     136846,
 268     171057,
 269     213821,
 270     267276,
 271     334096,
 272     417619,
 273     522024,
 274     652530,
 275     815663,
 276     1019579,
 277     // Powers of 2 from 2s to 32s @ 50% precision.
 278     2000000,
 279     4000000,
 280     8000000,
 281     16000000,
 282     32000000,
 283 };
 284
 285 #define UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(name, sample)             \
 286   do {                                                                     \
 287     UMA_HISTOGRAM_CUSTOM_ENUMERATION(                                      \
 288         name "2", sample.InMicroseconds(),                                 \
 289         std::vector<int>(kUMAVSyncBuckets,                                 \
 290                          kUMAVSyncBuckets + std::size(kUMAVSyncBuckets))); \
 291   } while (false)
 292
 293 #define UMA_HISTOGRAM_CUSTOM_TIMES_DURATION_SUFFIX(name, suffix, sample) \
 294   do {                                                                   \
 295     UMA_HISTOGRAM_CUSTOM_ENUMERATION(                                    \
 296         name "2" suffix, sample.InMicroseconds(),                        \
 297         std::vector<int>(                                                \
 298             kUMADurationBuckets,                                         \
 299             kUMADurationBuckets + std::size(kUMADurationBuckets)));      \
 300   } while (false)
 301
 302 #define UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(name, sample) \
 303   UMA_HISTOGRAM_CUSTOM_TIMES_DURATION_SUFFIX(name, "", sample)
 304
 305 #define UMA_HISTOGRAM_READY_TO_ACTIVATE(name, sample, priority)            \
 306   do {                                                                     \
 307     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(name, sample);                     \
 308     switch (priority) {                                                    \
 309       case SAME_PRIORITY_FOR_BOTH_TREES:                                   \
 310         UMA_HISTOGRAM_CUSTOM_TIMES_DURATION_SUFFIX(name, ".Same", sample); \
 311         break;                                                             \
 312       case SMOOTHNESS_TAKES_PRIORITY:                                      \
 313         UMA_HISTOGRAM_CUSTOM_TIMES_DURATION_SUFFIX(name, ".Smoothness",    \
 314                                                    sample);                \
 315         break;                                                             \
 316       case NEW_CONTENT_TAKES_PRIORITY:                                     \
 317         UMA_HISTOGRAM_CUSTOM_TIMES_DURATION_SUFFIX(name, ".NewContent",    \
 318                                                    sample);                \
 319         break;                                                             \
 320     }                                                                      \
 321   } while (false)
 322
 323 class RendererUMAReporter : public CompositorTimingHistory::UMAReporter {
 324  public:
 325   ~RendererUMAReporter() override = default;
 326
 327   void AddDrawInterval(base::TimeDelta interval) override {
 328     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED("Scheduling.Renderer.DrawInterval",
 329                                              interval);
 330   }
 331
 332   void AddDrawIntervalWithCustomPropertyAnimations(
 333       base::TimeDelta interval) override {
 334     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(
 335         "Scheduling.Renderer.DrawIntervalWithCustomPropertyAnimations",
 336         interval);
 337   }
 338
 339   void AddBeginImplFrameLatency(base::TimeDelta delta) override {
 340     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
 341         "Scheduling.Renderer.BeginImplFrameLatency", delta);
 342   }
 343
 344   void AddDrawDuration(base::TimeDelta duration) override {
 345     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION("Scheduling.Renderer.DrawDuration",
 346                                         duration);
 347   }
 348
 349   void AddImplFrameDeadlineType(
 350       CompositorTimingHistory::DeadlineMode deadline_mode) override {
 351     UMA_HISTOGRAM_ENUMERATION("Scheduling.Renderer.DeadlineMode",
 352                               deadline_mode);
 353   }
 354 };
 355
 356 class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
 357  public:
 358   ~BrowserUMAReporter() override = default;
 359
 360   // DrawInterval is not meaningful to measure on browser side because
 361   // browser rendering fps is not at 60.
 362   void AddDrawInterval(base::TimeDelta interval) override {}
 363
 364   void AddDrawIntervalWithCustomPropertyAnimations(
 365       base::TimeDelta interval) override {}
 366
 367   void AddBeginImplFrameLatency(base::TimeDelta delta) override {
 368     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
 369         "Scheduling.Browser.BeginImplFrameLatency", delta);
 370   }
 371
 372   void AddDrawDuration(base::TimeDelta duration) override {
 373     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION("Scheduling.Browser.DrawDuration",
 374                                         duration);
 375   }
 376
 377   void AddImplFrameDeadlineType(
 378       CompositorTimingHistory::DeadlineMode deadline_mode) override {
 379     // The browser compositor scheduler is synchronous and only has None (or
 380     // Blocked as edges cases) for deadline mode.
 381   }
 382 };
 383
 384 class NullUMAReporter : public CompositorTimingHistory::UMAReporter {
 385  public:
 386   ~NullUMAReporter() override = default;
 387   void AddDrawInterval(base::TimeDelta interval) override {}
 388   void AddDrawIntervalWithCustomPropertyAnimations(
 389       base::TimeDelta inverval) override {}
 390   void AddBeginImplFrameLatency(base::TimeDelta delta) override {}
 391   void AddDrawDuration(base::TimeDelta duration) override {}
 392   void AddImplFrameDeadlineType(
 393       CompositorTimingHistory::DeadlineMode deadline_mode) override {}
 394 };
 395
 396 }  // namespace
 397
 398 CompositorTimingHistory::CompositorTimingHistory(
 399     bool using_synchronous_renderer_compositor,
 400     UMACategory uma_category,
 401     RenderingStatsInstrumentation* rendering_stats_instrumentation)
 402     : using_synchronous_renderer_compositor_(
 403           using_synchronous_renderer_compositor),
 404       enabled_(false),
 405       compositor_drawing_continuously_(false),
 406       begin_main_frame_queue_duration_history_(kDurationHistorySize),
 407       begin_main_frame_queue_duration_critical_history_(kDurationHistorySize),
 408       begin_main_frame_queue_duration_not_critical_history_(
 409           kDurationHistorySize),
 410       begin_main_frame_start_to_ready_to_commit_duration_history_(
 411           kDurationHistorySize),
 412       commit_duration_history_(kDurationHistorySize),
 413       commit_to_ready_to_activate_duration_history_(kDurationHistorySize),
 414       prepare_tiles_duration_history_(kDurationHistorySize),
 415       activate_duration_history_(kDurationHistorySize),
 416       draw_duration_history_(kDurationHistorySize),
 417       duration_estimates_enabled_(base::FeatureList::IsEnabled(
 418           features::kDurationEstimatesInCompositorTimingHistory)),
 419       bmf_start_to_ready_to_commit_critical_history_(kDurationHistorySize),
 420       bmf_start_to_ready_to_commit_critical_percentile_(
 421           BeginMainFrameStartToReadyToCommitCriticalPercentile()),
 422       bmf_start_to_ready_to_commit_not_critical_history_(kDurationHistorySize),
 423       bmf_start_to_ready_to_commit_not_critical_percentile_(
 424           BeginMainFrameStartToReadyToCommitNonCriticalPercentile()),
 425       bmf_queue_to_activate_critical_history_(kDurationHistorySize),
 426       bmf_queue_to_activate_critical_percentile_(
 427           BeginMainFrameQueueToActivateCriticalPercentile()),
 428       uma_reporter_(CreateUMAReporter(uma_category)),
 429       rendering_stats_instrumentation_(rendering_stats_instrumentation) {}
 430
 431 CompositorTimingHistory::~CompositorTimingHistory() = default;
 432
 433 std::unique_ptr<CompositorTimingHistory::UMAReporter>
 434 CompositorTimingHistory::CreateUMAReporter(UMACategory category) {
 435   switch (category) {
 436     case RENDERER_UMA:
 437       return base::WrapUnique(new RendererUMAReporter);
 438     case BROWSER_UMA:
 439       return base::WrapUnique(new BrowserUMAReporter);
 440     case NULL_UMA:
 441       return base::WrapUnique(new NullUMAReporter);
 442   }
 443   NOTREACHED();
 444   return base::WrapUnique<CompositorTimingHistory::UMAReporter>(nullptr);
 445 }
 446
 447 base::TimeTicks CompositorTimingHistory::Now() const {
 448   return base::TimeTicks::Now();
 449 }
 450
 451 void CompositorTimingHistory::SetRecordingEnabled(bool enabled) {
 452   enabled_ = enabled;
 453 }
 454
 455 void CompositorTimingHistory::SetCompositorDrawingContinuously(bool active) {
 456   if (active == compositor_drawing_continuously_)
 457     return;
 458   draw_end_time_prev_ = base::TimeTicks();
 459   compositor_drawing_continuously_ = active;
 460 }
 461
 462 base::TimeDelta
 463 CompositorTimingHistory::BeginMainFrameQueueDurationCriticalEstimate() const {
 464   base::TimeDelta all = begin_main_frame_queue_duration_history_.Percentile(
 465       kBeginMainFrameQueueDurationEstimationPercentile);
 466   base::TimeDelta critical =
 467       begin_main_frame_queue_duration_critical_history_.Percentile(
 468           kBeginMainFrameQueueDurationCriticalEstimationPercentile);
 469   // Return the min since critical BeginMainFrames are likely fast if
 470   // the non critical ones are.
 471   return std::min(critical, all);
 472 }
 473
 474 base::TimeDelta
 475 CompositorTimingHistory::BeginMainFrameQueueDurationNotCriticalEstimate()
 476     const {
 477   base::TimeDelta all = begin_main_frame_queue_duration_history_.Percentile(
 478       kBeginMainFrameQueueDurationEstimationPercentile);
 479   base::TimeDelta not_critical =
 480       begin_main_frame_queue_duration_not_critical_history_.Percentile(
 481           kBeginMainFrameQueueDurationNotCriticalEstimationPercentile);
 482   // Return the max since, non critical BeginMainFrames are likely slow if
 483   // the critical ones are.
 484   return std::max(not_critical, all);
 485 }
 486
 487 base::TimeDelta
 488 CompositorTimingHistory::BeginMainFrameStartToReadyToCommitDurationEstimate()
 489     const {
 490   return begin_main_frame_start_to_ready_to_commit_duration_history_.Percentile(
 491       kBeginMainFrameStartToReadyToCommitEstimationPercentile);
 492 }
 493
 494 base::TimeDelta CompositorTimingHistory::CommitDurationEstimate() const {
 495   return commit_duration_history_.Percentile(kCommitEstimatePercentile);
 496 }
 497
 498 base::TimeDelta
 499 CompositorTimingHistory::CommitToReadyToActivateDurationEstimate() const {
 500   return commit_to_ready_to_activate_duration_history_.Percentile(
 501       kCommitToReadyToActivateEstimationPercentile);
 502 }
 503
 504 base::TimeDelta CompositorTimingHistory::PrepareTilesDurationEstimate() const {
 505   return prepare_tiles_duration_history_.Percentile(
 506       kPrepareTilesEstimationPercentile);
 507 }
 508
 509 base::TimeDelta CompositorTimingHistory::ActivateDurationEstimate() const {
 510   return activate_duration_history_.Percentile(kActivateEstimationPercentile);
 511 }
 512
 513 base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
 514   return draw_duration_history_.Percentile(kDrawEstimationPercentile);
 515 }
 516
 517 base::TimeDelta
 518 CompositorTimingHistory::BeginMainFrameStartToReadyToCommitCriticalEstimate()
 519     const {
 520   if (duration_estimates_enabled_) {
 521     return bmf_start_to_ready_to_commit_critical_history_.Percentile(
 522         bmf_start_to_ready_to_commit_critical_percentile_);
 523   }
 524   return BeginMainFrameStartToReadyToCommitDurationEstimate() +
 525          BeginMainFrameQueueDurationCriticalEstimate();
 526 }
 527
 528 base::TimeDelta
 529 CompositorTimingHistory::BeginMainFrameStartToReadyToCommitNotCriticalEstimate()
 530     const {
 531   if (duration_estimates_enabled_) {
 532     return bmf_start_to_ready_to_commit_not_critical_history_.Percentile(
 533         bmf_start_to_ready_to_commit_not_critical_percentile_);
 534   }
 535   return BeginMainFrameStartToReadyToCommitDurationEstimate() +
 536          BeginMainFrameQueueDurationNotCriticalEstimate();
 537 }
 538
 539 base::TimeDelta
 540 CompositorTimingHistory::BeginMainFrameQueueToActivateCriticalEstimate() const {
 541   if (duration_estimates_enabled_) {
 542     return bmf_queue_to_activate_critical_history_.Percentile(
 543         bmf_queue_to_activate_critical_percentile_);
 544   }
 545   return BeginMainFrameStartToReadyToCommitDurationEstimate() +
 546          CommitDurationEstimate() + CommitToReadyToActivateDurationEstimate() +
 547          ActivateDurationEstimate() +
 548          BeginMainFrameQueueDurationCriticalEstimate();
 549 }
 550
 551 void CompositorTimingHistory::WillBeginImplFrame(
 552     const viz::BeginFrameArgs& args,
 553     base::TimeTicks now) {
 554   viz::BeginFrameArgs::BeginFrameArgsType frame_type = args.type;
 555   base::TimeTicks frame_time = args.frame_time;
 556
 557   if (frame_type == viz::BeginFrameArgs::NORMAL)
 558     uma_reporter_->AddBeginImplFrameLatency(now - frame_time);
 559 }
 560
 561 void CompositorTimingHistory::WillFinishImplFrame(bool needs_redraw) {
 562   if (!needs_redraw)
 563     SetCompositorDrawingContinuously(false);
 564 }
 565
 566 void CompositorTimingHistory::BeginImplFrameNotExpectedSoon() {
 567   SetCompositorDrawingContinuously(false);
 568 }
 569
 570 void CompositorTimingHistory::WillBeginMainFrame(
 571     const viz::BeginFrameArgs& args) {
 572   DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
 573
 574   begin_main_frame_on_critical_path_ = args.on_critical_path;
 575   begin_main_frame_sent_time_ = Now();
 576 }
 577
 578 void CompositorTimingHistory::BeginMainFrameStarted(
 579     base::TimeTicks main_thread_start_time) {
 580   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
 581   DCHECK_EQ(base::TimeTicks(), begin_main_frame_start_time_);
 582   begin_main_frame_start_time_ = main_thread_start_time;
 583 }
 584
 585 void CompositorTimingHistory::BeginMainFrameAborted() {
 586   base::TimeTicks begin_main_frame_end_time = Now();
 587   DidBeginMainFrame(begin_main_frame_end_time);
 588 }
 589
 590 void CompositorTimingHistory::NotifyReadyToCommit() {
 591   DCHECK_NE(begin_main_frame_start_time_, base::TimeTicks());
 592   DCHECK_EQ(ready_to_commit_time_, base::TimeTicks());
 593   ready_to_commit_time_ = Now();
 594   pending_commit_on_critical_path_ = begin_main_frame_on_critical_path_;
 595   if (enabled_ && duration_estimates_enabled_) {
 596     bmf_start_to_ready_to_activate_duration_ =
 597         ready_to_commit_time_ - begin_main_frame_start_time_;
 598   }
 599   base::TimeDelta bmf_duration =
 600       ready_to_commit_time_ - begin_main_frame_start_time_;
 601   DidBeginMainFrame(ready_to_commit_time_);
 602   begin_main_frame_start_to_ready_to_commit_duration_history_.InsertSample(
 603       bmf_duration);
 604   if (enabled_ && duration_estimates_enabled_) {
 605     if (pending_commit_on_critical_path_) {
 606       bmf_start_to_ready_to_commit_critical_history_.InsertSample(
 607           bmf_duration + begin_main_frame_queue_duration_);
 608     } else {
 609       bmf_start_to_ready_to_commit_not_critical_history_.InsertSample(
 610           bmf_duration + begin_main_frame_queue_duration_);
 611     }
 612   }
 613 }
 614
 615 void CompositorTimingHistory::WillCommit() {
 616   DCHECK_NE(ready_to_commit_time_, base::TimeTicks());
 617   commit_start_time_ = Now();
 618   if (enabled_ && duration_estimates_enabled_) {
 619     DCHECK_NE(ready_to_commit_time_, base::TimeTicks());
 620     bmf_start_to_ready_to_activate_duration_ +=
 621         commit_start_time_ - ready_to_commit_time_;
 622   }
 623   ready_to_commit_time_ = base::TimeTicks();
 624 }
 625
 626 void CompositorTimingHistory::DidCommit() {
 627   DCHECK_EQ(pending_tree_creation_time_, base::TimeTicks());
 628   DCHECK_NE(commit_start_time_, base::TimeTicks());
 629
 630   base::TimeTicks commit_end_time = Now();
 631   if (enabled_ && duration_estimates_enabled_) {
 632     pending_tree_on_critical_path_ = pending_commit_on_critical_path_;
 633     bmf_start_to_ready_to_activate_duration_ +=
 634         (commit_end_time - commit_start_time_);
 635   }
 636   commit_duration_history_.InsertSample(commit_end_time - commit_start_time_);
 637
 638   pending_tree_is_impl_side_ = false;
 639   pending_tree_creation_time_ = commit_end_time;
 640   if (enabled_ && duration_estimates_enabled_)
 641     pending_tree_bmf_queue_duration_ = begin_main_frame_queue_duration_;
 642 }
 643
 644 void CompositorTimingHistory::DidBeginMainFrame(
 645     base::TimeTicks begin_main_frame_end_time) {
 646   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
 647
 648   // If the BeginMainFrame start time isn't known, assume it was immediate
 649   // for scheduling purposes, but don't report it for UMA to avoid skewing
 650   // the results.
 651   // TODO(szager): Can this be true? begin_main_frame_start_time_ should be
 652   // unconditionally assigned in BeginMainFrameStarted().
 653   if (begin_main_frame_start_time_.is_null())
 654     begin_main_frame_start_time_ = begin_main_frame_sent_time_;
 655
 656   base::TimeDelta bmf_sent_to_commit_duration =
 657       begin_main_frame_end_time - begin_main_frame_sent_time_;
 658   base::TimeDelta bmf_queue_duration =
 659       begin_main_frame_start_time_ - begin_main_frame_sent_time_;
 660
 661   rendering_stats_instrumentation_->AddBeginMainFrameToCommitDuration(
 662       bmf_sent_to_commit_duration);
 663
 664   if (enabled_) {
 665     begin_main_frame_queue_duration_history_.InsertSample(bmf_queue_duration);
 666     if (begin_main_frame_on_critical_path_) {
 667       begin_main_frame_queue_duration_critical_history_.InsertSample(
 668           bmf_queue_duration);
 669     } else {
 670       begin_main_frame_queue_duration_not_critical_history_.InsertSample(
 671           bmf_queue_duration);
 672     }
 673     if (duration_estimates_enabled_)
 674       begin_main_frame_queue_duration_ = bmf_queue_duration;
 675   }
 676
 677   begin_main_frame_sent_time_ = base::TimeTicks();
 678   begin_main_frame_start_time_ = base::TimeTicks();
 679   begin_main_frame_on_critical_path_ = false;
 680 }
 681
 682 void CompositorTimingHistory::WillInvalidateOnImplSide() {
 683   DCHECK(!pending_tree_is_impl_side_);
 684   DCHECK_EQ(pending_tree_creation_time_, base::TimeTicks());
 685
 686   pending_tree_is_impl_side_ = true;
 687   pending_tree_on_critical_path_ = false;
 688   pending_tree_bmf_queue_duration_ = base::TimeDelta();
 689   pending_tree_creation_time_ = base::TimeTicks::Now();
 690 }
 691
 692 void CompositorTimingHistory::WillPrepareTiles() {
 693   DCHECK_EQ(base::TimeTicks(), prepare_tiles_start_time_);
 694   prepare_tiles_start_time_ = Now();
 695 }
 696
 697 void CompositorTimingHistory::DidPrepareTiles() {
 698   DCHECK_NE(base::TimeTicks(), prepare_tiles_start_time_);
 699
 700   base::TimeDelta prepare_tiles_duration = Now() - prepare_tiles_start_time_;
 701   if (enabled_)
 702     prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration);
 703
 704   prepare_tiles_start_time_ = base::TimeTicks();
 705 }
 706
 707 void CompositorTimingHistory::ReadyToActivate() {
 708   DCHECK_NE(pending_tree_creation_time_, base::TimeTicks());
 709   DCHECK_EQ(pending_tree_ready_to_activate_time_, base::TimeTicks());
 710
 711   pending_tree_ready_to_activate_time_ = Now();
 712   if (!pending_tree_is_impl_side_) {
 713     base::TimeDelta time_since_commit =
 714         pending_tree_ready_to_activate_time_ - pending_tree_creation_time_;
 715
 716     // Before adding the new data point to the timing history, see what we would
 717     // have predicted for this frame. This allows us to keep track of the
 718     // accuracy of our predictions.
 719
 720     base::TimeDelta commit_to_ready_to_activate_estimate =
 721         CommitToReadyToActivateDurationEstimate();
 722     rendering_stats_instrumentation_->AddCommitToActivateDuration(
 723         time_since_commit, commit_to_ready_to_activate_estimate);
 724
 725     if (enabled_) {
 726       commit_to_ready_to_activate_duration_history_.InsertSample(
 727           time_since_commit);
 728       if (duration_estimates_enabled_)
 729         bmf_start_to_ready_to_activate_duration_ += time_since_commit;
 730     }
 731   }
 732 }
 733
 734 void CompositorTimingHistory::WillActivate() {
 735   DCHECK_EQ(base::TimeTicks(), activate_start_time_);
 736
 737   activate_start_time_ = Now();
 738
 739   pending_tree_is_impl_side_ = false;
 740   pending_tree_creation_time_ = base::TimeTicks();
 741 }
 742
 743 void CompositorTimingHistory::DidActivate() {
 744   DCHECK_NE(base::TimeTicks(), activate_start_time_);
 745   base::TimeTicks activate_end_time = Now();
 746   base::TimeDelta activate_duration = activate_end_time - activate_start_time_;
 747
 748   if (enabled_) {
 749     activate_duration_history_.InsertSample(activate_duration);
 750
 751     if (duration_estimates_enabled_) {
 752       if (pending_tree_on_critical_path_) {
 753         base::TimeDelta time_since_ready_to_activate =
 754             activate_end_time - pending_tree_ready_to_activate_time_;
 755         DCHECK_NE(pending_tree_bmf_queue_duration_, base::TimeDelta());
 756         bmf_queue_to_activate_critical_history_.InsertSample(
 757             bmf_start_to_ready_to_activate_duration_ +
 758             time_since_ready_to_activate + pending_tree_bmf_queue_duration_);
 759       }
 760       bmf_start_to_ready_to_activate_duration_ = base::TimeDelta();
 761       pending_tree_on_critical_path_ = false;
 762     }
 763   }
 764
 765   pending_tree_ready_to_activate_time_ = base::TimeTicks();
 766   activate_start_time_ = base::TimeTicks();
 767 }
 768
 769 void CompositorTimingHistory::WillDraw() {
 770   DCHECK_EQ(base::TimeTicks(), draw_start_time_);
 771   draw_start_time_ = Now();
 772 }
 773
 774 void CompositorTimingHistory::DidDraw(bool used_new_active_tree,
 775                                       bool has_custom_property_animations) {
 776   DCHECK_NE(base::TimeTicks(), draw_start_time_);
 777   base::TimeTicks draw_end_time = Now();
 778   base::TimeDelta draw_duration = draw_end_time - draw_start_time_;
 779
 780   // Before adding the new data point to the timing history, see what we would
 781   // have predicted for this frame. This allows us to keep track of the accuracy
 782   // of our predictions.
 783   base::TimeDelta draw_estimate = DrawDurationEstimate();
 784   rendering_stats_instrumentation_->AddDrawDuration(draw_duration,
 785                                                     draw_estimate);
 786
 787   uma_reporter_->AddDrawDuration(draw_duration);
 788
 789   if (enabled_) {
 790     draw_duration_history_.InsertSample(draw_duration);
 791   }
 792
 793   SetCompositorDrawingContinuously(true);
 794   if (!draw_end_time_prev_.is_null()) {
 795     base::TimeDelta draw_interval = draw_end_time - draw_end_time_prev_;
 796     uma_reporter_->AddDrawInterval(draw_interval);
 797     // Emit a trace event to highlight a long time lapse between the draw times
 798     // of back-to-back BeginImplFrames.
 799     if (draw_interval > kDrawIntervalTraceThreshold) {
 800       TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
 801           "latency", "Long Draw Interval",
 802           TRACE_ID_WITH_SCOPE("Long Draw Interval", g_num_long_draw_intervals),
 803           draw_start_time_);
 804       TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
 805           "latency", "Long Draw Interval",
 806           TRACE_ID_WITH_SCOPE("Long Draw Interval", g_num_long_draw_intervals),
 807           draw_end_time);
 808       g_num_long_draw_intervals++;
 809     }
 810     if (has_custom_property_animations &&
 811         previous_frame_had_custom_property_animations_)
 812       uma_reporter_->AddDrawIntervalWithCustomPropertyAnimations(draw_interval);
 813   }
 814   previous_frame_had_custom_property_animations_ =
 815       has_custom_property_animations;
 816   draw_end_time_prev_ = draw_end_time;
 817
 818   if (used_new_active_tree)
 819     new_active_tree_draw_end_time_prev_ = draw_end_time;
 820   draw_start_time_ = base::TimeTicks();
 821 }
 822
 823 void CompositorTimingHistory::RecordDeadlineMode(DeadlineMode deadline_mode) {
 824   if (uma_reporter_)
 825     uma_reporter_->AddImplFrameDeadlineType(deadline_mode);
 826 }
 827
 828 void CompositorTimingHistory::ClearHistory() {
 829   TRACE_EVENT0("cc,benchmark", "CompositorTimingHistory::ClearHistory");
 830
 831   begin_main_frame_queue_duration_history_.Clear();
 832   begin_main_frame_queue_duration_critical_history_.Clear();
 833   begin_main_frame_queue_duration_not_critical_history_.Clear();
 834   begin_main_frame_start_to_ready_to_commit_duration_history_.Clear();
 835   commit_duration_history_.Clear();
 836   commit_to_ready_to_activate_duration_history_.Clear();
 837   prepare_tiles_duration_history_.Clear();
 838   activate_duration_history_.Clear();
 839   draw_duration_history_.Clear();
 840   bmf_start_to_ready_to_commit_critical_history_.Clear();
 841   bmf_start_to_ready_to_commit_not_critical_history_.Clear();
 842   bmf_queue_to_activate_critical_history_.Clear();
 843 }
 844
 845 size_t CompositorTimingHistory::CommitDurationSampleCountForTesting() const {
 846   return commit_duration_history_.sample_count();
 847 }
 848 }  // namespace cc