cc/metrics/average_lag_tracker.cc

   1 // Copyright 2019 The Chromium Authors
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "cc/metrics/average_lag_tracker.h"
   6
   7 #include <algorithm>
   8
   9 #include "base/metrics/histogram_functions.h"
  10 #include "base/strings/string_util.h"
  11
  12 namespace cc {
  13
  14 AverageLagTracker::AverageLagTracker() = default;
  15 AverageLagTracker::~AverageLagTracker() = default;
  16
  17 void AverageLagTracker::AddScrollEventInFrame(const EventInfo& event_info) {
  18   if (event_info.event_type == EventType::ScrollBegin) {
  19     AddScrollBeginInFrame(event_info);
  20   } else if (!last_event_timestamp_.is_null()) {
  21     AddScrollUpdateInFrame(event_info);
  22   }
  23
  24   last_event_timestamp_ = event_info.event_timestamp;
  25   last_event_accumulated_delta_ += event_info.event_scroll_delta;
  26   last_rendered_accumulated_delta_ += event_info.predicted_scroll_delta;
  27 }
  28
  29 std::string AverageLagTracker::GetAverageLagMetricName(EventType event) const {
  30   std::string metric_name = "AverageLagPresentation";
  31
  32   std::string event_name =
  33       event == EventType::ScrollBegin ? "ScrollBegin" : "ScrollUpdate";
  34
  35   return base::JoinString(
  36       {"Event", "Latency", event_name, "Touch", metric_name}, ".");
  37 }
  38
  39 void AverageLagTracker::AddScrollBeginInFrame(const EventInfo& event_info) {
  40   DCHECK_EQ(event_info.event_type, EventType::ScrollBegin);
  41
  42   // Flush all unfinished frames.
  43   while (!frame_lag_infos_.empty()) {
  44     frame_lag_infos_.front().lag_area += LagForUnfinishedFrame(
  45         frame_lag_infos_.front().rendered_accumulated_delta);
  46     frame_lag_infos_.front().lag_area_no_prediction += LagForUnfinishedFrame(
  47         frame_lag_infos_.front().rendered_accumulated_delta_no_prediction);
  48
  49     // Record UMA when it's the last item in queue.
  50     CalculateAndReportAverageLagUma(frame_lag_infos_.size() == 1);
  51   }
  52   // |accumulated_lag_| should be cleared/reset.
  53   DCHECK_EQ(accumulated_lag_, 0);
  54
  55   // Create ScrollBegin report, with report time equals to the frame
  56   // timestamp.
  57   LagAreaInFrame first_frame(event_info.finish_timestamp);
  58   frame_lag_infos_.push_back(first_frame);
  59
  60   // Reset fields.
  61   last_reported_time_ = event_info.event_timestamp;
  62   last_finished_frame_time_ = event_info.event_timestamp;
  63   last_event_accumulated_delta_ = 0;
  64   last_rendered_accumulated_delta_ = 0;
  65   is_begin_ = true;
  66 }
  67
  68 void AverageLagTracker::AddScrollUpdateInFrame(const EventInfo& event_info) {
  69   DCHECK_EQ(event_info.event_type, EventType::ScrollUpdate);
  70
  71   // Only accept events in nondecreasing order.
  72   if ((event_info.event_timestamp - last_event_timestamp_).InMilliseconds() < 0)
  73     return;
  74
  75   // Pop all frames where frame_time <= event_timestamp.
  76   while (!frame_lag_infos_.empty() &&
  77          frame_lag_infos_.front().frame_time <= event_info.event_timestamp) {
  78     base::TimeTicks front_time =
  79         std::max(last_event_timestamp_, last_finished_frame_time_);
  80     base::TimeTicks back_time = frame_lag_infos_.front().frame_time;
  81     frame_lag_infos_.front().lag_area +=
  82         LagBetween(front_time, back_time, event_info.event_scroll_delta,
  83                    event_info.event_timestamp,
  84                    frame_lag_infos_.front().rendered_accumulated_delta);
  85     frame_lag_infos_.front().lag_area_no_prediction += LagBetween(
  86         front_time, back_time, event_info.event_scroll_delta,
  87         event_info.event_timestamp,
  88         frame_lag_infos_.front().rendered_accumulated_delta_no_prediction);
  89
  90     CalculateAndReportAverageLagUma();
  91   }
  92
  93   // Initialize a new LagAreaInFrame when current_frame_time > frame_time.
  94   if (frame_lag_infos_.empty() ||
  95       event_info.finish_timestamp > frame_lag_infos_.back().frame_time) {
  96     LagAreaInFrame new_frame(event_info.finish_timestamp,
  97                              last_rendered_accumulated_delta_,
  98                              last_event_accumulated_delta_);
  99     frame_lag_infos_.push_back(new_frame);
 100   }
 101
 102   // last_frame_time <= event_timestamp < frame_time
 103   if (!frame_lag_infos_.empty()) {
 104     // The front element in queue (if any) must satisfy frame_time >
 105     // event_timestamp, otherwise it would be popped in the while loop.
 106     DCHECK_LE(last_finished_frame_time_, event_info.event_timestamp);
 107     DCHECK_LE(event_info.event_timestamp, frame_lag_infos_.front().frame_time);
 108     base::TimeTicks front_time =
 109         std::max(last_finished_frame_time_, last_event_timestamp_);
 110     base::TimeTicks back_time = event_info.event_timestamp;
 111
 112     frame_lag_infos_.front().lag_area +=
 113         LagBetween(front_time, back_time, event_info.event_scroll_delta,
 114                    event_info.event_timestamp,
 115                    frame_lag_infos_.front().rendered_accumulated_delta);
 116
 117     frame_lag_infos_.front().lag_area_no_prediction += LagBetween(
 118         front_time, back_time, event_info.event_scroll_delta,
 119         event_info.event_timestamp,
 120         frame_lag_infos_.front().rendered_accumulated_delta_no_prediction);
 121   }
 122 }
 123
 124 float AverageLagTracker::LagBetween(base::TimeTicks front_time,
 125                                     base::TimeTicks back_time,
 126                                     const float scroll_delta,
 127                                     base::TimeTicks event_timestamp,
 128                                     float rendered_accumulated_delta) {
 129   // In some tests, we use const event time. return 0 to avoid divided by 0.
 130   if (event_timestamp == last_event_timestamp_)
 131     return 0;
 132
 133   float front_delta =
 134       (last_event_accumulated_delta_ +
 135        (scroll_delta * ((front_time - last_event_timestamp_) /
 136                         (event_timestamp - last_event_timestamp_)))) -
 137       rendered_accumulated_delta;
 138
 139   float back_delta =
 140       (last_event_accumulated_delta_ +
 141        scroll_delta * ((back_time - last_event_timestamp_) /
 142                        (event_timestamp - last_event_timestamp_))) -
 143       rendered_accumulated_delta;
 144
 145   // Calculate the trapezoid area.
 146   if (front_delta * back_delta >= 0) {
 147     return 0.5f * std::abs(front_delta + back_delta) *
 148            (back_time - front_time).InMillisecondsF();
 149   }
 150
 151   // Corner case that rendered_accumulated_delta is in between of front_pos
 152   // and back_pos.
 153   return 0.5f *
 154          std::abs((front_delta * front_delta + back_delta * back_delta) /
 155                   (back_delta - front_delta)) *
 156          (back_time - front_time).InMillisecondsF();
 157 }
 158
 159 float AverageLagTracker::LagForUnfinishedFrame(
 160     float rendered_accumulated_delta) {
 161   base::TimeTicks last_time =
 162       std::max(last_event_timestamp_, last_finished_frame_time_);
 163   return std::abs(last_event_accumulated_delta_ - rendered_accumulated_delta) *
 164          (frame_lag_infos_.front().frame_time - last_time).InMillisecondsF();
 165 }
 166
 167 void AverageLagTracker::CalculateAndReportAverageLagUma(bool send_anyway) {
 168   DCHECK(!frame_lag_infos_.empty());
 169   const LagAreaInFrame& frame_lag = frame_lag_infos_.front();
 170
 171   DCHECK_GE(frame_lag.lag_area, 0.f);
 172   DCHECK_GE(frame_lag.lag_area_no_prediction, 0.f);
 173   accumulated_lag_ += frame_lag.lag_area;
 174   accumulated_lag_no_prediction_ += frame_lag.lag_area_no_prediction;
 175
 176   if (is_begin_) {
 177     DCHECK_EQ(accumulated_lag_, accumulated_lag_no_prediction_);
 178   }
 179
 180   // |send_anyway| is true when we are flush all remaining frames on next
 181   // |ScrollBegin|. Otherwise record UMA when it's ScrollBegin, or when
 182   // reaching the 1 second gap.
 183   if (send_anyway || is_begin_ ||
 184       (frame_lag.frame_time - last_reported_time_) >= base::Seconds(1)) {
 185     const EventType event_type =
 186         is_begin_ ? EventType::ScrollBegin : EventType::ScrollUpdate;
 187
 188     const float time_delta =
 189         (frame_lag.frame_time - last_reported_time_).InMillisecondsF();
 190     const float scaled_lag_with_prediction = accumulated_lag_ / time_delta;
 191     const float scaled_lag_no_prediction =
 192         accumulated_lag_no_prediction_ / time_delta;
 193
 194     base::UmaHistogramCounts1000(GetAverageLagMetricName(event_type),
 195                                  scaled_lag_with_prediction);
 196     base::UmaHistogramCounts1000(
 197         base::JoinString({GetAverageLagMetricName(event_type), "NoPrediction"},
 198                          "."),
 199         scaled_lag_no_prediction);
 200
 201     const float lag_improvement =
 202         scaled_lag_no_prediction - scaled_lag_with_prediction;
 203
 204     // Log positive and negative prediction effects. ScrollBegin currently
 205     // doesn't take prediction into account so don't log for it.
 206     // Positive effect means that the prediction reduced the perceived lag,
 207     // where negative means prediction made lag worse (most likely due to
 208     // misprediction).
 209     if (event_type == EventType::ScrollUpdate) {
 210       if (lag_improvement >= 0.f) {
 211         base::UmaHistogramCounts1000(
 212             base::JoinString(
 213                 {GetAverageLagMetricName(event_type), "PredictionPositive"},
 214                 "."),
 215             lag_improvement);
 216       } else {
 217         base::UmaHistogramCounts1000(
 218             base::JoinString(
 219                 {GetAverageLagMetricName(event_type), "PredictionNegative"},
 220                 "."),
 221             -lag_improvement);
 222       }
 223
 224       if (scaled_lag_no_prediction > 0) {
 225         // How much of the original lag wasn't removed by prediction.
 226         float remaining_lag_ratio =
 227             scaled_lag_with_prediction / scaled_lag_no_prediction;
 228
 229         // Using custom bucket count for high precision on values in (0, 100).
 230         // With 100 buckets, (0, 100) is mapped into 60 buckets.
 231         base::UmaHistogramCustomCounts(
 232             base::JoinString(
 233                 {GetAverageLagMetricName(event_type), "RemainingLagPercentage"},
 234                 "."),
 235             100 * remaining_lag_ratio, 1, 500, 100);
 236       }
 237     }
 238     accumulated_lag_ = 0;
 239     accumulated_lag_no_prediction_ = 0;
 240     last_reported_time_ = frame_lag.frame_time;
 241     is_begin_ = false;
 242   }
 243
 244   last_finished_frame_time_ = frame_lag.frame_time;
 245   frame_lag_infos_.pop_front();
 246 }
 247
 248 }  // namespace cc