InputTracer: Add timestamp to perfetto trace packets

Use the event processing time as the packet timestamp for input events,
and use the delivery time as the packet timestamp for dispatch events.

Bug: 332714237
Bug: 210460522
Test: atest inputflinger_tests
Test: manual with perfetto
Change-Id: I30f4c21dfee68603d0dad01d205f8a5581e6db31

7 files changed, 29 insertions, 11 deletions

diff --git a/services/inputflinger/dispatcher/InputDispatcher.cpp b/services/inputflinger/dispatcher/InputDispatcher.cpp
index 5ed5eb8e33..347f106686 100644
--- a/services/inputflinger/dispatcher/InputDispatcher.cpp
+++ b/services/inputflinger/dispatcher/InputDispatcher.cpp
@@ -879,7 +879,7 @@ std::pair<bool /*cancelPointers*/, bool /*cancelNonPointers*/> expandCancellatio
 class ScopedSyntheticEventTracer {
 public:
     ScopedSyntheticEventTracer(std::unique_ptr<trace::InputTracerInterface>& tracer)
-          : mTracer(tracer) {
+          : mTracer(tracer), mProcessingTimestamp(now()) {
         if (mTracer) {
             mEventTracker = mTracer->createTrackerForSyntheticEvent();
         }
@@ -887,7 +887,7 @@ public:
 
     ~ScopedSyntheticEventTracer() {
         if (mTracer) {
-            mTracer->eventProcessingComplete(*mEventTracker);
+            mTracer->eventProcessingComplete(*mEventTracker, mProcessingTimestamp);
         }
     }
 
@@ -896,8 +896,9 @@ public:
     }
 
 private:
-    std::unique_ptr<trace::InputTracerInterface>& mTracer;
+    const std::unique_ptr<trace::InputTracerInterface>& mTracer;
     std::unique_ptr<trace::EventTrackerInterface> mEventTracker;
+    const nsecs_t mProcessingTimestamp;
 };
 
 } // namespace
@@ -1263,7 +1264,7 @@ void InputDispatcher::dispatchOnceInnerLocked(nsecs_t& nextWakeupTime) {
 
         if (mTracer) {
             if (auto& traceTracker = getTraceTracker(*mPendingEvent); traceTracker != nullptr) {
-                mTracer->eventProcessingComplete(*traceTracker);
+                mTracer->eventProcessingComplete(*traceTracker, currentTime);
             }
         }
 
diff --git a/services/inputflinger/dispatcher/trace/InputTracer.cpp b/services/inputflinger/dispatcher/trace/InputTracer.cpp
index a1a87afd04..5d2b8541d1 100644
--- a/services/inputflinger/dispatcher/trace/InputTracer.cpp
+++ b/services/inputflinger/dispatcher/trace/InputTracer.cpp
@@ -145,7 +145,8 @@ void InputTracer::dispatchToTargetHint(const EventTrackerInterface& cookie,
     eventState->metadata.isSecure |= targetInfo.isSecureWindow;
 }
 
-void InputTracer::eventProcessingComplete(const EventTrackerInterface& cookie) {
+void InputTracer::eventProcessingComplete(const EventTrackerInterface& cookie,
+                                          nsecs_t processingTimestamp) {
     if (isDerivedCookie(cookie)) {
         LOG(FATAL) << "Event processing cannot be set from a derived cookie.";
     }
@@ -154,7 +155,7 @@ void InputTracer::eventProcessingComplete(const EventTrackerInterface& cookie) {
         LOG(FATAL) << "Traced event was already logged. "
                       "eventProcessingComplete() was likely called more than once.";
     }
-    eventState->onEventProcessingComplete();
+    eventState->onEventProcessingComplete(processingTimestamp);
 }
 
 std::unique_ptr<EventTrackerInterface> InputTracer::traceDerivedEvent(
@@ -242,7 +243,8 @@ bool InputTracer::isDerivedCookie(const EventTrackerInterface& cookie) {
 
 // --- InputTracer::EventState ---
 
-void InputTracer::EventState::onEventProcessingComplete() {
+void InputTracer::EventState::onEventProcessingComplete(nsecs_t processingTimestamp) {
+    metadata.processingTimestamp = processingTimestamp;
     metadata.isImeConnectionActive = tracer.mIsImeConnectionActive;
 
     // Write all of the events known so far to the trace.
@@ -277,7 +279,7 @@ InputTracer::EventState::~EventState() {
     // We should never end up here in normal operation. However, in tests, it's possible that we
     // stop and destroy InputDispatcher without waiting for it to finish processing events, at
     // which point an event (and thus its EventState) may be destroyed before processing finishes.
-    onEventProcessingComplete();
+    onEventProcessingComplete(systemTime(CLOCK_MONOTONIC));
 }
 
 } // namespace android::inputdispatcher::trace::impl
diff --git a/services/inputflinger/dispatcher/trace/InputTracer.h b/services/inputflinger/dispatcher/trace/InputTracer.h
index ab175bef4a..cb525a4a92 100644
--- a/services/inputflinger/dispatcher/trace/InputTracer.h
+++ b/services/inputflinger/dispatcher/trace/InputTracer.h
@@ -44,7 +44,8 @@ public:
     std::unique_ptr<EventTrackerInterface> traceInboundEvent(const EventEntry&) override;
     std::unique_ptr<EventTrackerInterface> createTrackerForSyntheticEvent() override;
     void dispatchToTargetHint(const EventTrackerInterface&, const InputTarget&) override;
-    void eventProcessingComplete(const EventTrackerInterface&) override;
+    void eventProcessingComplete(const EventTrackerInterface&,
+                                 nsecs_t processingTimestamp) override;
     std::unique_ptr<EventTrackerInterface> traceDerivedEvent(const EventEntry&,
                                                              const EventTrackerInterface&) override;
     void traceEventDispatch(const DispatchEntry&, const EventTrackerInterface&) override;
@@ -61,7 +62,7 @@ private:
         explicit inline EventState(InputTracer& tracer) : tracer(tracer){};
         ~EventState();
 
-        void onEventProcessingComplete();
+        void onEventProcessingComplete(nsecs_t processingTimestamp);
 
         InputTracer& tracer;
         std::vector<const TracedEvent> events;
diff --git a/services/inputflinger/dispatcher/trace/InputTracerInterface.h b/services/inputflinger/dispatcher/trace/InputTracerInterface.h
index af6eefb1db..f5e4e592bb 100644
--- a/services/inputflinger/dispatcher/trace/InputTracerInterface.h
+++ b/services/inputflinger/dispatcher/trace/InputTracerInterface.h
@@ -81,7 +81,8 @@ public:
      * outside of our control, such as how long apps take to respond, so we don't want to depend on
      * that.
      */
-    virtual void eventProcessingComplete(const EventTrackerInterface&) = 0;
+    virtual void eventProcessingComplete(const EventTrackerInterface&,
+                                         nsecs_t processingTimestamp) = 0;
 
     /**
      * Trace an input event that is derived from another event. This is used in cases where an event
diff --git a/services/inputflinger/dispatcher/trace/InputTracingBackendInterface.h b/services/inputflinger/dispatcher/trace/InputTracingBackendInterface.h
index 25099c3199..761d619cec 100644
--- a/services/inputflinger/dispatcher/trace/InputTracingBackendInterface.h
+++ b/services/inputflinger/dispatcher/trace/InputTracingBackendInterface.h
@@ -99,6 +99,8 @@ struct TracedEventMetadata {
     std::set<gui::Uid> targets;
     // True if the there was an active input method connection while this event was processed.
     bool isImeConnectionActive;
+    // The timestamp for when the dispatching decisions were made for the event by the system.
+    nsecs_t processingTimestamp;
 };
 
 /** Additional information about an input event being dispatched to a window. */
diff --git a/services/inputflinger/dispatcher/trace/InputTracingPerfettoBackend.cpp b/services/inputflinger/dispatcher/trace/InputTracingPerfettoBackend.cpp
index 3d30ad6c7b..77b5c2ebcd 100644
--- a/services/inputflinger/dispatcher/trace/InputTracingPerfettoBackend.cpp
+++ b/services/inputflinger/dispatcher/trace/InputTracingPerfettoBackend.cpp
@@ -231,6 +231,8 @@ void PerfettoBackend::traceMotionEvent(const TracedMotionEvent& event,
         }
         const bool isRedacted = traceLevel == TraceLevel::TRACE_LEVEL_REDACTED;
         auto tracePacket = ctx.NewTracePacket();
+        tracePacket->set_timestamp(metadata.processingTimestamp);
+        tracePacket->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
         auto* winscopeExtensions = static_cast<perfetto::protos::pbzero::WinscopeExtensionsImpl*>(
                 tracePacket->set_winscope_extensions());
         auto* inputEvent = winscopeExtensions->set_android_input_event();
@@ -257,6 +259,8 @@ void PerfettoBackend::traceKeyEvent(const TracedKeyEvent& event,
         }
         const bool isRedacted = traceLevel == TraceLevel::TRACE_LEVEL_REDACTED;
         auto tracePacket = ctx.NewTracePacket();
+        tracePacket->set_timestamp(metadata.processingTimestamp);
+        tracePacket->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
         auto* winscopeExtensions = static_cast<perfetto::protos::pbzero::WinscopeExtensionsImpl*>(
                 tracePacket->set_winscope_extensions());
         auto* inputEvent = winscopeExtensions->set_android_input_event();
@@ -283,6 +287,8 @@ void PerfettoBackend::traceWindowDispatch(const WindowDispatchArgs& dispatchArgs
         }
         const bool isRedacted = traceLevel == TraceLevel::TRACE_LEVEL_REDACTED;
         auto tracePacket = ctx.NewTracePacket();
+        tracePacket->set_timestamp(dispatchArgs.deliveryTime);
+        tracePacket->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
         auto* winscopeExtensions = static_cast<perfetto::protos::pbzero::WinscopeExtensionsImpl*>(
                 tracePacket->set_winscope_extensions());
         auto* inputEvent = winscopeExtensions->set_android_input_event();
diff --git a/services/inputflinger/tests/InputTraceSession.cpp b/services/inputflinger/tests/InputTraceSession.cpp
index a9d370aedd..db4e761162 100644
--- a/services/inputflinger/tests/InputTraceSession.cpp
+++ b/services/inputflinger/tests/InputTraceSession.cpp
@@ -103,6 +103,11 @@ auto decodeTrace(const std::string& rawTrace) {
                 continue;
             }
 
+            EXPECT_TRUE(packet.has_timestamp());
+            EXPECT_TRUE(packet.has_timestamp_clock_id());
+            EXPECT_EQ(packet.timestamp_clock_id(),
+                      static_cast<uint32_t>(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC));
+
             AndroidInputEvent::Decoder event{field.as_bytes()};
             if (event.has_dispatcher_motion_event()) {
                 tracedMotions.emplace_back(event.dispatcher_motion_event(),