Decouple AverageLagTracker and LatencyInfo.
Moving the event collection to LayerTreeHostImpl is an initial step
towards a new version of the AverageLag metrics using
PresentationFeedback times instead of GpuSwap times, which are available
through LayerTreeHostImpl.
Moving them from LatencyTracker is also interesting as it aggregates
events across all viz clients at the end of the GPU pipeline, which can
potentially mix up events from multiple sources.
Tracking events by viz client (through LayerTreeHostImpl) avoids it.
As AverageLagTracker should be dedicated to Telemetry, it is interesting
to remove all LatencyInfo preprocessing from it, as LatencyInfo stores
a lot of information that is irrelevant to AverageLagTracker.
This CL proposes to move the scroll events collection from LatencyTracker
to LayerTreeHostImpl. It also proposes an AverageLagTrackingManager,
an intermediary class for using AverageLagTracker that preprocesses
LatencyInfo objects so AverageLagTracker can be independent from it.
As the event collection is moved to LayerTreeHostImpl, the
AverageLagTrackingManager also serves to encapsulate any preprocessing
from LayerTreeHostImpl and AverageLagTrakcer.
Bug: 1079024, 989207
Change-Id: I2e73e244eee9565239a638f00dfbf19d5658eadb
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2189633
Commit-Queue: João Victor Almeida de Aguiar <joalmei@microsoft.com>
Reviewed-by: Steven Holte <holte@chromium.org>
Reviewed-by: Robert Flack <flackr@chromium.org>
Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: Xida Chen <xidachen@chromium.org>
Reviewed-by: Daniel Libby <dlibby@microsoft.com>
Cr-Commit-Position: refs/heads/master@{#785975}
diff --git a/cc/BUILD.gn b/cc/BUILD.gn
index 7e5e837..ce648504 100644
--- a/cc/BUILD.gn
+++ b/cc/BUILD.gn
@@ -149,6 +149,10 @@
"layers/video_layer_impl.h",
"layers/viewport.cc",
"layers/viewport.h",
+ "metrics/average_lag_tracker.cc",
+ "metrics/average_lag_tracker.h",
+ "metrics/average_lag_tracking_manager.cc",
+ "metrics/average_lag_tracking_manager.h",
"metrics/begin_main_frame_metrics.cc",
"metrics/begin_main_frame_metrics.h",
"metrics/compositor_frame_reporter.cc",
@@ -660,6 +664,8 @@
"layers/video_frame_provider_client_impl_unittest.cc",
"layers/video_layer_impl_unittest.cc",
"layers/viewport_unittest.cc",
+ "metrics/average_lag_tracker_unittest.cc",
+ "metrics/average_lag_tracking_manager_unittest.cc",
"metrics/compositor_frame_reporter_unittest.cc",
"metrics/compositor_frame_reporting_controller_unittest.cc",
"metrics/compositor_timing_history_unittest.cc",
diff --git a/cc/metrics/average_lag_tracker.cc b/cc/metrics/average_lag_tracker.cc
new file mode 100644
index 0000000..5aa9b7d
--- /dev/null
+++ b/cc/metrics/average_lag_tracker.cc
@@ -0,0 +1,211 @@
+// Copyright 2019 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "cc/metrics/average_lag_tracker.h"
+
+#include <algorithm>
+
+#include "base/metrics/histogram_functions.h"
+
+namespace cc {
+
+AverageLagTracker::AverageLagTracker() = default;
+AverageLagTracker::~AverageLagTracker() = default;
+
+void AverageLagTracker::AddScrollEventInFrame(const EventInfo& event_info) {
+ if (event_info.event_type == EventType::ScrollBegin) {
+ AddScrollBeginInFrame(event_info);
+ } else if (!last_event_timestamp_.is_null()) {
+ AddScrollUpdateInFrame(event_info);
+ }
+
+ last_event_timestamp_ = event_info.event_timestamp;
+ last_event_accumulated_delta_ += event_info.event_scroll_delta;
+ last_rendered_accumulated_delta_ += event_info.predicted_scroll_delta;
+}
+
+void AverageLagTracker::AddScrollBeginInFrame(const EventInfo& event_info) {
+ DCHECK_EQ(event_info.event_type, EventType::ScrollBegin);
+
+ // Flush all unfinished frames.
+ while (!frame_lag_infos_.empty()) {
+ frame_lag_infos_.front().lag_area += LagForUnfinishedFrame(
+ frame_lag_infos_.front().rendered_accumulated_delta);
+ frame_lag_infos_.front().lag_area_no_prediction += LagForUnfinishedFrame(
+ frame_lag_infos_.front().rendered_accumulated_delta_no_prediction);
+
+ // Record UMA when it's the last item in queue.
+ CalculateAndReportAverageLagUma(frame_lag_infos_.size() == 1);
+ }
+ // |accumulated_lag_| should be cleared/reset.
+ DCHECK_EQ(accumulated_lag_, 0);
+
+ // Create ScrollBegin report, with report time equals to the frame
+ // timestamp.
+ LagAreaInFrame first_frame(event_info.finish_timestamp);
+ frame_lag_infos_.push_back(first_frame);
+
+ // Reset fields.
+ last_reported_time_ = event_info.event_timestamp;
+ last_finished_frame_time_ = event_info.event_timestamp;
+ last_event_accumulated_delta_ = 0;
+ last_rendered_accumulated_delta_ = 0;
+ is_begin_ = true;
+}
+
+void AverageLagTracker::AddScrollUpdateInFrame(const EventInfo& event_info) {
+ DCHECK_EQ(event_info.event_type, EventType::ScrollUpdate);
+
+ // Only accept events in nondecreasing order.
+ if ((event_info.event_timestamp - last_event_timestamp_).InMilliseconds() < 0)
+ return;
+
+ // Pop all frames where frame_time <= event_timestamp.
+ while (!frame_lag_infos_.empty() &&
+ frame_lag_infos_.front().frame_time <= event_info.event_timestamp) {
+ base::TimeTicks front_time =
+ std::max(last_event_timestamp_, last_finished_frame_time_);
+ base::TimeTicks back_time = frame_lag_infos_.front().frame_time;
+ frame_lag_infos_.front().lag_area +=
+ LagBetween(front_time, back_time, event_info.event_scroll_delta,
+ event_info.event_timestamp,
+ frame_lag_infos_.front().rendered_accumulated_delta);
+ frame_lag_infos_.front().lag_area_no_prediction += LagBetween(
+ front_time, back_time, event_info.event_scroll_delta,
+ event_info.event_timestamp,
+ frame_lag_infos_.front().rendered_accumulated_delta_no_prediction);
+
+ CalculateAndReportAverageLagUma();
+ }
+
+ // Initialize a new LagAreaInFrame when current_frame_time > frame_time.
+ if (frame_lag_infos_.empty() ||
+ event_info.finish_timestamp > frame_lag_infos_.back().frame_time) {
+ LagAreaInFrame new_frame(event_info.finish_timestamp,
+ last_rendered_accumulated_delta_,
+ last_event_accumulated_delta_);
+ frame_lag_infos_.push_back(new_frame);
+ }
+
+ // last_frame_time <= event_timestamp < frame_time
+ if (!frame_lag_infos_.empty()) {
+ // The front element in queue (if any) must satisfy frame_time >
+ // event_timestamp, otherwise it would be popped in the while loop.
+ DCHECK_LE(last_finished_frame_time_, event_info.event_timestamp);
+ DCHECK_LE(event_info.event_timestamp, frame_lag_infos_.front().frame_time);
+ base::TimeTicks front_time =
+ std::max(last_finished_frame_time_, last_event_timestamp_);
+ base::TimeTicks back_time = event_info.event_timestamp;
+
+ frame_lag_infos_.front().lag_area +=
+ LagBetween(front_time, back_time, event_info.event_scroll_delta,
+ event_info.event_timestamp,
+ frame_lag_infos_.front().rendered_accumulated_delta);
+
+ frame_lag_infos_.front().lag_area_no_prediction += LagBetween(
+ front_time, back_time, event_info.event_scroll_delta,
+ event_info.event_timestamp,
+ frame_lag_infos_.front().rendered_accumulated_delta_no_prediction);
+ }
+}
+
+float AverageLagTracker::LagBetween(base::TimeTicks front_time,
+ base::TimeTicks back_time,
+ const float scroll_delta,
+ base::TimeTicks event_timestamp,
+ float rendered_accumulated_delta) {
+ // In some tests, we use const event time. return 0 to avoid divided by 0.
+ if (event_timestamp == last_event_timestamp_)
+ return 0;
+
+ float front_delta =
+ (last_event_accumulated_delta_ +
+ (scroll_delta *
+ ((front_time - last_event_timestamp_).InMillisecondsF() /
+ (event_timestamp - last_event_timestamp_).InMillisecondsF()))) -
+ rendered_accumulated_delta;
+
+ float back_delta =
+ (last_event_accumulated_delta_ +
+ scroll_delta *
+ ((back_time - last_event_timestamp_).InMillisecondsF() /
+ (event_timestamp - last_event_timestamp_).InMillisecondsF())) -
+ rendered_accumulated_delta;
+
+ // Calculate the trapezoid area.
+ if (front_delta * back_delta >= 0) {
+ return 0.5f * std::abs(front_delta + back_delta) *
+ (back_time - front_time).InMillisecondsF();
+ }
+
+ // Corner case that rendered_accumulated_delta is in between of front_pos
+ // and back_pos.
+ return 0.5f *
+ std::abs((front_delta * front_delta + back_delta * back_delta) /
+ (back_delta - front_delta)) *
+ (back_time - front_time).InMillisecondsF();
+}
+
+float AverageLagTracker::LagForUnfinishedFrame(
+ float rendered_accumulated_delta) {
+ base::TimeTicks last_time =
+ std::max(last_event_timestamp_, last_finished_frame_time_);
+ return std::abs(last_event_accumulated_delta_ - rendered_accumulated_delta) *
+ (frame_lag_infos_.front().frame_time - last_time).InMillisecondsF();
+}
+
+void AverageLagTracker::CalculateAndReportAverageLagUma(bool send_anyway) {
+ DCHECK(!frame_lag_infos_.empty());
+ const LagAreaInFrame& frame_lag = frame_lag_infos_.front();
+
+ DCHECK_GE(frame_lag.lag_area, 0.f);
+ DCHECK_GE(frame_lag.lag_area_no_prediction, 0.f);
+ accumulated_lag_ += frame_lag.lag_area;
+ accumulated_lag_no_prediction_ += frame_lag.lag_area_no_prediction;
+
+ if (is_begin_) {
+ DCHECK_EQ(accumulated_lag_, accumulated_lag_no_prediction_);
+ }
+
+ // |send_anyway| is true when we are flush all remaining frames on next
+ // |ScrollBegin|. Otherwise record UMA when it's ScrollBegin, or when
+ // reaching the 1 second gap.
+ if (send_anyway || is_begin_ ||
+ (frame_lag.frame_time - last_reported_time_).InSecondsF() >= 1.0f) {
+ std::string scroll_name = is_begin_ ? "ScrollBegin" : "ScrollUpdate";
+ const float time_delta =
+ (frame_lag.frame_time - last_reported_time_).InMillisecondsF();
+ const float scaled_lag = accumulated_lag_ / time_delta;
+ base::UmaHistogramCounts1000(
+ "Event.Latency." + scroll_name + ".Touch.AverageLag", scaled_lag);
+
+ const float prediction_effect =
+ (accumulated_lag_no_prediction_ - accumulated_lag_) / time_delta;
+ // Log positive and negative prediction effects. ScrollBegin currently
+ // doesn't take prediction into account so don't log for it.
+ // Positive effect means that the prediction reduced the perceived lag,
+ // where negative means prediction made lag worse (most likely due to
+ // misprediction).
+ if (!is_begin_) {
+ if (prediction_effect >= 0.f) {
+ base::UmaHistogramCounts1000(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive",
+ prediction_effect);
+ } else {
+ base::UmaHistogramCounts1000(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative",
+ -prediction_effect);
+ }
+ }
+ accumulated_lag_ = 0;
+ accumulated_lag_no_prediction_ = 0;
+ last_reported_time_ = frame_lag.frame_time;
+ is_begin_ = false;
+ }
+
+ last_finished_frame_time_ = frame_lag.frame_time;
+ frame_lag_infos_.pop_front();
+}
+
+} // namespace cc
diff --git a/cc/metrics/average_lag_tracker.h b/cc/metrics/average_lag_tracker.h
new file mode 100644
index 0000000..d113601
--- /dev/null
+++ b/cc/metrics/average_lag_tracker.h
@@ -0,0 +1,137 @@
+// Copyright 2019 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef CC_METRICS_AVERAGE_LAG_TRACKER_H_
+#define CC_METRICS_AVERAGE_LAG_TRACKER_H_
+
+#include <deque>
+#include <string>
+
+#include "base/macros.h"
+#include "base/time/time.h"
+#include "cc/cc_export.h"
+
+namespace cc {
+
+// A class for reporting AverageLag metrics. See
+// https://docs.google.com/document/d/1e8NuzPblIv2B9bz01oSj40rmlse7_PHq5oFS3lqz6N4/
+class CC_EXPORT AverageLagTracker {
+ public:
+ enum class EventType { ScrollBegin, ScrollUpdate };
+ struct EventInfo {
+ EventInfo(int trace_id,
+ float event_scroll_delta,
+ float predicted_scroll_delta,
+ base::TimeTicks event_timestamp,
+ EventType event_type)
+ : trace_id(trace_id),
+ event_scroll_delta(event_scroll_delta),
+ predicted_scroll_delta(predicted_scroll_delta),
+ event_timestamp(event_timestamp),
+ event_type(event_type) {}
+ // Id from the original LatencyInfo.
+ int trace_id;
+ // Delta reported by the scroll event (begin or update).
+ float event_scroll_delta;
+ // Delta predicted (when prediction is on, otherwise should be equals to
+ // |event_scroll_delta|).
+ float predicted_scroll_delta;
+ // Timestamp when the scroll event happened.
+ base::TimeTicks event_timestamp;
+ // Timestamp when the scroll event's frame finished, which is currently
+ // when the frame swap completed.
+ base::TimeTicks finish_timestamp;
+ // Scroll event type (begin or update).
+ EventType event_type;
+ };
+
+ AverageLagTracker();
+ ~AverageLagTracker();
+
+ // Disallow copy and assign.
+ AverageLagTracker(const AverageLagTracker&) = delete;
+ AverageLagTracker& operator=(AverageLagTracker const&) = delete;
+
+ // Adds a scroll event defined by |event_info|.
+ void AddScrollEventInFrame(const EventInfo& event_info);
+
+ private:
+ typedef struct LagAreaInFrame {
+ LagAreaInFrame(base::TimeTicks time,
+ float rendered_pos = 0,
+ float rendered_pos_no_prediction = 0)
+ : frame_time(time),
+ rendered_accumulated_delta(rendered_pos),
+ lag_area(0),
+ rendered_accumulated_delta_no_prediction(rendered_pos_no_prediction),
+ lag_area_no_prediction(0) {}
+ base::TimeTicks frame_time;
+ // |rendered_accumulated_delta| is the cumulative delta that was swapped for
+ // this frame; this is based on the predicted delta, if prediction is
+ // enabled.
+ float rendered_accumulated_delta;
+ // |lag_area| is computed once a future input is processed that occurs after
+ // the swap timestamp (so that we can compute how far the rendered delta
+ // was from the actual position at the swap time).
+ float lag_area;
+ // |rendered_accumulated_delta_no_prediction| is the what would have been
+ // rendered if prediction was not taken into account, i.e., the actual delta
+ // from the input event.
+ float rendered_accumulated_delta_no_prediction;
+ // |lag_area_no_prediction| is computed the same as |lag_area| but using
+ // rendered_accumulated_delta_no_prediction as the rendered delta.
+ float lag_area_no_prediction;
+ } LagAreaInFrame;
+
+ // Processes |event_info| as a ScrollBegin event and add it to the Lag.
+ void AddScrollBeginInFrame(const EventInfo& event_info);
+ // Processes |event_info| as a ScrollUpdate event and add it to the Lag.
+ void AddScrollUpdateInFrame(const EventInfo& event_info);
+
+ // Calculate lag in 1 seconds intervals and report UMA.
+ void CalculateAndReportAverageLagUma(bool send_anyway = false);
+
+ // Helper function to calculate lag area between |front_time| to
+ // |back_time|.
+ float LagBetween(base::TimeTicks front_time,
+ base::TimeTicks back_time,
+ float scroll_delta,
+ base::TimeTicks event_time,
+ float rendered_accumulated_delta);
+
+ float LagForUnfinishedFrame(float rendered_accumulated_delta);
+
+ std::deque<LagAreaInFrame> frame_lag_infos_;
+
+ // Last scroll event's timestamp in the sequence, reset on ScrollBegin.
+ base::TimeTicks last_event_timestamp_;
+ // Timestamp of the last frame popped from |frame_lag_infos_| queue.
+ base::TimeTicks last_finished_frame_time_;
+
+ // Accumulated scroll delta for actual scroll update events. Cumulated from
+ // event_scroll_delta. Reset on ScrollBegin.
+ float last_event_accumulated_delta_ = 0;
+ // Accumulated scroll delta got rendered on gpu swap. Cumulated from
+ // predicted_scroll_delta. It always has same value as
+ // |last_event_accumulated_delta_| when scroll prediction is disabled.
+ float last_rendered_accumulated_delta_ = 0;
+
+ // This keeps track of the last report_time when we report to UMA, so we can
+ // calculate the report's duration by current - last. Reset on ScrollBegin.
+ base::TimeTicks last_reported_time_;
+
+ // True if the first element of |frame_lag_infos_| is for ScrollBegin.
+ // For ScrollBegin, we don't wait for the 1 second interval but record the
+ // UMA once the frame is finished.
+ bool is_begin_ = false;
+
+ // Accumulated lag area in the 1 second intervals.
+ float accumulated_lag_ = 0;
+ // Accumulated lag not taking into account the predicted deltas.
+ float accumulated_lag_no_prediction_ = 0;
+};
+
+} // namespace cc
+
+#endif // CC_METRICS_AVERAGE_LAG_TRACKER_H_
diff --git a/cc/metrics/average_lag_tracker_unittest.cc b/cc/metrics/average_lag_tracker_unittest.cc
new file mode 100644
index 0000000..7b0c9b4
--- /dev/null
+++ b/cc/metrics/average_lag_tracker_unittest.cc
@@ -0,0 +1,519 @@
+// Copyright 2019 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "cc/metrics/average_lag_tracker.h"
+
+#include <memory>
+
+#include "base/test/metrics/histogram_tester.h"
+#include "testing/gmock/include/gmock/gmock.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+using base::Bucket;
+using testing::ElementsAre;
+
+namespace cc {
+namespace {
+
+class AverageLagTrackerTest : public testing::Test {
+ public:
+ AverageLagTrackerTest() { ResetHistograms(); }
+
+ void ResetHistograms() {
+ histogram_tester_ = std::make_unique<base::HistogramTester>();
+ }
+
+ const base::HistogramTester& histogram_tester() { return *histogram_tester_; }
+
+ void SetUp() override {
+ average_lag_tracker_ = std::make_unique<AverageLagTracker>();
+ }
+
+ void SyntheticTouchScrollBegin(base::TimeTicks event_time,
+ base::TimeTicks frame_time,
+ float delta,
+ float predicted_delta = 0) {
+ AverageLagTracker::EventInfo event_info(
+ 0, delta, predicted_delta != 0 ? predicted_delta : delta, event_time,
+ AverageLagTracker::EventType::ScrollBegin);
+ event_info.finish_timestamp = frame_time;
+ average_lag_tracker_->AddScrollEventInFrame(event_info);
+ }
+
+ void SyntheticTouchScrollUpdate(base::TimeTicks event_time,
+ base::TimeTicks frame_time,
+ float delta,
+ float predicted_delta = 0) {
+ AverageLagTracker::EventInfo event_info(
+ 0, delta, predicted_delta != 0 ? predicted_delta : delta, event_time,
+ AverageLagTracker::EventType::ScrollUpdate);
+ event_info.finish_timestamp = frame_time;
+ average_lag_tracker_->AddScrollEventInFrame(event_info);
+ }
+
+ protected:
+ std::unique_ptr<AverageLagTracker> average_lag_tracker_;
+
+ std::unique_ptr<base::HistogramTester> histogram_tester_;
+};
+
+base::TimeTicks MillisecondsToTimeTicks(float t_ms) {
+ return base::TimeTicks() + base::TimeDelta::FromMilliseconds(t_ms);
+}
+
+// Simulate a simple situation that events at every 10ms and start at t=15ms,
+// frame swaps at every 10ms too and start at t=20ms and test we record one
+// UMA for ScrollUpdate in one second.
+TEST_F(AverageLagTrackerTest, OneSecondInterval) {
+ base::TimeTicks event_time =
+ base::TimeTicks() + base::TimeDelta::FromMilliseconds(5);
+ base::TimeTicks frame_time =
+ base::TimeTicks() + base::TimeDelta::FromMilliseconds(10);
+ float scroll_delta = 10;
+
+ // ScrollBegin
+ event_time += base::TimeDelta::FromMilliseconds(10); // 15ms
+ frame_time += base::TimeDelta::FromMilliseconds(10); // 20ms
+ SyntheticTouchScrollBegin(event_time, frame_time, scroll_delta);
+
+ // Send 101 ScrollUpdate events to verify that there is 1 AverageLag record
+ // per 1 second.
+ const int kUpdates = 101;
+ for (int i = 0; i < kUpdates; i++) {
+ event_time += base::TimeDelta::FromMilliseconds(10);
+ frame_time += base::TimeDelta::FromMilliseconds(10);
+ // First 50 has positive delta, others negetive delta.
+ const int sign = (i < kUpdates / 2) ? 1 : -1;
+ SyntheticTouchScrollUpdate(event_time, frame_time, sign * scroll_delta);
+ }
+
+ // ScrollBegin report_time is at 20ms, so the next ScrollUpdate report_time is
+ // at 1020ms. The last event_time that finish this report should be later than
+ // 1020ms.
+ EXPECT_EQ(event_time,
+ base::TimeTicks() + base::TimeDelta::FromMilliseconds(1025));
+ EXPECT_EQ(frame_time,
+ base::TimeTicks() + base::TimeDelta::FromMilliseconds(1030));
+
+ // ScrollBegin AverageLag are the area between the event original component
+ // (time=15ms, delta=10px) to the frame swap time (time=20ms, expect finger
+ // position at delta=15px). The AverageLag scaled to 1 second is
+ // (0.5*(10px+15px)*5ms)/5ms = 12.5px.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(12, 1)));
+ // This ScrollUpdate AverageLag are calculated as the finger uniformly scroll
+ // 10px each frame. For scroll up/down frame, the Lag at the last frame swap
+ // is 5px, and Lag at this frame swap is 15px. For the one changing direction,
+ // the Lag is from 5 to 10 and down to 5 again. So total LagArea is 99 * 100,
+ // plus 75. the AverageLag in 1 second is 9.975px.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(9, 1)));
+ EXPECT_THAT(
+ histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive"),
+ ElementsAre(Bucket(0, 1)));
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative", 0);
+ ResetHistograms();
+
+ // Send another ScrollBegin to end the unfinished ScrollUpdate report.
+ event_time += base::TimeDelta::FromMilliseconds(10);
+ frame_time += base::TimeDelta::FromMilliseconds(10);
+ SyntheticTouchScrollBegin(event_time, frame_time, scroll_delta);
+
+ // The last ScrollUpdate's lag is 8.75px and truncated to 8.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(8, 1)));
+ EXPECT_THAT(
+ histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive"),
+ ElementsAre(Bucket(0, 1)));
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative", 0);
+}
+
+// Test the case that event's frame swap time is later than next event's
+// creation time. (i.e, event at t=10ms will be dispatch at t=30ms, while next
+// event is at t=20ms).
+TEST_F(AverageLagTrackerTest, LargerLatency) {
+ base::TimeTicks event_time = MillisecondsToTimeTicks(10);
+ base::TimeTicks frame_time =
+ event_time + base::TimeDelta::FromMilliseconds(20);
+ float scroll_delta = 10;
+
+ SyntheticTouchScrollBegin(event_time, frame_time, scroll_delta);
+
+ // Send 2 ScrollUpdate. The second one will record AverageLag.ScrollBegin as
+ // it's event_time is larger or equal to ScrollBegin's frame_time.
+ for (int i = 0; i < 2; i++) {
+ event_time += base::TimeDelta::FromMilliseconds(10);
+ frame_time = event_time + base::TimeDelta::FromMilliseconds(20);
+ SyntheticTouchScrollUpdate(event_time, frame_time, scroll_delta);
+ }
+
+ // ScrollBegin AveragLag are from t=10ms to t=30ms, with absolute scroll
+ // position from 10 to 30. The AverageLag should be:
+ // (0.5*(10px + 30px)*20ms/20ms) = 20px.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(20, 1)));
+
+ // Another ScrollBegin to flush unfinished frames.
+ // event_time doesn't matter here because the previous frames' lag are
+ // compute from their frame_time.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, scroll_delta);
+ // The to unfinished frames' lag are (finger_positon-rendered_position)*time,
+ // AverageLag is ((30px-10px)*10ms+(30px-20px)*10ms)/20ms = 15px.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(14, 1)));
+}
+
+// Test that multiple latency being flush in the same frame swap.
+TEST_F(AverageLagTrackerTest, TwoLatencyInfoInSameFrame) {
+ // ScrollBegin
+ base::TimeTicks event_time = MillisecondsToTimeTicks(10);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollBegin(event_time, frame_time, -10 /* scroll_delta */);
+
+ // ScrollUpdate with event_time >= ScrollBegin frame_time will generate
+ // a histogram for AverageLag.ScrollBegin.
+ event_time = MillisecondsToTimeTicks(20);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, -10 /* scroll_delta */);
+
+ // Absolute position from -10 to -20. The AverageLag should be:
+ // (0.5*(10px + 20px)*10ms/10ms) = 15px.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(14, 1)));
+
+ event_time = MillisecondsToTimeTicks(25);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 5 /* scroll_delta */);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ // The ScrollUpdates are at t=20ms, finger_pos=-20px, rendered_pos=-10px,
+ // at t=25ms, finger_pos=-15px, rendered_pos=-10px;
+ // To t=30ms both events get flush.
+ // AverageLag is (0.5*(10px+5px)*5ms + 5px*5ms)/10ms = 6.25px
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(6, 1)));
+}
+
+// Test the case that switching direction causes lag at current frame
+// time and previous frame time are in different direction.
+TEST_F(AverageLagTrackerTest, ChangeDirectionInFrame) {
+ // ScrollBegin
+ base::TimeTicks event_time = MillisecondsToTimeTicks(10);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollBegin(event_time, frame_time, 10 /* scroll_delta */);
+
+ // At t=20, lag = 10px.
+ event_time = MillisecondsToTimeTicks(20);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */);
+
+ // At t=30, lag = -10px.
+ event_time = MillisecondsToTimeTicks(30);
+ frame_time = MillisecondsToTimeTicks(40);
+ SyntheticTouchScrollUpdate(event_time, frame_time, -20 /* scroll_delta */);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ // From t=20 to t=30, lag_area=2*(0.5*10px*5ms)=50px*ms.
+ // From t=30 to t=40, lag_area=20px*10ms=200px*ms
+ // AverageLag = (50+200)/20 = 12.5px.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(12, 1)));
+}
+
+// A simple case without scroll prediction to compare with the two with
+// prediction cases below.
+TEST_F(AverageLagTrackerTest, NoScrollPrediction) {
+ // ScrollBegin, at t=5, finger_pos=5px.
+ base::TimeTicks event_time = MillisecondsToTimeTicks(5);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(10);
+ SyntheticTouchScrollBegin(event_time, frame_time, 5 /* scroll_delta */);
+
+ // ScrollUpdate, at t=15, finger_pos=15px.
+ event_time = MillisecondsToTimeTicks(15);
+ frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */);
+
+ // ScrollUpdate, at t=25, finger_pos=25px.
+ event_time = MillisecondsToTimeTicks(25);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ // Prediction hasn't take affect on ScrollBegin so it'll stay the same.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(7, 1)));
+ // At t=10, finger_pos = 10px, rendered_pos = 5px.
+ // At t=20, finger_pos = 20px, rendered_pos = 15px.
+ // At t=30, finger_pos = 25px, rendered_pos = 25px.
+ // AverageLag = ((5px+15px)*10ms/2 + (5px+10px)*5ms/2 + 10px*5ms)/20ms
+ // = 9.375
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(9, 1)));
+}
+
+// Test AverageLag with perfect scroll prediction.
+TEST_F(AverageLagTrackerTest, ScrollPrediction) {
+ // ScrollBegin, at t=5, finger_pos=5px.
+ // Predict frame_time=10, predicted_pos = 10px.
+ base::TimeTicks event_time = MillisecondsToTimeTicks(5);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(10);
+ SyntheticTouchScrollBegin(event_time, frame_time, 5 /* scroll_delta */,
+ 10 /* predicted_delta */);
+
+ // ScrollUpdate, at t=15, finger_pos=15px.
+ // Predict frame_time=20, predicted_pos = 20px.
+ event_time = MillisecondsToTimeTicks(15);
+ frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 10 /* predicted_delta */);
+
+ // ScrollUpdate, at t=25, finger_pos=25px.
+ // Predict frame_time=30, predicted_pos = 30px.
+ event_time = MillisecondsToTimeTicks(25);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 10 /* predicted_delta */);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ // Prediction hasn't take affect on ScrollBegin so it'll stay the same.
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(7, 1)));
+ // At t=10, finger_pos = 10px, rendered_pos = 10px.
+ // At t=20, finger_pos = 20px, rendered_pos = 20px.
+ // At t=30, finger_pos = 25px, rendered_pos = 30px.
+ // AverageLag = ((0px+10px)*10ms/2 + (0px+5px)*10ms/2 + 5px*5ms)/20ms
+ // = 4.375px
+ // AverageLag (w/o prediction)
+ // ((5px+15px)*10ms/2 + (5px+10px)*5ms/2 + 10px*5ms)/20ms
+ // = 9.375px
+ // Positive effect of prediction = 5px
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(4, 1)));
+ EXPECT_THAT(
+ histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive"),
+ ElementsAre(Bucket(5, 1)));
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative", 0);
+}
+
+// Test AverageLag with imperfect scroll prediction.
+TEST_F(AverageLagTrackerTest, ImperfectScrollPrediction) {
+ // ScrollBegin, at t=5, finger_pos=5px.
+ // Predict frame_time=10, predicted_pos(over) = 12px.
+ base::TimeTicks event_time = MillisecondsToTimeTicks(5);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(10);
+ SyntheticTouchScrollBegin(event_time, frame_time, 5 /* scroll_delta */,
+ 12 /* predicted_delta */);
+
+ // ScrollUpdate, at t=15, finger_pos=15px.
+ // Predict frame_time=20, predicted_pos(under) = 17px.
+ event_time = MillisecondsToTimeTicks(15);
+ frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 5 /* predicted_delta */);
+
+ // ScrollUpdate, at t=25, finger_pos=25px.
+ // Predict frame_time=30, predicted_pos(over) = 31px.
+ event_time = MillisecondsToTimeTicks(25);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 14 /* predicted_delta */);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(7, 1)));
+ // AverageLag = ((2px*2ms/2+8px*8ms/2)+ ((3px+8px)*5ms/2+8px*5ms))/20ms
+ // = 5.075px
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(5, 1)));
+ // AverageLag (w/o prediction =
+ // ((5px+15px)*10ms/2 + (5px+10px)*5ms/2 + 10px*5ms)/20ms
+ // = 9.375px
+ // Positive effect of prediction = 4.3px
+ EXPECT_THAT(
+ histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive"),
+ ElementsAre(Bucket(4, 1)));
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative", 0);
+}
+
+TEST_F(AverageLagTrackerTest, NegativePredictionEffect) {
+ // ScrollBegin, at t=5, finger_pos=5px.
+ // Predict frame_time=10, predicted_pos(over) = 20px.
+ base::TimeTicks event_time = MillisecondsToTimeTicks(5);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(10);
+ SyntheticTouchScrollBegin(event_time, frame_time, 5 /* scroll_delta */,
+ 20 /* predicted_delta */);
+
+ // ScrollUpdate, at t=15, finger_pos=15px.
+ // Predict frame_time=20, predicted_pos(over) = 60px.
+ event_time = MillisecondsToTimeTicks(15);
+ frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 40 /* predicted_delta */);
+
+ // ScrollUpdate, at t=25, finger_pos=25px.
+ // Predict frame_time=30, predicted_pos(over) = 60px.
+ event_time = MillisecondsToTimeTicks(25);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 0 /* predicted_delta */);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(7, 1)));
+ // AverageLag = ((10px+0px)*10ms/2)+ ((40px+35px)*5ms/2+35px*5ms))/20ms
+ // = 20.625px
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(20, 1)));
+ // AverageLag (w/o prediction =
+ // ((5px+15px)*10ms/2 + (5px+10px)*5ms/2 + 10px*5ms)/20ms
+ // = 9.375px
+ // Negative effect of prediction = 11.25
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive", 0);
+ EXPECT_THAT(
+ histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative"),
+ ElementsAre(Bucket(11, 1)));
+}
+
+TEST_F(AverageLagTrackerTest, NoPredictionEffect) {
+ // ScrollBegin, at t=5, finger_pos=5px.
+ // Predict frame_time=10, predicted_pos(over) = 25px.
+ base::TimeTicks event_time = MillisecondsToTimeTicks(5);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(10);
+ SyntheticTouchScrollBegin(event_time, frame_time, 5 /* scroll_delta */,
+ 25 /* predicted_delta */);
+
+ // ScrollUpdate, at t=15, finger_pos=15px.
+ // Predict frame_time=20, predicted_pos(over) = 32px.
+ event_time = MillisecondsToTimeTicks(15);
+ frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 7 /* predicted_delta */);
+
+ // ScrollUpdate, at t=25, finger_pos=25px.
+ // Predict frame_time=30, predicted_pos(over) = 37px.
+ event_time = MillisecondsToTimeTicks(25);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, 10 /* scroll_delta */,
+ 5 /* predicted_delta */);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(7, 1)));
+ // AverageLag = ((15px+5px)*10ms/2 + (12px+7px)*5ms/2 + 7px*5ms)/20ms
+ // = 9.125px
+ EXPECT_THAT(histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(9, 1)));
+ // AverageLag (w/o prediction) =
+ // ((5px+15px)*10ms/2 + (5px+10px)*5ms/2 + 10px*5ms)/20ms
+ // = 9.375px
+ // Prediction slightly positive, we should see a 0 bucket in
+ // PredictionPositive UMA
+ EXPECT_THAT(
+ histogram_tester().GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive"),
+ ElementsAre(Bucket(0, 1)));
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative", 0);
+}
+
+// Tests that when an event arrives out-of-order, the average lag tracker
+// properly ignores it.
+TEST_F(AverageLagTrackerTest, EventOutOfOrder) {
+ base::TimeTicks event_time = MillisecondsToTimeTicks(5);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(10);
+ float scroll_delta = 5.f;
+ SyntheticTouchScrollBegin(event_time, frame_time, scroll_delta);
+
+ event_time = MillisecondsToTimeTicks(15);
+ frame_time = MillisecondsToTimeTicks(20);
+ SyntheticTouchScrollUpdate(event_time, frame_time, scroll_delta);
+
+ event_time = MillisecondsToTimeTicks(25);
+ frame_time = MillisecondsToTimeTicks(30);
+ SyntheticTouchScrollUpdate(event_time, frame_time, scroll_delta);
+
+ // A ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(1000);
+ frame_time = MillisecondsToTimeTicks(1000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag", 1);
+
+ // Send an event whose timestamp is earlier than the most recent event,
+ // representing an event that gets process out of order.
+ base::TimeTicks earlier_event_time = MillisecondsToTimeTicks(15);
+ frame_time = MillisecondsToTimeTicks(1010);
+ SyntheticTouchScrollUpdate(earlier_event_time, frame_time, scroll_delta);
+
+ // Another ScrollBegin to flush unfinished frames.
+ event_time = MillisecondsToTimeTicks(2000);
+ frame_time = MillisecondsToTimeTicks(2000);
+ SyntheticTouchScrollBegin(event_time, frame_time, 0);
+
+ // Ensure that the event was ignored.
+ histogram_tester().ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag", 1);
+}
+
+} // namespace
+} // namespace cc
diff --git a/cc/metrics/average_lag_tracking_manager.cc b/cc/metrics/average_lag_tracking_manager.cc
new file mode 100644
index 0000000..3ddd0ae
--- /dev/null
+++ b/cc/metrics/average_lag_tracking_manager.cc
@@ -0,0 +1,96 @@
+// Copyright 2020 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "cc/metrics/average_lag_tracking_manager.h"
+
+#include <algorithm>
+
+#include "components/viz/common/frame_timing_details.h"
+#include "components/viz/common/quads/compositor_frame_metadata.h"
+#include "ui/latency/latency_info.h"
+
+namespace cc {
+
+AverageLagTrackingManager::AverageLagTrackingManager() = default;
+
+AverageLagTrackingManager::~AverageLagTrackingManager() {
+ // The map must contain only frames that haven't been presented (i.e. did not
+ // get a presentation feedback yet). Thus, at a given point in time, more than
+ // a handful (actually around 2) of frames without feedback is unexpected.
+ DCHECK_LE(frame_token_to_info_.size(), 20u);
+}
+
+void AverageLagTrackingManager::CollectScrollEventsFromFrame(
+ uint32_t frame_token,
+ const std::vector<ui::LatencyInfo>& latency_infos) {
+ std::vector<AverageLagTracker::EventInfo> event_infos;
+
+ for (ui::LatencyInfo latency_info : latency_infos) {
+ if (latency_info.source_event_type() != ui::SourceEventType::TOUCH)
+ continue;
+
+ bool found_scroll_begin = latency_info.FindLatency(
+ ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+ nullptr);
+ bool found_scroll_update = latency_info.FindLatency(
+ ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT, nullptr);
+
+ if (!found_scroll_begin && !found_scroll_update)
+ continue;
+
+ base::TimeTicks event_timestamp;
+ bool found_event = latency_info.FindLatency(
+ ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_LAST_EVENT_COMPONENT,
+ &event_timestamp);
+ DCHECK(found_event);
+
+ AverageLagTracker::EventInfo event_info(
+ latency_info.trace_id(), latency_info.scroll_update_delta(),
+ latency_info.predicted_scroll_update_delta(), event_timestamp,
+ found_scroll_begin == true
+ ? AverageLagTracker::EventType::ScrollBegin
+ : AverageLagTracker::EventType::ScrollUpdate);
+
+ event_infos.push_back(event_info);
+ }
+
+ frame_token_to_info_.push_back(
+ std::make_pair(frame_token, std::move(event_infos)));
+}
+
+void AverageLagTrackingManager::DidPresentCompositorFrame(
+ uint32_t frame_token,
+ const viz::FrameTimingDetails& frame_details) {
+ // Erase all previous frames that haven't received a feedback and get the
+ // current |frame_token| list of events.
+ std::vector<AverageLagTracker::EventInfo> infos;
+ while (!frame_token_to_info_.empty() &&
+ !viz::FrameTokenGT(frame_token_to_info_.front().first, frame_token)) {
+ if (frame_token_to_info_.front().first == frame_token)
+ infos = std::move(frame_token_to_info_.front().second);
+
+ frame_token_to_info_.pop_front();
+ }
+
+ if (infos.size() == 0)
+ return;
+
+ if (!frame_details.presentation_feedback.failed()) {
+ DCHECK(!frame_details.swap_timings.is_null());
+
+ // Sorts data by trace_id because |infos| can be in non-ascending order
+ // (ascending order of trace_id/time is required by AverageLagTracker).
+ std::sort(infos.begin(), infos.end(),
+ [](const AverageLagTracker::EventInfo& a,
+ const AverageLagTracker::EventInfo& b) {
+ return a.trace_id < b.trace_id;
+ });
+
+ for (AverageLagTracker::EventInfo info : infos) {
+ info.finish_timestamp = frame_details.swap_timings.swap_start;
+ lag_tracker_.AddScrollEventInFrame(info);
+ }
+ }
+}
+} // namespace cc
diff --git a/cc/metrics/average_lag_tracking_manager.h b/cc/metrics/average_lag_tracking_manager.h
new file mode 100644
index 0000000..70af5cc
--- /dev/null
+++ b/cc/metrics/average_lag_tracking_manager.h
@@ -0,0 +1,62 @@
+// Copyright 2020 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef CC_METRICS_AVERAGE_LAG_TRACKING_MANAGER_H_
+#define CC_METRICS_AVERAGE_LAG_TRACKING_MANAGER_H_
+
+#include <utility>
+#include <vector>
+
+#include "base/containers/circular_deque.h"
+#include "cc/cc_export.h"
+#include "cc/metrics/average_lag_tracker.h"
+
+namespace ui {
+class LatencyInfo;
+} // namespace ui
+
+namespace viz {
+struct FrameTimingDetails;
+} // namespace viz
+
+namespace cc {
+
+// A helper to decouple the LatencyInfos and the AverageLagTracker
+class CC_EXPORT AverageLagTrackingManager {
+ public:
+ AverageLagTrackingManager();
+ ~AverageLagTrackingManager();
+
+ // Disallow copy and assign.
+ AverageLagTrackingManager(const AverageLagTrackingManager&) = delete;
+ AverageLagTrackingManager& operator=(AverageLagTrackingManager const&) =
+ delete;
+
+ // Adds all the eligible events in the collection |infos| to the |frame_token|
+ // wait list.
+ void CollectScrollEventsFromFrame(uint32_t frame_token,
+ const std::vector<ui::LatencyInfo>& infos);
+
+ // Sends all pending events in the |frame_token| list to the
+ // AverageLagTracker, given its |frame_details|.
+ void DidPresentCompositorFrame(uint32_t frame_token,
+ const viz::FrameTimingDetails& frame_details);
+
+ private:
+ // Adds an eligible event |info| to the |frame_token| wait list.
+ void CollectScrollEventFromFrame(uint32_t frame_token,
+ const ui::LatencyInfo& info);
+
+ AverageLagTracker lag_tracker_;
+
+ // List of events (vector) per frame (uint32_t |frame_token|) to submit to the
+ // lag trackers when DidPresentCompositorFrame is called for a |frame_token|.
+ base::circular_deque<
+ std::pair<uint32_t, std::vector<AverageLagTracker::EventInfo>>>
+ frame_token_to_info_;
+};
+
+} // namespace cc
+
+#endif // CC_METRICS_AVERAGE_LAG_TRACKING_MANAGER_H_
diff --git a/cc/metrics/average_lag_tracking_manager_unittest.cc b/cc/metrics/average_lag_tracking_manager_unittest.cc
new file mode 100644
index 0000000..5aa6095
--- /dev/null
+++ b/cc/metrics/average_lag_tracking_manager_unittest.cc
@@ -0,0 +1,228 @@
+// Copyright 2020 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "cc/metrics/average_lag_tracking_manager.h"
+
+#include <algorithm>
+#include <memory>
+
+#include "base/test/metrics/histogram_tester.h"
+#include "components/viz/common/frame_timing_details.h"
+#include "testing/gmock/include/gmock/gmock.h"
+#include "testing/gtest/include/gtest/gtest.h"
+#include "ui/latency/latency_info.h"
+
+namespace cc {
+namespace {
+
+using base::Bucket;
+using testing::ElementsAre;
+
+// Helper for TimeTicks usage
+base::TimeTicks MillisecondsToTimeTicks(float t_ms) {
+ return base::TimeTicks() + base::TimeDelta::FromMilliseconds(t_ms);
+}
+
+// Helper for FrameTimingDetails usage in DidPresentCompositorFrame
+viz::FrameTimingDetails PrepareFrameDetails(base::TimeTicks swap_time) {
+ gfx::SwapTimings timings;
+ timings.swap_start = swap_time;
+ viz::FrameTimingDetails details;
+ details.swap_timings = timings;
+ return details;
+}
+
+class AverageLagTrackingManagerTest : public testing::Test {
+ protected:
+ AverageLagTrackingManagerTest() = default;
+
+ void SetUp() override { ResetHistograms(); }
+
+ void ResetHistograms() {
+ histogram_tester_ = std::make_unique<base::HistogramTester>();
+ }
+
+ // Creates a scroll event each |scroll_rate| (in ms) of |scroll_delta| px.
+ // Collect events at the expected |frame_times|.
+ void SimulateConstantScroll(const std::vector<unsigned int>& frame_times,
+ float scroll_delta,
+ unsigned int scroll_rate) {
+ if (frame_times.size() == 0 || frame_times[0] < scroll_rate)
+ return;
+
+ // Creates 1st frame with scroll begin
+ std::vector<ui::LatencyInfo> events(frame_times[0] / scroll_rate);
+ base::TimeTicks event_time = MillisecondsToTimeTicks(scroll_rate);
+ events[0] = PrepareScrollEvent(AverageLagTracker::EventType::ScrollBegin,
+ event_time, 0, scroll_delta);
+ for (size_t i = 1; i < events.size(); i++) {
+ event_time += base::TimeDelta::FromMilliseconds(scroll_rate);
+ events[i] = PrepareScrollEvent(AverageLagTracker::EventType::ScrollUpdate,
+ event_time, i, scroll_delta);
+ }
+ average_lag_tracking_manager_.CollectScrollEventsFromFrame(0, events);
+
+ // Creates remaining frames
+ for (size_t frame = 1; frame < frame_times.size(); frame++) {
+ unsigned int time_delta = frame_times[frame] - frame_times[frame - 1];
+ events = std::vector<ui::LatencyInfo>(time_delta / scroll_rate);
+ for (size_t i = 0; i < events.size(); i++) {
+ event_time += base::TimeDelta::FromMilliseconds(scroll_rate);
+ events[i] =
+ PrepareScrollEvent(AverageLagTracker::EventType::ScrollUpdate,
+ event_time, i, scroll_delta);
+ }
+ average_lag_tracking_manager_.CollectScrollEventsFromFrame(frame, events);
+ }
+ }
+
+ // Prepares a ui::LatencyInfo object for a ScrollEvent
+ ui::LatencyInfo PrepareScrollEvent(AverageLagTracker::EventType event_type,
+ base::TimeTicks event_time,
+ int trace_id,
+ float delta,
+ float predicted_delta = 0) {
+ ui::LatencyInfo info;
+ info.set_trace_id(trace_id);
+ info.set_source_event_type(ui::SourceEventType::TOUCH);
+
+ info.AddLatencyNumberWithTimestamp(
+ event_type == AverageLagTracker::EventType::ScrollBegin
+ ? ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT
+ : ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+ event_time);
+
+ info.AddLatencyNumberWithTimestamp(
+ ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_LAST_EVENT_COMPONENT, event_time);
+
+ info.set_scroll_update_delta(delta);
+ info.set_predicted_scroll_update_delta(
+ predicted_delta != 0 ? predicted_delta : delta);
+
+ return info;
+ }
+
+ AverageLagTrackingManager average_lag_tracking_manager_;
+ std::unique_ptr<base::HistogramTester> histogram_tester_;
+};
+
+// Simulate a simple situation that events at every 10ms and start at t=15ms,
+// frame swaps at every 10ms too and start at t=20ms and test we record one
+// UMA for ScrollUpdate in one second. Tests using CollectScrollEventAtFrame
+// (1 event per collection)
+TEST_F(AverageLagTrackingManagerTest, OneSecondInterval) {
+ base::TimeTicks event_time = MillisecondsToTimeTicks(5);
+ base::TimeTicks frame_time = MillisecondsToTimeTicks(10);
+ float scroll_delta = 10;
+ int frame_id = 1;
+
+ // ScrollBegin
+ event_time += base::TimeDelta::FromMilliseconds(10); // 15ms
+ frame_time += base::TimeDelta::FromMilliseconds(10); // 20ms
+ ui::LatencyInfo evt = PrepareScrollEvent(
+ AverageLagTracker::EventType::ScrollBegin, event_time, 1, scroll_delta);
+ average_lag_tracking_manager_.CollectScrollEventsFromFrame(
+ frame_id, std::vector<ui::LatencyInfo>{evt});
+ average_lag_tracking_manager_.DidPresentCompositorFrame(
+ frame_id, PrepareFrameDetails(frame_time));
+
+ // Send 101 ScrollUpdate events to verify that there is 1 AverageLag record
+ // per 1 second.
+ const int kUpdates = 101;
+ for (int i = 0; i < kUpdates; i++) {
+ event_time += base::TimeDelta::FromMilliseconds(10);
+ frame_time += base::TimeDelta::FromMilliseconds(10);
+ // First 50 has positive delta, others negative delta.
+ const int sign = (i < kUpdates / 2) ? 1 : -1;
+
+ evt = PrepareScrollEvent(AverageLagTracker::EventType::ScrollUpdate,
+ event_time, 1, sign * scroll_delta);
+ average_lag_tracking_manager_.CollectScrollEventsFromFrame(
+ frame_id, std::vector<ui::LatencyInfo>{evt});
+ average_lag_tracking_manager_.DidPresentCompositorFrame(
+ frame_id, PrepareFrameDetails(frame_time));
+ }
+
+ // ScrollBegin report_time is at 20ms, so the next ScrollUpdate report_time is
+ // at 1020ms. The last event_time that finish this report should be later than
+ // 1020ms.
+ EXPECT_EQ(event_time, MillisecondsToTimeTicks(1025));
+ EXPECT_EQ(frame_time, MillisecondsToTimeTicks(1030));
+
+ // ScrollBegin AverageLag are the area between the event original component
+ // (time=15ms, delta=10px) to the frame swap time (time=20ms, expect finger
+ // position at delta=15px). The AverageLag scaled to 1 second is
+ // (0.5*(10px+15px)*5ms)/5ms = 12.5px.
+ EXPECT_THAT(histogram_tester_->GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(12, 1)));
+ // This ScrollUpdate AverageLag are calculated as the finger uniformly scroll
+ // 10px each frame. For scroll up/down frame, the Lag at the last frame swap
+ // is 5px, and Lag at this frame swap is 15px. For the one changing direction,
+ // the Lag is from 5 to 10 and down to 5 again. So total LagArea is 99 * 100,
+ // plus 75. the AverageLag in 1 second is 9.975px.
+ EXPECT_THAT(histogram_tester_->GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(9, 1)));
+ EXPECT_THAT(
+ histogram_tester_->GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive"),
+ ElementsAre(Bucket(0, 1)));
+ histogram_tester_->ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative", 0);
+ ResetHistograms();
+
+ // Send another ScrollBegin to end the unfinished ScrollUpdate report.
+ event_time += base::TimeDelta::FromMilliseconds(10);
+ frame_time += base::TimeDelta::FromMilliseconds(10);
+ evt = PrepareScrollEvent(AverageLagTracker::EventType::ScrollBegin,
+ event_time, 1, scroll_delta);
+ average_lag_tracking_manager_.CollectScrollEventsFromFrame(
+ frame_id, std::vector<ui::LatencyInfo>{evt});
+ average_lag_tracking_manager_.DidPresentCompositorFrame(
+ frame_id, PrepareFrameDetails(frame_time));
+
+ // The last ScrollUpdate's lag is 8.75px and truncated to 8.
+ EXPECT_THAT(histogram_tester_->GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(8, 1)));
+ EXPECT_THAT(
+ histogram_tester_->GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionPositive"),
+ ElementsAre(Bucket(0, 1)));
+ histogram_tester_->ExpectTotalCount(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag.PredictionNegative", 0);
+}
+
+// This test creates 3 frames in order to check the submission of ScrollBegin
+// and ScrollUpdate events sent using CollectScrollEventsAtFrame (multiple
+// events per collection)
+TEST_F(AverageLagTrackingManagerTest, MultipleEventsInSameFrame) {
+ std::vector<unsigned int> frame_times = {400, 1400, 1600};
+ SimulateConstantScroll(frame_times, 10, 100);
+ for (size_t frame = 0; frame < frame_times.size(); frame++) {
+ average_lag_tracking_manager_.DidPresentCompositorFrame(
+ frame,
+ PrepareFrameDetails(MillisecondsToTimeTicks(frame_times[frame])));
+ }
+
+ // As the first frame is the ScrollBegin frame, the average lag is
+ // 0.5*(10 + 40) * 30 / 30 = 25. But UmaHistogramCounts1000's binning will
+ // round it to 23.
+ EXPECT_THAT(histogram_tester_->GetAllSamples(
+ "Event.Latency.ScrollBegin.Touch.AverageLag"),
+ ElementsAre(Bucket(23, 1)));
+
+ // Only the ScrollUpdate events from frame 2 are sent (as the frame 3 is
+ // waiting for the next frame for sumission).
+ // As there is a scroll update right at the same time as the frame submission,
+ // frame 2 starts with 0 lag at 0.4s and finishes with 100 at 1.4, thus:
+ // 0.5 * (0 + 100) / 2 = 50. It gets into the same bin as 47.
+ EXPECT_THAT(histogram_tester_->GetAllSamples(
+ "Event.Latency.ScrollUpdate.Touch.AverageLag"),
+ ElementsAre(Bucket(47, 1)));
+}
+
+} // namespace
+} // namespace cc
diff --git a/cc/trees/layer_tree_host_impl.cc b/cc/trees/layer_tree_host_impl.cc
index 8fa1a1c..3749862 100644
--- a/cc/trees/layer_tree_host_impl.cc
+++ b/cc/trees/layer_tree_host_impl.cc
@@ -2080,6 +2080,21 @@
client_->NotifyThroughputTrackerResults(
std::move(throughput_tracker_results));
}
+
+ // Send all pending lag events waiting on the frame pointed by |frame_token|.
+ // It is posted as a task because LayerTreeHostImpl::DidPresentCompositorFrame
+ // is in the rendering critical path (it is called by AsyncLayerTreeFrameSink
+ // ::OnBeginFrame).
+ GetTaskRunner()->PostTask(
+ FROM_HERE,
+ base::BindOnce(&LayerTreeHostImpl::LogAverageLagEvents,
+ weak_factory_.GetWeakPtr(), frame_token, details));
+}
+
+void LayerTreeHostImpl::LogAverageLagEvents(
+ uint32_t frame_token,
+ const viz::FrameTimingDetails& details) {
+ lag_tracking_manager_.DidPresentCompositorFrame(frame_token, details);
}
void LayerTreeHostImpl::DidNotNeedBeginFrame() {
@@ -2364,6 +2379,10 @@
auto compositor_frame = GenerateCompositorFrame(frame);
frame->frame_token = compositor_frame.metadata.frame_token;
+
+ // Collect |latency_info| information for tracking
+ lag_tracking_manager_.CollectScrollEventsFromFrame(
+ frame->frame_token, compositor_frame.metadata.latency_info);
layer_tree_frame_sink_->SubmitCompositorFrame(
std::move(compositor_frame),
/*hit_test_data_changed=*/false, debug_state_.show_hit_test_borders);
diff --git a/cc/trees/layer_tree_host_impl.h b/cc/trees/layer_tree_host_impl.h
index 53f6f15..ec84793f 100644
--- a/cc/trees/layer_tree_host_impl.h
+++ b/cc/trees/layer_tree_host_impl.h
@@ -9,6 +9,7 @@
#include <memory>
#include <set>
+#include <string>
#include <unordered_map>
#include <utility>
#include <vector>
@@ -29,6 +30,7 @@
#include "cc/input/scrollbar_animation_controller.h"
#include "cc/input/scrollbar_controller.h"
#include "cc/layers/layer_collections.h"
+#include "cc/metrics/average_lag_tracking_manager.h"
#include "cc/metrics/dropped_frame_counter.h"
#include "cc/metrics/event_metrics.h"
#include "cc/metrics/events_metrics_manager.h"
@@ -1127,6 +1129,11 @@
void AllocateLocalSurfaceId();
+ // Log the AverageLag events from the frame identified by |frame_token| and
+ // the information in |details|.
+ void LogAverageLagEvents(uint32_t frame_token,
+ const viz::FrameTimingDetails& details);
+
const LayerTreeSettings settings_;
// This is set to true only if:
@@ -1424,6 +1431,8 @@
// invalidating PaintWorklets as the property values change.
AnimatedPaintWorkletTracker paint_worklet_tracker_;
+ AverageLagTrackingManager lag_tracking_manager_;
+
// Helper for de-jelly logic.
DeJellyState de_jelly_state_;