Commit ca42e0d6 authored Jan 12, 2024 by Siarhei Vishniakou

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

parent 5b277ae3

libs/input/InputTransport.cpp

+6 −0

Original line number	Diff line number	Diff line
		@@ -867,6 +867,9 @@ status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consum
		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 @@ status_t InputConsumer::sendUnchainedFinishedSignal(uint32_t seq, bool handled)
		// 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;
		}