Fully delete duplicate entries inside LatencyTracker
Inside LatencyTracker, we use 2 collections that must always be in sync:
mTimelines and mEventTimes.
However, when duplicate input events are encountered, we do not treat
these collections equally. In one of them, we fully remove all data
associated with the duplicate inputEventId. In the other one, however,
we only remove the entry that matches both the inputEventId and the
eventTime. This means that the two collections will get out of sync,
because the entry with the mismatching eventTime will be kept in
mEventTimes.
To fix this, fully remove all entries with the duplicate inputEventId,
no matter what the eventTime is. Unfortunately, it means that we have to
traverse the entire collection of mEventTimes. However, since this event
should not occur often, it should not impact performance.
This issue was discovered via the use of the newly added fuzzer for
LatencyTracker. The fuzzer would hit this condition in about 2 seconds
after the run has started. This issue could have been identified the
fuzzer was in place from the start.
The removal of api 'reportNow':
The api 'reportNow' was added for convenience of writing tests. However,
this api has reduced the code coverage, since we would now short-circuit
the code around 'trackListener' that was responsible for event
reporting. This is why, when the issue was first being worked on, the
tests for duplicate events did not yield any crashes. To avoid such
problems in the future, fully remove this api and replace with a
'triggerEventReporting' method that's defined in the tests. This way,
the api's that are used by production code and by tests are identical.
Bug: 169866723
Bug: 205511073
Test: m inputflinger_latencytracker_fuzzer && adb sync data && adb shell /data/fuzz/arm64/inputflinger_latencytracker_fuzzer/inputflinger_latencytracker_fuzzer
Test: atest inputflinger_tests:LatencyTrackerTest
Change-Id: I04069cf2c9eb1154e3324b25c8c4bdff32d84d3f
Merged-In: I04069cf2c9eb1154e3324b25c8c4bdff32d84d3f
diff --git a/services/inputflinger/tests/LatencyTracker_test.cpp b/services/inputflinger/tests/LatencyTracker_test.cpp
index e7e1937..89c0741 100644
--- a/services/inputflinger/tests/LatencyTracker_test.cpp
+++ b/services/inputflinger/tests/LatencyTracker_test.cpp
@@ -16,6 +16,7 @@
#include "../dispatcher/LatencyTracker.h"
+#include <android-base/properties.h>
#include <binder/Binder.h>
#include <gtest/gtest.h>
#include <inttypes.h>
@@ -23,11 +24,16 @@
#define TAG "LatencyTracker_test"
+using android::base::HwTimeoutMultiplier;
using android::inputdispatcher::InputEventTimeline;
using android::inputdispatcher::LatencyTracker;
namespace android::inputdispatcher {
+const std::chrono::duration ANR_TIMEOUT = std::chrono::milliseconds(
+ android::os::IInputConstants::UNMULTIPLIED_DEFAULT_DISPATCHING_TIMEOUT_MILLIS *
+ HwTimeoutMultiplier());
+
InputEventTimeline getTestTimeline() {
InputEventTimeline t(
/*isDown*/ true,
@@ -57,6 +63,8 @@
}
void TearDown() override {}
+ void triggerEventReporting(nsecs_t lastEventTime);
+
void assertReceivedTimeline(const InputEventTimeline& timeline);
/**
* Timelines can be received in any order (order is not guaranteed). So if we are expecting more
@@ -72,8 +80,17 @@
std::deque<InputEventTimeline> mReceivedTimelines;
};
+/**
+ * Send an event that would trigger the reporting of all of the events that are at least as old as
+ * the provided 'lastEventTime'.
+ */
+void LatencyTrackerTest::triggerEventReporting(nsecs_t lastEventTime) {
+ const nsecs_t triggerEventTime =
+ lastEventTime + std::chrono::nanoseconds(ANR_TIMEOUT).count() + 1;
+ mTracker->trackListener(1 /*inputEventId*/, true /*isDown*/, triggerEventTime, 3 /*readTime*/);
+}
+
void LatencyTrackerTest::assertReceivedTimeline(const InputEventTimeline& timeline) {
- mTracker->reportNow();
ASSERT_FALSE(mReceivedTimelines.empty());
const InputEventTimeline& t = mReceivedTimelines.front();
ASSERT_EQ(timeline, t);
@@ -88,7 +105,6 @@
* equal element in B, and for every element in B there is an equal element in A.
*/
void LatencyTrackerTest::assertReceivedTimelines(const std::vector<InputEventTimeline>& timelines) {
- mTracker->reportNow();
ASSERT_EQ(timelines.size(), mReceivedTimelines.size());
for (const InputEventTimeline& expectedTimeline : timelines) {
bool found = false;
@@ -121,6 +137,7 @@
*/
TEST_F(LatencyTrackerTest, TrackListener_DoesNotTriggerReporting) {
mTracker->trackListener(1 /*inputEventId*/, false /*isDown*/, 2 /*eventTime*/, 3 /*readTime*/);
+ triggerEventReporting(2 /*eventTime*/);
assertReceivedTimeline(InputEventTimeline{false, 2, 3});
}
@@ -130,6 +147,7 @@
TEST_F(LatencyTrackerTest, TrackFinishedEvent_DoesNotTriggerReporting) {
mTracker->trackFinishedEvent(1 /*inputEventId*/, connection1, 2 /*deliveryTime*/,
3 /*consumeTime*/, 4 /*finishTime*/);
+ triggerEventReporting(4 /*eventTime*/);
assertReceivedTimelines({});
}
@@ -141,6 +159,7 @@
graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME] = 2;
graphicsTimeline[GraphicsTimeline::PRESENT_TIME] = 3;
mTracker->trackGraphicsLatency(1 /*inputEventId*/, connection2, graphicsTimeline);
+ triggerEventReporting(3 /*eventTime*/);
assertReceivedTimelines({});
}
@@ -155,9 +174,30 @@
expectedCT.consumeTime, expectedCT.finishTime);
mTracker->trackGraphicsLatency(inputEventId, connectionToken, expectedCT.graphicsTimeline);
+ triggerEventReporting(expected.eventTime);
assertReceivedTimeline(expected);
}
+/**
+ * Send 2 events with the same inputEventId, but different eventTime's. Ensure that no crash occurs,
+ * and that the tracker drops such events completely.
+ */
+TEST_F(LatencyTrackerTest, WhenDuplicateEventsAreReported_DoesNotCrash) {
+ constexpr nsecs_t inputEventId = 1;
+ constexpr nsecs_t readTime = 3; // does not matter for this test
+ constexpr bool isDown = true; // does not matter for this test
+
+ // In the following 2 calls to trackListener, the inputEventId's are the same, but event times
+ // are different.
+ mTracker->trackListener(inputEventId, isDown, 1 /*eventTime*/, readTime);
+ mTracker->trackListener(inputEventId, isDown, 2 /*eventTime*/, readTime);
+
+ triggerEventReporting(2 /*eventTime*/);
+ // Since we sent duplicate input events, the tracker should just delete all of them, because it
+ // does not have enough information to properly track them.
+ assertReceivedTimelines({});
+}
+
TEST_F(LatencyTrackerTest, MultipleEvents_AreReportedConsistently) {
constexpr int32_t inputEventId1 = 1;
InputEventTimeline timeline1(
@@ -204,6 +244,7 @@
mTracker->trackGraphicsLatency(inputEventId2, connection2,
connectionTimeline2.graphicsTimeline);
// Now both events should be completed
+ triggerEventReporting(timeline2.eventTime);
assertReceivedTimelines({timeline1, timeline2});
}
@@ -228,6 +269,7 @@
mTracker->trackGraphicsLatency(1 /*inputEventId*/, token, expectedCT.graphicsTimeline);
expectedTimelines[0].connectionTimelines.emplace(token, std::move(expectedCT));
+ triggerEventReporting(timeline.eventTime);
assertReceivedTimelines(expectedTimelines);
}
@@ -246,6 +288,7 @@
mTracker->trackGraphicsLatency(inputEventId, connection1, expectedCT.graphicsTimeline);
mTracker->trackListener(inputEventId, expected.isDown, expected.eventTime, expected.readTime);
+ triggerEventReporting(expected.eventTime);
assertReceivedTimeline(
InputEventTimeline{expected.isDown, expected.eventTime, expected.readTime});
}