cc/scheduler/compositor_timing_history.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   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/scheduler/compositor_timing_history.h"
   6
   7 #include "base/metrics/histogram.h"
   8 #include "base/trace_event/trace_event.h"
   9 #include "cc/debug/rendering_stats_instrumentation.h"
  10
  11 namespace cc {
  12
  13 class CompositorTimingHistory::UMAReporter {
  14  public:
  15   virtual ~UMAReporter() {}
  16
  17   virtual void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
  18                                                  base::TimeDelta estimate,
  19                                                  bool affects_estimate) = 0;
  20   virtual void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
  21                                                   base::TimeDelta estimate,
  22                                                   bool affects_estimate) = 0;
  23   virtual void AddPrepareTilesDuration(base::TimeDelta duration,
  24                                        base::TimeDelta estimate,
  25                                        bool affects_estimate) = 0;
  26   virtual void AddActivateDuration(base::TimeDelta duration,
  27                                    base::TimeDelta estimate,
  28                                    bool affects_estimate) = 0;
  29   virtual void AddDrawDuration(base::TimeDelta duration,
  30                                base::TimeDelta estimate,
  31                                bool affects_estimate) = 0;
  32 };
  33
  34 namespace {
  35
  36 // The estimates that affect the compositors deadline use the 100th percentile
  37 // to avoid missing the Browser's deadline.
  38 // The estimates related to main-thread responsiveness affect whether
  39 // we attempt to recovery latency or not and use the 50th percentile.
  40 // TODO(brianderson): Fine tune the percentiles below.
  41 const size_t kDurationHistorySize = 60;
  42 const size_t kDrawsBeforeEstimatesAffected = 2;
  43 const double kBeginMainFrameToCommitEstimationPercentile = 50.0;
  44 const double kCommitToReadyToActivateEstimationPercentile = 50.0;
  45 const double kPrepareTilesEstimationPercentile = 100.0;
  46 const double kActivateEstimationPercentile = 100.0;
  47 const double kDrawEstimationPercentile = 100.0;
  48
  49 const int kUmaDurationMin_uS = 1;
  50 const int64 kUmaDurationMax_uS = 1 * base::Time::kMicrosecondsPerSecond;
  51 const size_t kUmaDurationBucketCount = 100;
  52
  53 // Deprecated because they combine Browser and Renderer stats and have low
  54 // precision.
  55 // TODO(brianderson): Remove.
  56 void DeprecatedDrawDurationUMA(base::TimeDelta duration,
  57                                base::TimeDelta estimate) {
  58   base::TimeDelta duration_overestimate;
  59   base::TimeDelta duration_underestimate;
  60   if (duration > estimate)
  61     duration_underestimate = duration - estimate;
  62   else
  63     duration_overestimate = estimate - duration;
  64   UMA_HISTOGRAM_CUSTOM_TIMES("Renderer.DrawDuration", duration,
  65                              base::TimeDelta::FromMilliseconds(1),
  66                              base::TimeDelta::FromMilliseconds(100), 50);
  67   UMA_HISTOGRAM_CUSTOM_TIMES("Renderer.DrawDurationUnderestimate",
  68                              duration_underestimate,
  69                              base::TimeDelta::FromMilliseconds(1),
  70                              base::TimeDelta::FromMilliseconds(100), 50);
  71   UMA_HISTOGRAM_CUSTOM_TIMES("Renderer.DrawDurationOverestimate",
  72                              duration_overestimate,
  73                              base::TimeDelta::FromMilliseconds(1),
  74                              base::TimeDelta::FromMilliseconds(100), 50);
  75 }
  76
  77 #define UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(name, sample)  \
  78   UMA_HISTOGRAM_CUSTOM_COUNTS(                           \
  79       name, sample.InMicroseconds(), kUmaDurationMin_uS, \
  80       kUmaDurationMax_uS, kUmaDurationBucketCount);
  81
  82 #define REPORT_COMPOSITOR_TIMING_HISTORY_UMA(category, subcategory)            \
  83   do {                                                                         \
  84     base::TimeDelta duration_overestimate;                                     \
  85     base::TimeDelta duration_underestimate;                                    \
  86     if (duration > estimate)                                                   \
  87       duration_underestimate = duration - estimate;                            \
  88     else                                                                       \
  89       duration_overestimate = estimate - duration;                             \
  90     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(                                         \
  91         "Scheduling." category "." subcategory "Duration", duration);          \
  92     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory   \
  93                                       "Duration.Underestimate",                \
  94                                       duration_underestimate);                 \
  95     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory   \
  96                                       "Duration.Overestimate",                 \
  97                                       duration_overestimate);                  \
  98     if (!affects_estimate) {                                                   \
  99       UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory \
 100                                         "Duration.NotUsedForEstimate",         \
 101                                         duration);                             \
 102     }                                                                          \
 103   } while (false)
 104
 105 class RendererUMAReporter : public CompositorTimingHistory::UMAReporter {
 106  public:
 107   ~RendererUMAReporter() override {}
 108
 109   void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
 110                                          base::TimeDelta estimate,
 111                                          bool affects_estimate) override {
 112     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "BeginMainFrameToCommit");
 113   }
 114
 115   void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
 116                                           base::TimeDelta estimate,
 117                                           bool affects_estimate) override {
 118     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "CommitToReadyToActivate");
 119   }
 120
 121   void AddPrepareTilesDuration(base::TimeDelta duration,
 122                                base::TimeDelta estimate,
 123                                bool affects_estimate) override {
 124     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "PrepareTiles");
 125   }
 126
 127   void AddActivateDuration(base::TimeDelta duration,
 128                            base::TimeDelta estimate,
 129                            bool affects_estimate) override {
 130     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "Activate");
 131   }
 132
 133   void AddDrawDuration(base::TimeDelta duration,
 134                        base::TimeDelta estimate,
 135                        bool affects_estimate) override {
 136     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "Draw");
 137     DeprecatedDrawDurationUMA(duration, estimate);
 138   }
 139 };
 140
 141 class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
 142  public:
 143   ~BrowserUMAReporter() override {}
 144
 145   void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
 146                                          base::TimeDelta estimate,
 147                                          bool affects_estimate) override {
 148     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "BeginMainFrameToCommit");
 149   }
 150
 151   void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
 152                                           base::TimeDelta estimate,
 153                                           bool affects_estimate) override {
 154     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "CommitToReadyToActivate");
 155   }
 156
 157   void AddPrepareTilesDuration(base::TimeDelta duration,
 158                                base::TimeDelta estimate,
 159                                bool affects_estimate) override {
 160     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "PrepareTiles");
 161   }
 162
 163   void AddActivateDuration(base::TimeDelta duration,
 164                            base::TimeDelta estimate,
 165                            bool affects_estimate) override {
 166     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "Activate");
 167   }
 168
 169   void AddDrawDuration(base::TimeDelta duration,
 170                        base::TimeDelta estimate,
 171                        bool affects_estimate) override {
 172     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "Draw");
 173     DeprecatedDrawDurationUMA(duration, estimate);
 174   }
 175 };
 176
 177 class NullUMAReporter : public CompositorTimingHistory::UMAReporter {
 178  public:
 179   ~NullUMAReporter() override {}
 180   void AddPrepareTilesDuration(base::TimeDelta duration,
 181                                base::TimeDelta estimate,
 182                                bool affects_estimate) override {}
 183   void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
 184                                          base::TimeDelta estimate,
 185                                          bool affects_estimate) override {}
 186   void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
 187                                           base::TimeDelta estimate,
 188                                           bool affects_estimate) override {}
 189   void AddActivateDuration(base::TimeDelta duration,
 190                            base::TimeDelta estimate,
 191                            bool affects_estimate) override {}
 192   void AddDrawDuration(base::TimeDelta duration,
 193                        base::TimeDelta estimate,
 194                        bool affects_estimate) override {}
 195 };
 196
 197 }  // namespace
 198
 199 CompositorTimingHistory::CompositorTimingHistory(
 200     UMACategory uma_category,
 201     RenderingStatsInstrumentation* rendering_stats_instrumentation)
 202     : enabled_(false),
 203       draws_left_before_estimates_affected_(0),
 204       begin_main_frame_to_commit_duration_history_(kDurationHistorySize),
 205       commit_to_ready_to_activate_duration_history_(kDurationHistorySize),
 206       prepare_tiles_duration_history_(kDurationHistorySize),
 207       activate_duration_history_(kDurationHistorySize),
 208       draw_duration_history_(kDurationHistorySize),
 209       uma_reporter_(CreateUMAReporter(uma_category)),
 210       rendering_stats_instrumentation_(rendering_stats_instrumentation) {}
 211
 212 CompositorTimingHistory::~CompositorTimingHistory() {
 213 }
 214
 215 scoped_ptr<CompositorTimingHistory::UMAReporter>
 216 CompositorTimingHistory::CreateUMAReporter(UMACategory category) {
 217   switch (category) {
 218     case RENDERER_UMA:
 219       return make_scoped_ptr(new RendererUMAReporter);
 220       break;
 221     case BROWSER_UMA:
 222       return make_scoped_ptr(new BrowserUMAReporter);
 223       break;
 224     case NULL_UMA:
 225       return make_scoped_ptr(new NullUMAReporter);
 226       break;
 227   }
 228   NOTREACHED();
 229   return make_scoped_ptr<CompositorTimingHistory::UMAReporter>(nullptr);
 230 }
 231
 232 void CompositorTimingHistory::AsValueInto(
 233     base::trace_event::TracedValue* state) const {
 234   state->SetDouble("begin_main_frame_to_commit_estimate_ms",
 235                    BeginMainFrameToCommitDurationEstimate().InMillisecondsF());
 236   state->SetDouble("commit_to_ready_to_activate_estimate_ms",
 237                    CommitToReadyToActivateDurationEstimate().InMillisecondsF());
 238   state->SetDouble("prepare_tiles_estimate_ms",
 239                    PrepareTilesDurationEstimate().InMillisecondsF());
 240   state->SetDouble("activate_estimate_ms",
 241                    ActivateDurationEstimate().InMillisecondsF());
 242   state->SetDouble("draw_estimate_ms",
 243                    DrawDurationEstimate().InMillisecondsF());
 244 }
 245
 246 base::TimeTicks CompositorTimingHistory::Now() const {
 247   return base::TimeTicks::Now();
 248 }
 249
 250 bool CompositorTimingHistory::AffectsEstimate() const {
 251   return enabled_ && (draws_left_before_estimates_affected_ == 0);
 252 }
 253
 254 void CompositorTimingHistory::SetRecordingEnabled(bool enabled) {
 255   if (enabled == enabled_)
 256     return;
 257
 258   enabled_ = enabled;
 259
 260   if (enabled_)
 261     draws_left_before_estimates_affected_ = kDrawsBeforeEstimatesAffected;
 262 }
 263
 264 base::TimeDelta
 265 CompositorTimingHistory::BeginMainFrameToCommitDurationEstimate() const {
 266   return begin_main_frame_to_commit_duration_history_.Percentile(
 267       kBeginMainFrameToCommitEstimationPercentile);
 268 }
 269
 270 base::TimeDelta
 271 CompositorTimingHistory::CommitToReadyToActivateDurationEstimate() const {
 272   return commit_to_ready_to_activate_duration_history_.Percentile(
 273       kCommitToReadyToActivateEstimationPercentile);
 274 }
 275
 276 base::TimeDelta CompositorTimingHistory::PrepareTilesDurationEstimate() const {
 277   return prepare_tiles_duration_history_.Percentile(
 278       kPrepareTilesEstimationPercentile);
 279 }
 280
 281 base::TimeDelta CompositorTimingHistory::ActivateDurationEstimate() const {
 282   return activate_duration_history_.Percentile(kActivateEstimationPercentile);
 283 }
 284
 285 base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
 286   return draw_duration_history_.Percentile(kDrawEstimationPercentile);
 287 }
 288
 289 void CompositorTimingHistory::WillBeginMainFrame() {
 290   DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
 291   begin_main_frame_sent_time_ = Now();
 292 }
 293
 294 void CompositorTimingHistory::BeginMainFrameAborted() {
 295   DidCommit();
 296 }
 297
 298 void CompositorTimingHistory::DidCommit() {
 299   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
 300
 301   commit_time_ = Now();
 302
 303   base::TimeDelta begin_main_frame_to_commit_duration =
 304       commit_time_ - begin_main_frame_sent_time_;
 305
 306   // Before adding the new data point to the timing history, see what we would
 307   // have predicted for this frame. This allows us to keep track of the accuracy
 308   // of our predictions.
 309   base::TimeDelta begin_main_frame_to_commit_estimate =
 310       BeginMainFrameToCommitDurationEstimate();
 311
 312   rendering_stats_instrumentation_->AddBeginMainFrameToCommitDuration(
 313       begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate);
 314
 315   bool affects_estimate = AffectsEstimate();
 316   uma_reporter_->AddBeginMainFrameToCommitDuration(
 317       begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate,
 318       affects_estimate);
 319   if (affects_estimate) {
 320     begin_main_frame_to_commit_duration_history_.InsertSample(
 321         begin_main_frame_to_commit_duration);
 322   }
 323
 324   begin_main_frame_sent_time_ = base::TimeTicks();
 325 }
 326
 327 void CompositorTimingHistory::WillPrepareTiles() {
 328   DCHECK_EQ(base::TimeTicks(), start_prepare_tiles_time_);
 329   start_prepare_tiles_time_ = Now();
 330 }
 331
 332 void CompositorTimingHistory::DidPrepareTiles() {
 333   DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_);
 334
 335   base::TimeDelta prepare_tiles_duration = Now() - start_prepare_tiles_time_;
 336
 337   bool affects_estimate = AffectsEstimate();
 338   uma_reporter_->AddPrepareTilesDuration(
 339       prepare_tiles_duration, PrepareTilesDurationEstimate(), affects_estimate);
 340   if (affects_estimate)
 341     prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration);
 342
 343   start_prepare_tiles_time_ = base::TimeTicks();
 344 }
 345
 346 void CompositorTimingHistory::ReadyToActivate() {
 347   // We only care about the first ready to activate signal
 348   // after a commit.
 349   if (commit_time_ == base::TimeTicks())
 350     return;
 351
 352   base::TimeDelta time_since_commit = Now() - commit_time_;
 353
 354   // Before adding the new data point to the timing history, see what we would
 355   // have predicted for this frame. This allows us to keep track of the accuracy
 356   // of our predictions.
 357
 358   base::TimeDelta commit_to_ready_to_activate_estimate =
 359       CommitToReadyToActivateDurationEstimate();
 360   rendering_stats_instrumentation_->AddCommitToActivateDuration(
 361       time_since_commit, commit_to_ready_to_activate_estimate);
 362
 363   bool affects_estimate = AffectsEstimate();
 364   uma_reporter_->AddCommitToReadyToActivateDuration(
 365       time_since_commit, commit_to_ready_to_activate_estimate,
 366       affects_estimate);
 367   if (affects_estimate) {
 368     commit_to_ready_to_activate_duration_history_.InsertSample(
 369         time_since_commit);
 370   }
 371
 372   commit_time_ = base::TimeTicks();
 373 }
 374
 375 void CompositorTimingHistory::WillActivate() {
 376   DCHECK_EQ(base::TimeTicks(), start_activate_time_);
 377   start_activate_time_ = Now();
 378 }
 379
 380 void CompositorTimingHistory::DidActivate() {
 381   DCHECK_NE(base::TimeTicks(), start_activate_time_);
 382   base::TimeDelta activate_duration = Now() - start_activate_time_;
 383
 384   bool affects_estimate = AffectsEstimate();
 385   uma_reporter_->AddActivateDuration(
 386       activate_duration, ActivateDurationEstimate(), affects_estimate);
 387   if (affects_estimate)
 388     activate_duration_history_.InsertSample(activate_duration);
 389
 390   start_activate_time_ = base::TimeTicks();
 391 }
 392
 393 void CompositorTimingHistory::WillDraw() {
 394   DCHECK_EQ(base::TimeTicks(), start_draw_time_);
 395   start_draw_time_ = Now();
 396 }
 397
 398 void CompositorTimingHistory::DidDraw() {
 399   DCHECK_NE(base::TimeTicks(), start_draw_time_);
 400   base::TimeDelta draw_duration = Now() - start_draw_time_;
 401
 402   // Before adding the new data point to the timing history, see what we would
 403   // have predicted for this frame. This allows us to keep track of the accuracy
 404   // of our predictions.
 405   base::TimeDelta draw_estimate = DrawDurationEstimate();
 406   rendering_stats_instrumentation_->AddDrawDuration(draw_duration,
 407                                                     draw_estimate);
 408
 409   bool affects_estimate = AffectsEstimate();
 410   uma_reporter_->AddDrawDuration(draw_duration, draw_estimate,
 411                                  affects_estimate);
 412   if (affects_estimate)
 413     draw_duration_history_.InsertSample(draw_duration);
 414
 415   if (draws_left_before_estimates_affected_ > 0)
 416     draws_left_before_estimates_affected_--;
 417
 418   start_draw_time_ = base::TimeTicks();
 419 }
 420
 421 }  // namespace cc