Add app-side event lifetime tracing
This should help figure out / confirm whether there are bugs in the
application input event consumption code.
In this trace, we are adding app-process "InputConsumer processing" tag,
with the cookie = sequence number of the input event.
In this context, input events include everything, like key events,
motion events, focus events, etc. In other words, anything that's being
sent from the InputDispatcher to the receiving window.
When the "finish" is finally successfully written into the fd, we end
the trace.
Therefore, in cases of batching, we would see a few of these events pile
up, until we finally produce a frame that captures all of them.
It would also be interesting to add some app-side benchmarks for this.
We currently collect those in
https://pitot-autopush.corp.google.com/metric_index/Touch%20latency
but they are not broken down by the application.
Test procedure:
1. Add "system tracing" to quick settings from developer options (enable
the quick settings tile for system tracing)
2. Start system tracing via UI of quick settings
3. Open all apps and do some swipes
4. Click "stop tracing"
5. Pull the logs to the device `adb pull /data/local/traces/ ~/trace`
6. Go to https://ui.perfetto.dev/
7. Click "open trace file" and navigate to the local file
8. In the trace, open the process of interest. In this case, it's the
launcher process
9. Scroll down to "InputConsumer processing"
10. The "cookie" field of each entry is the sequence number of this
event (but not the event id).
Bug: 319884471
Test: see procedure
Change-Id: I569d8be51ac7b14f8bf54a00bf027323b96b9808
diff --git a/libs/input/InputTransport.cpp b/libs/input/InputTransport.cpp
index 598f949..fa094df 100644
--- a/libs/input/InputTransport.cpp
+++ b/libs/input/InputTransport.cpp
@@ -867,6 +867,9 @@
mConsumeTimes.emplace(mMsg.header.seq, systemTime(SYSTEM_TIME_MONOTONIC));
LOG_ALWAYS_FATAL_IF(!inserted, "Already have a consume time for seq=%" PRIu32,
mMsg.header.seq);
+
+ // Trace the event processing timeline - event was just read from the socket
+ ATRACE_ASYNC_BEGIN("InputConsumer processing", /*cookie=*/mMsg.header.seq);
}
if (result) {
// Consume the next batched event unless batches are being held for later.
@@ -1405,6 +1408,9 @@
// message anymore. If the socket write did not succeed, we will try again and will still
// need consume time.
popConsumeTime(seq);
+
+ // Trace the event processing timeline - event was just finished
+ ATRACE_ASYNC_END("InputConsumer processing", /*cookie=*/seq);
}
return result;
}