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
diff --git a/services/inputflinger/dispatcher/InputDispatcher.cpp b/services/inputflinger/dispatcher/InputDispatcher.cpp
index 5ed5eb8..347f106 100644
--- a/services/inputflinger/dispatcher/InputDispatcher.cpp
+++ b/services/inputflinger/dispatcher/InputDispatcher.cpp
@@ -879,7 +879,7 @@
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 @@
~ScopedSyntheticEventTracer() {
if (mTracer) {
- mTracer->eventProcessingComplete(*mEventTracker);
+ mTracer->eventProcessingComplete(*mEventTracker, mProcessingTimestamp);
}
}
@@ -896,8 +896,9 @@
}
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 @@
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 a1a87af..5d2b854 100644
--- a/services/inputflinger/dispatcher/trace/InputTracer.cpp
+++ b/services/inputflinger/dispatcher/trace/InputTracer.cpp
@@ -145,7 +145,8 @@
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 @@
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 @@
// --- 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 @@
// 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 ab175be..cb525a4 100644
--- a/services/inputflinger/dispatcher/trace/InputTracer.h
+++ b/services/inputflinger/dispatcher/trace/InputTracer.h
@@ -44,7 +44,8 @@
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 @@
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 af6eefb..f5e4e59 100644
--- a/services/inputflinger/dispatcher/trace/InputTracerInterface.h
+++ b/services/inputflinger/dispatcher/trace/InputTracerInterface.h
@@ -81,7 +81,8 @@
* 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 25099c3..761d619 100644
--- a/services/inputflinger/dispatcher/trace/InputTracingBackendInterface.h
+++ b/services/inputflinger/dispatcher/trace/InputTracingBackendInterface.h
@@ -99,6 +99,8 @@
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 3d30ad6..77b5c2e 100644
--- a/services/inputflinger/dispatcher/trace/InputTracingPerfettoBackend.cpp
+++ b/services/inputflinger/dispatcher/trace/InputTracingPerfettoBackend.cpp
@@ -231,6 +231,8 @@
}
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 @@
}
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 @@
}
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 a9d370a..db4e761 100644
--- a/services/inputflinger/tests/InputTraceSession.cpp
+++ b/services/inputflinger/tests/InputTraceSession.cpp
@@ -103,6 +103,11 @@
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(),