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