Add LatencyTracker to InputDispatcher
LatencyTracker will be used to record the complete timeline of an input
event dispatch, from the kernel to the presentation of a graphics frame
to the display.
The data about input event timeline is coming from three different
locations:
1) notifyMotion: this is when the InputDispatcher first learns about the
event from InputReader. At this point, we learn the time when the event
was first created, to time when the event was read by the user space,
and we are now adding the timestamps when the InputReader notifies the
dispatcher about the event.
2) finishInputEvent: this is when the app sends an 'ack' that a specific
input event has been processed. Through this call, we learn about when
the event was first sent to the app, and when it was read by the app. At
this time, we are also collecting the 'finishTime', so that we can
measure the total time that the app spent processing the event.
3) sendTimeline: this is when the SurfaceFlinger notifies the app about
the metrics for a specific frame. This metrics information is passed
down through the InputChannel to the InputDispatcher. Here we learn
about the time when the app sent the buffer to the SurfaceFlinger
(gpuCompletedTime), and the time when the frame was presented
(presentTime).
Overall, the end-to-end touch latency is presentTime - eventTime.
The rest of the data can be used to measure the breakdown of this
latency.
The goal of LatencyTracker is to combine all this data and present a
complete, unified timeline for a specific input event for further data analysis.
In a separate CL, we will report this complete timeline to statsd.
Bug: 169866723
Test: atest inputflinger_tests
Change-Id: I6e6e80e3393878fe86f3935c7c0e13dfff8629f9
diff --git a/services/inputflinger/dispatcher/LatencyTracker.cpp b/services/inputflinger/dispatcher/LatencyTracker.cpp
new file mode 100644
index 0000000..d634dcd
--- /dev/null
+++ b/services/inputflinger/dispatcher/LatencyTracker.cpp
@@ -0,0 +1,183 @@
+/*
+ * Copyright (C) 2021 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#define LOG_TAG "LatencyTracker"
+#include "LatencyTracker.h"
+
+#include <inttypes.h>
+
+#include <android-base/properties.h>
+#include <android-base/stringprintf.h>
+#include <android/os/IInputConstants.h>
+#include <input/Input.h>
+#include <log/log.h>
+
+using android::base::HwTimeoutMultiplier;
+using android::base::StringPrintf;
+
+namespace android::inputdispatcher {
+
+/**
+ * Events that are older than this time will be considered mature, at which point we will stop
+ * waiting for the apps to provide further information about them.
+ * It's likely that the apps will ANR if the events are not received by this deadline, and we
+ * already track ANR metrics separately.
+ */
+const std::chrono::duration ANR_TIMEOUT = std::chrono::milliseconds(
+ android::os::IInputConstants::UNMULTIPLIED_DEFAULT_DISPATCHING_TIMEOUT_MILLIS *
+ HwTimeoutMultiplier());
+
+static bool isMatureEvent(nsecs_t eventTime, nsecs_t now) {
+ std::chrono::duration age = std::chrono::nanoseconds(now) - std::chrono::nanoseconds(eventTime);
+ return age > ANR_TIMEOUT;
+}
+
+/**
+ * A multimap allows to have several entries with the same key. This function just erases a specific
+ * key-value pair. Equivalent to the imaginary std api std::multimap::erase(key, value).
+ */
+template <typename K, typename V>
+static void eraseByKeyAndValue(std::multimap<K, V>& map, K key, V value) {
+ auto iterpair = map.equal_range(key);
+
+ for (auto it = iterpair.first; it != iterpair.second; ++it) {
+ if (it->second == value) {
+ map.erase(it);
+ break;
+ }
+ }
+}
+
+LatencyTracker::LatencyTracker(InputEventTimelineProcessor* processor)
+ : mTimelineProcessor(processor) {
+ LOG_ALWAYS_FATAL_IF(processor == nullptr);
+}
+
+void LatencyTracker::trackListener(int32_t inputEventId, bool isDown, nsecs_t eventTime,
+ nsecs_t readTime) {
+ reportAndPruneMatureRecords(eventTime);
+ const auto it = mTimelines.find(inputEventId);
+ if (it != mTimelines.end()) {
+ // Input event ids are randomly generated, so it's possible that two events have the same
+ // event id. Drop this event, and also drop the existing event because the apps would
+ // confuse us by reporting the rest of the timeline for one of them. This should happen
+ // rarely, so we won't lose much data
+ mTimelines.erase(it);
+ // In case we have another input event with a different id and at the same eventTime,
+ // only erase this specific inputEventId.
+ eraseByKeyAndValue(mEventTimes, eventTime, inputEventId);
+ return;
+ }
+ mTimelines.emplace(inputEventId, InputEventTimeline(isDown, eventTime, readTime));
+ mEventTimes.emplace(eventTime, inputEventId);
+}
+
+void LatencyTracker::trackFinishedEvent(int32_t inputEventId, const sp<IBinder>& connectionToken,
+ nsecs_t deliveryTime, nsecs_t consumeTime,
+ nsecs_t finishTime) {
+ const auto it = mTimelines.find(inputEventId);
+ if (it == mTimelines.end()) {
+ // It's possible that an app sends a bad (or late)'Finish' signal, since it's free to do
+ // anything in its process. Just drop the report and move on.
+ return;
+ }
+
+ InputEventTimeline& timeline = it->second;
+ const auto connectionIt = timeline.connectionTimelines.find(connectionToken);
+ if (connectionIt == timeline.connectionTimelines.end()) {
+ // Most likely case: app calls 'finishInputEvent' before it reports the graphics timeline
+ timeline.connectionTimelines.emplace(connectionToken,
+ ConnectionTimeline{deliveryTime, consumeTime,
+ finishTime});
+ } else {
+ // Already have a record for this connectionToken
+ ConnectionTimeline& connectionTimeline = connectionIt->second;
+ const bool success =
+ connectionTimeline.setDispatchTimeline(deliveryTime, consumeTime, finishTime);
+ if (!success) {
+ // We are receiving unreliable data from the app. Just delete the entire connection
+ // timeline for this event
+ timeline.connectionTimelines.erase(connectionIt);
+ }
+ }
+}
+
+void LatencyTracker::trackGraphicsLatency(
+ int32_t inputEventId, const sp<IBinder>& connectionToken,
+ std::array<nsecs_t, GraphicsTimeline::SIZE> graphicsTimeline) {
+ const auto it = mTimelines.find(inputEventId);
+ if (it == mTimelines.end()) {
+ // It's possible that an app sends a bad (or late) 'Timeline' signal, since it's free to do
+ // anything in its process. Just drop the report and move on.
+ return;
+ }
+
+ InputEventTimeline& timeline = it->second;
+ const auto connectionIt = timeline.connectionTimelines.find(connectionToken);
+ if (connectionIt == timeline.connectionTimelines.end()) {
+ timeline.connectionTimelines.emplace(connectionToken, std::move(graphicsTimeline));
+ } else {
+ // Most likely case
+ ConnectionTimeline& connectionTimeline = connectionIt->second;
+ const bool success = connectionTimeline.setGraphicsTimeline(std::move(graphicsTimeline));
+ if (!success) {
+ // We are receiving unreliable data from the app. Just delete the entire connection
+ // timeline for this event
+ timeline.connectionTimelines.erase(connectionIt);
+ }
+ }
+}
+
+/**
+ * We should use the current time 'now()' here to determine the age of the event, but instead we
+ * are using the latest 'eventTime' for efficiency since this time is already acquired, and
+ * 'trackListener' should happen soon after the event occurs.
+ */
+void LatencyTracker::reportAndPruneMatureRecords(nsecs_t newEventTime) {
+ while (!mEventTimes.empty()) {
+ const auto& [oldestEventTime, oldestInputEventId] = *mEventTimes.begin();
+ if (isMatureEvent(oldestEventTime, newEventTime /*now*/)) {
+ // Report and drop this event
+ const auto it = mTimelines.find(oldestInputEventId);
+ LOG_ALWAYS_FATAL_IF(it == mTimelines.end(),
+ "Event %" PRId32 " is in mEventTimes, but not in mTimelines",
+ oldestInputEventId);
+ const InputEventTimeline& timeline = it->second;
+ mTimelineProcessor->processTimeline(timeline);
+ mTimelines.erase(it);
+ mEventTimes.erase(mEventTimes.begin());
+ } else {
+ // If the oldest event does not need to be pruned, no events should be pruned.
+ return;
+ }
+ }
+}
+
+void LatencyTracker::reportNow() {
+ for (const auto& [inputEventId, timeline] : mTimelines) {
+ mTimelineProcessor->processTimeline(timeline);
+ }
+ mTimelines.clear();
+ mEventTimes.clear();
+}
+
+std::string LatencyTracker::dump(const char* prefix) {
+ return StringPrintf("%sLatencyTracker:\n", prefix) +
+ StringPrintf("%s mTimelines.size() = %zu\n", prefix, mTimelines.size()) +
+ StringPrintf("%s mEventTimes.size() = %zu\n", prefix, mEventTimes.size());
+}
+
+} // namespace android::inputdispatcher