[tracing] Add trace events about scroll deltas for scrolling.

Add trace events to help us monitor low-level scrolling signals:
- ScrollTree::ScrollBy
- perfetto::TracedValue support for gfx geometry primitives
- EventForwarder::OnTouchEvent
- List of inputs that were shown together in one GPU frame
- Add frame ids to Graphics.Pipeline event to make it possible to
  correlate this with PipelineReporter.
- Add trace_id to ScrollUpdate EventLatency to be able select all debug traces related to a particular input

# Example of using this tracing data
Screenshot: https://screenshot.googleplex.com/BrKjcNfpSR8V2xP
Script: https://paste.googleplex.com/6052006484508672

PAIR=mekk@chromium.org
PAIR=altimin@chromium.org

Bug: b/266910376
Change-Id: Ib72dcceb1218c77ac083c5ec7cae3e8ef0b6f8c3
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4194682
Reviewed-by: Robert Flack <flackr@chromium.org>
Reviewed-by: Scott Violet <sky@chromium.org>
Reviewed-by: Jonathan Ross <jonross@chromium.org>
Commit-Queue: Violetta Fedotova <violettfaid@google.com>
Cr-Commit-Position: refs/heads/main@{#1101181}

cc/metrics/average_lag_tracking_manager_unittest.cc

@@ -92,10 +92,12 @@ class AverageLagTrackingManagerTest : public testing::Test {
       base::TimeTicks arrived_in_browser_main_timestamp,
       float delta) {
     const bool kScrollIsNotInertial = false;
+    const int64_t trace_id = 123;
     return ScrollUpdateEventMetrics::Create(
         ui::ET_GESTURE_SCROLL_UPDATE, ui::ScrollInputType::kTouchscreen,
         kScrollIsNotInertial, scroll_update_type, delta, event_time,
-        arrived_in_browser_main_timestamp);
+        arrived_in_browser_main_timestamp,
+        base::IdType64<class ui::LatencyInfo>(trace_id));
   }
 
   AverageLagTrackingManager average_lag_tracking_manager_;

cc/metrics/compositor_frame_reporter.cc

@@ -8,6 +8,7 @@
 #include <cstdint>
 #include <memory>
 #include <string>
+#include <type_traits>
 #include <utility>
 
 #include "base/cpu_reduction_experiment.h"
@@ -213,6 +214,42 @@ double DetermineHighestContribution(
   return highest_contribution_change;
 }
 
+void TraceScrollJankMetrics(const EventMetrics::List& events_metrics,
+                            int32_t fling_input_count,
+                            int32_t normal_input_count,
+                            perfetto::EventContext& ctx) {
+  using TraceId = base::IdType64<class ui::LatencyInfo>;
+  auto dict = std::make_unique<base::trace_event::TracedValue>();
+  float delta = 0;
+  float predicted_delta = 0;
+  std::vector<absl::optional<TraceId>> trace_ids;
+  std::vector<float> original_deltas;
+  std::vector<float> predicted_deltas;
+
+  for (const auto& event : events_metrics) {
+    auto type = event->type();
+    if (type != EventMetrics::EventType::kGestureScrollUpdate &&
+        type != EventMetrics::EventType::kFirstGestureScrollUpdate &&
+        type != EventMetrics::EventType::kInertialGestureScrollUpdate) {
+      continue;
+    }
+    original_deltas.push_back(event->AsScrollUpdate()->delta());
+    predicted_deltas.push_back(event->AsScrollUpdate()->predicted_delta());
+    trace_ids.push_back(event->AsScrollUpdate()->trace_id());
+    delta += event->AsScrollUpdate()->delta();
+    predicted_delta += event->AsScrollUpdate()->predicted_delta();
+  }
+  if (trace_ids.empty()) {
+    return;
+  }
+  ctx.AddDebugAnnotation("event_count", fling_input_count + normal_input_count);
+  ctx.AddDebugAnnotation("original_delta", delta);
+  ctx.AddDebugAnnotation("predicted_delta", predicted_delta);
+  ctx.AddDebugAnnotation("trace_ids", trace_ids);
+  ctx.AddDebugAnnotation("segregated_original_deltas", original_deltas);
+  ctx.AddDebugAnnotation("segregated_predicted_deltas", predicted_deltas);
+}
+
 }  // namespace
 
 // CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator ==================
@@ -1334,6 +1371,12 @@ void CompositorFrameReporter::ReportScrollJankMetrics() const {
     }
   }
 
+  TRACE_EVENT("input", "PresentedFrameInformation",
+              [events_metrics = std::cref(events_metrics_), fling_input_count,
+               normal_input_count](perfetto::EventContext& ctx) {
+                TraceScrollJankMetrics(events_metrics, fling_input_count,
+                                       normal_input_count, ctx);
+              });
   // Counting number of inputs per frame for flings and normal input has
   // to be separate as the rate of input generation is different for each
   // of them, normal input is screen generated, and flings are GPU vsync

cc/metrics/event_metrics.cc

@@ -543,17 +543,19 @@ std::unique_ptr<ScrollUpdateEventMetrics> ScrollUpdateEventMetrics::Create(
     ScrollUpdateType scroll_update_type,
     float delta,
     base::TimeTicks timestamp,
-    base::TimeTicks arrived_in_browser_main_timestamp) {
+    base::TimeTicks arrived_in_browser_main_timestamp,
+    TraceId trace_id) {
   // TODO(crbug.com/1157090): We expect that `timestamp` is not null, but there
   // seems to be some tests that are emitting events with null timestamp. We
   // should investigate and try to fix those cases and add a `DCHECK` here to
   // assert `timestamp` is not null.
 
   DCHECK(IsGestureScrollUpdate(type));
 
-  std::unique_ptr<ScrollUpdateEventMetrics> metrics = CreateInternal(
-      type, input_type, is_inertial, scroll_update_type, delta, timestamp,
-      arrived_in_browser_main_timestamp, base::DefaultTickClock::GetInstance());
+  std::unique_ptr<ScrollUpdateEventMetrics> metrics =
+      CreateInternal(type, input_type, is_inertial, scroll_update_type, delta,
+                     timestamp, arrived_in_browser_main_timestamp,
+                     base::DefaultTickClock::GetInstance(), trace_id);
   if (!metrics)
     return nullptr;
 
@@ -569,9 +571,10 @@ ScrollUpdateEventMetrics::CreateForBrowser(ui::EventType type,
                                            bool is_inertial,
                                            ScrollUpdateType scroll_update_type,
                                            float delta,
-                                           base::TimeTicks timestamp) {
+                                           base::TimeTicks timestamp,
+                                           TraceId trace_id) {
   return Create(type, input_type, is_inertial, scroll_update_type, delta,
-                timestamp, base::TimeTicks());
+                timestamp, base::TimeTicks(), trace_id);
 }
 
 // static
@@ -587,9 +590,9 @@ ScrollUpdateEventMetrics::CreateForTesting(
     const base::TickClock* tick_clock) {
   DCHECK(!timestamp.is_null());
 
-  std::unique_ptr<ScrollUpdateEventMetrics> metrics =
-      CreateInternal(type, input_type, is_inertial, scroll_update_type, delta,
-                     timestamp, arrived_in_browser_main_timestamp, tick_clock);
+  std::unique_ptr<ScrollUpdateEventMetrics> metrics = CreateInternal(
+      type, input_type, is_inertial, scroll_update_type, delta, timestamp,
+      arrived_in_browser_main_timestamp, tick_clock, absl::nullopt);
   if (!metrics)
     return nullptr;
 
@@ -616,9 +619,10 @@ ScrollUpdateEventMetrics::CreateFromExisting(
   if (!existing)
     return nullptr;
 
-  std::unique_ptr<ScrollUpdateEventMetrics> metrics = CreateInternal(
-      type, input_type, is_inertial, scroll_update_type, delta,
-      base::TimeTicks(), base::TimeTicks(), existing->tick_clock_);
+  std::unique_ptr<ScrollUpdateEventMetrics> metrics =
+      CreateInternal(type, input_type, is_inertial, scroll_update_type, delta,
+                     base::TimeTicks(), base::TimeTicks(),
+                     existing->tick_clock_, absl::nullopt);
   if (!metrics)
     return nullptr;
 
@@ -639,14 +643,15 @@ ScrollUpdateEventMetrics::CreateInternal(
     float delta,
     base::TimeTicks timestamp,
     base::TimeTicks arrived_in_browser_main_timestamp,
-    const base::TickClock* tick_clock) {
+    const base::TickClock* tick_clock,
+    absl::optional<TraceId> trace_id) {
   absl::optional<EventType> interesting_type =
       ToInterestingEventType(type, is_inertial, scroll_update_type);
   if (!interesting_type)
     return nullptr;
   return base::WrapUnique(new ScrollUpdateEventMetrics(
       *interesting_type, ToScrollType(input_type), scroll_update_type, delta,
-      timestamp, arrived_in_browser_main_timestamp, tick_clock));
+      timestamp, arrived_in_browser_main_timestamp, tick_clock, trace_id));
 }
 
 ScrollUpdateEventMetrics::ScrollUpdateEventMetrics(
@@ -656,15 +661,17 @@ ScrollUpdateEventMetrics::ScrollUpdateEventMetrics(
     float delta,
     base::TimeTicks timestamp,
     base::TimeTicks arrived_in_browser_main_timestamp,
-    const base::TickClock* tick_clock)
+    const base::TickClock* tick_clock,
+    absl::optional<TraceId> trace_id)
     : ScrollEventMetrics(type,
                          scroll_type,
                          timestamp,
                          arrived_in_browser_main_timestamp,
                          tick_clock),
       delta_(delta),
       predicted_delta_(delta),
-      last_timestamp_(timestamp) {}
+      last_timestamp_(timestamp),
+      trace_id_(trace_id) {}
 
 ScrollUpdateEventMetrics::ScrollUpdateEventMetrics(
     const ScrollUpdateEventMetrics&) = default;

cc/metrics/event_metrics.h

@@ -13,11 +13,12 @@
 #include "base/memory/raw_ptr.h"
 #include "base/time/tick_clock.h"
 #include "base/time/time.h"
+#include "base/types/id_type.h"
 #include "cc/cc_export.h"
 #include "third_party/abseil-cpp/absl/types/optional.h"
 #include "ui/events/types/event_type.h"
 #include "ui/events/types/scroll_input_type.h"
-
+#include "ui/latency/latency_info.h"
 namespace cc {
 class PinchEventMetrics;
 class ScrollEventMetrics;
@@ -28,7 +29,7 @@ class ScrollUpdateEventMetrics;
 class CC_EXPORT EventMetrics {
  public:
   using List = std::vector<std::unique_ptr<EventMetrics>>;
-
+  using TraceId = base::IdType64<class ui::LatencyInfo>;
   // Event types we are interested in. This list should be in the same order as
   // values of EventLatencyEventType enum from enums.xml file.
   enum class EventType {
@@ -328,7 +329,8 @@ class CC_EXPORT ScrollUpdateEventMetrics : public ScrollEventMetrics {
       ScrollUpdateType scroll_update_type,
       float delta,
       base::TimeTicks timestamp,
-      base::TimeTicks arrived_in_browser_main_timestamp);
+      base::TimeTicks arrived_in_browser_main_timestamp,
+      TraceId trace_id);
 
   // Prefer to use `Create()` above. This method is used only by the Browser
   // process which have own breakdowns.
@@ -339,7 +341,8 @@ class CC_EXPORT ScrollUpdateEventMetrics : public ScrollEventMetrics {
       bool is_inertial,
       ScrollUpdateType scroll_update_type,
       float delta,
-      base::TimeTicks timestamp);
+      base::TimeTicks timestamp,
+      TraceId trace_id);
 
   // Similar to `Create()` with an extra `base::TickClock` to use in tests.
   // Should only be used for scroll-update events.
@@ -380,6 +383,9 @@ class CC_EXPORT ScrollUpdateEventMetrics : public ScrollEventMetrics {
   float predicted_delta() const { return predicted_delta_; }
 
   int32_t coalesced_event_count() { return coalesced_event_count_; }
+
+  absl::optional<TraceId> trace_id() { return trace_id_; }
+
   void set_predicted_delta(float predicted_delta) {
     predicted_delta_ = predicted_delta;
   }
@@ -395,7 +401,8 @@ class CC_EXPORT ScrollUpdateEventMetrics : public ScrollEventMetrics {
                            float delta,
                            base::TimeTicks timestamp,
                            base::TimeTicks arrived_in_browser_main_timestamp,
-                           const base::TickClock* tick_clock);
+                           const base::TickClock* tick_clock,
+                           absl::optional<TraceId> trace_id);
   ScrollUpdateEventMetrics(const ScrollUpdateEventMetrics&);
 
  private:
@@ -407,7 +414,8 @@ class CC_EXPORT ScrollUpdateEventMetrics : public ScrollEventMetrics {
       float delta,
       base::TimeTicks timestamp,
       base::TimeTicks arrived_in_browser_main_timestamp,
-      const base::TickClock* tick_clock);
+      const base::TickClock* tick_clock,
+      absl::optional<TraceId> trace_id);
 
   float delta_;
   float predicted_delta_;
@@ -417,6 +425,10 @@ class CC_EXPORT ScrollUpdateEventMetrics : public ScrollEventMetrics {
 
   // Total events that were coalesced into this into this ScrollUpdate
   int32_t coalesced_event_count_ = 1;
+  // This is a trace id of an input event. It can be null for events which don't
+  // have a corresponding input, for example a generated event based on existing
+  // event.
+  absl::optional<TraceId> trace_id_;
 };
 
 class CC_EXPORT PinchEventMetrics : public EventMetrics {

cc/metrics/event_metrics_unittest.cc

@@ -9,6 +9,8 @@
 
 namespace cc {
 namespace {
+
+using TraceId = base::IdType64<class ui::LatencyInfo>;
 class EventMetricsTest : public testing::Test {
  private:
   base::SimpleTestTickClock test_tick_clock_;
@@ -161,16 +163,18 @@ TEST_F(EventMetricsTest, ScrollUpdateCreateWithNullBeginRwhTime) {
   base::TimeTicks event_time = base::TimeTicks::Now() - base::Microseconds(100);
   base::TimeTicks arrived_in_browser_main_timestamp;
   base::TimeTicks now = base::TimeTicks::Now();
+  TraceId trace_id(123);
 
   // Act
   std::unique_ptr<ScrollUpdateEventMetrics> scroll_event_metric =
       ScrollUpdateEventMetrics::Create(
           ui::ET_GESTURE_SCROLL_UPDATE, ui::ScrollInputType::kTouchscreen,
           /*is_inertial=*/false,
           ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, /*delta=*/0.4,
-          event_time, arrived_in_browser_main_timestamp);
+          event_time, arrived_in_browser_main_timestamp, trace_id);
 
   // Assert
+  EXPECT_EQ(trace_id, scroll_event_metric->trace_id());
   EXPECT_EQ(event_time, scroll_event_metric->GetDispatchStageTimestamp(
                             EventMetrics::DispatchStage::kGenerated));
   EXPECT_LE(now,
@@ -205,16 +209,18 @@ TEST_F(EventMetricsTest, ScrollUpdateCreate) {
   base::TimeTicks arrived_in_browser_main_timestamp =
       base::TimeTicks::Now() - base::Microseconds(50);
   base::TimeTicks now = base::TimeTicks::Now();
+  TraceId trace_id(123);
 
   // Act
   std::unique_ptr<ScrollUpdateEventMetrics> scroll_event_metric =
       ScrollUpdateEventMetrics::Create(
           ui::ET_GESTURE_SCROLL_UPDATE, ui::ScrollInputType::kTouchscreen,
           /*is_inertial=*/false,
           ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, /*delta=*/0.4,
-          event_time, arrived_in_browser_main_timestamp);
+          event_time, arrived_in_browser_main_timestamp, TraceId(trace_id));
 
   // Assert
+  EXPECT_EQ(trace_id, scroll_event_metric->trace_id());
   EXPECT_EQ(event_time, scroll_event_metric->GetDispatchStageTimestamp(
                             EventMetrics::DispatchStage::kGenerated));
   EXPECT_EQ(arrived_in_browser_main_timestamp,
@@ -247,12 +253,13 @@ TEST_F(EventMetricsTest, ScrollUpdateCreateFromExisting) {
   base::TimeTicks event_time = base::TimeTicks::Now() - base::Microseconds(100);
   base::TimeTicks arrived_in_browser_main_timestamp =
       base::TimeTicks::Now() - base::Microseconds(50);
+  TraceId trace_id(123);
   std::unique_ptr<ScrollUpdateEventMetrics> scroll_metric =
       ScrollUpdateEventMetrics::Create(
           ui::ET_GESTURE_SCROLL_UPDATE, ui::ScrollInputType::kTouchscreen,
           /*is_inertial=*/false,
           ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, /*delta=*/0.4,
-          event_time, arrived_in_browser_main_timestamp);
+          event_time, arrived_in_browser_main_timestamp, trace_id);
 
   // Act
   std::unique_ptr<ScrollUpdateEventMetrics> copy_scroll_metric =
@@ -264,6 +271,7 @@ TEST_F(EventMetricsTest, ScrollUpdateCreateFromExisting) {
           scroll_metric.get());
 
   // Assert
+  EXPECT_NE(scroll_metric->trace_id(), copy_scroll_metric->trace_id());
   EXPECT_EQ(scroll_metric->GetDispatchStageTimestamp(
                 EventMetrics::DispatchStage::kGenerated),
             copy_scroll_metric->GetDispatchStageTimestamp(

cc/mojo_embedder/async_layer_tree_frame_sink.cc

@@ -272,10 +272,10 @@ void AsyncLayerTreeFrameSink::OnBeginFrame(
                        FrameSkippedReason::kNoDamage);
     return;
   }
-  TRACE_EVENT_WITH_FLOW1("viz,benchmark", "Graphics.Pipeline",
-                         TRACE_ID_GLOBAL(args.trace_id),
-                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT,
-                         "step", "ReceiveBeginFrame");
+  TRACE_EVENT_WITH_FLOW2(
+      "viz,benchmark", "Graphics.Pipeline", TRACE_ID_GLOBAL(args.trace_id),
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT, "step",
+      "ReceiveBeginFrame", "frame_sequence", args.frame_id.sequence_number);
 
   if (begin_frame_source_)
     begin_frame_source_->OnBeginFrame(args);

cc/trees/layer_tree_host_impl_unittest.cc

@@ -14289,7 +14289,8 @@ TEST_F(LayerTreeHostImplTest,
         i == 0 ? ScrollUpdateEventMetrics::ScrollUpdateType::kStarted
                : ScrollUpdateEventMetrics::ScrollUpdateType::kContinued,
         /*delta=*/10.0f, base::TimeTicks::Now(),
-        base::TimeTicks::Now() + base::Milliseconds(1)));
+        base::TimeTicks::Now() + base::Milliseconds(1),
+        /*trace_id*/ base::IdType64<class ui::LatencyInfo>(123)));
     host_impl_->active_tree()->AppendEventsMetricsFromMainThread(
         std::move(events_metrics));
 

cc/trees/property_tree.cc

@@ -1896,6 +1896,8 @@ const gfx::Vector2dF ScrollTree::GetScrollOffsetDeltaForTesting(
 gfx::Vector2dF ScrollTree::ScrollBy(const ScrollNode& scroll_node,
                                     const gfx::Vector2dF& scroll,
                                     LayerTreeImpl* layer_tree_impl) {
+  TRACE_EVENT_BEGIN("input", "ScrollTree::ScrollBy", "scroll", scroll,
+                    "scroll_node_id", scroll_node.id);
   gfx::Vector2dF adjusted_scroll(scroll);
   if (!scroll_node.user_scrollable_horizontal)
     adjusted_scroll.set_x(0);
@@ -1908,6 +1910,9 @@ gfx::Vector2dF ScrollTree::ScrollBy(const ScrollNode& scroll_node,
   if (SetScrollOffset(scroll_node.element_id, new_offset))
     layer_tree_impl->DidUpdateScrollOffset(scroll_node.element_id);
 
+  TRACE_EVENT_END("input", /* ScrollTree::ScrollBy */
+                  "old_offset", old_offset, "new_offset", new_offset);
+
   // Return the amount of scroll delta we could not consume for this node.
   return old_offset + scroll - new_offset;
 }

content/browser/renderer_host/input/input_router_impl.cc

@@ -67,7 +67,7 @@ std::unique_ptr<blink::WebCoalescedInputEvent> ScaleEvent(
     double scale,
     const ui::LatencyInfo& latency_info) {
   std::unique_ptr<blink::WebInputEvent> event_in_viewport =
-      ui::ScaleWebInputEvent(event, scale);
+      ui::ScaleWebInputEvent(event, scale, latency_info.trace_id());
   return std::make_unique<blink::WebCoalescedInputEvent>(
       event_in_viewport ? std::move(event_in_viewport) : event.Clone(),
       std::vector<std::unique_ptr<WebInputEvent>>(),