1 /*
2 * Copyright (C) 2021 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "../dispatcher/LatencyTracker.h"
18
19 #include <android-base/properties.h>
20 #include <binder/Binder.h>
21 #include <gtest/gtest.h>
22 #include <inttypes.h>
23 #include <log/log.h>
24
25 #define TAG "LatencyTracker_test"
26
27 using android::base::HwTimeoutMultiplier;
28 using android::inputdispatcher::InputEventTimeline;
29 using android::inputdispatcher::LatencyTracker;
30
31 namespace android::inputdispatcher {
32
33 const std::chrono::duration ANR_TIMEOUT = std::chrono::milliseconds(
34 android::os::IInputConstants::UNMULTIPLIED_DEFAULT_DISPATCHING_TIMEOUT_MILLIS *
35 HwTimeoutMultiplier());
36
getTestTimeline()37 InputEventTimeline getTestTimeline() {
38 InputEventTimeline t(
39 /*isDown*/ true,
40 /*eventTime*/ 2,
41 /*readTime*/ 3);
42 ConnectionTimeline expectedCT(/*deliveryTime*/ 6, /* consumeTime*/ 7, /*finishTime*/ 8);
43 std::array<nsecs_t, GraphicsTimeline::SIZE> graphicsTimeline;
44 graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME] = 9;
45 graphicsTimeline[GraphicsTimeline::PRESENT_TIME] = 10;
46 expectedCT.setGraphicsTimeline(std::move(graphicsTimeline));
47 t.connectionTimelines.emplace(new BBinder(), std::move(expectedCT));
48 return t;
49 }
50
51 // --- LatencyTrackerTest ---
52 class LatencyTrackerTest : public testing::Test, public InputEventTimelineProcessor {
53 protected:
54 std::unique_ptr<LatencyTracker> mTracker;
55 sp<IBinder> connection1;
56 sp<IBinder> connection2;
57
SetUp()58 void SetUp() override {
59 connection1 = new BBinder();
60 connection2 = new BBinder();
61
62 mTracker = std::make_unique<LatencyTracker>(this);
63 }
TearDown()64 void TearDown() override {}
65
66 void triggerEventReporting(nsecs_t lastEventTime);
67
68 void assertReceivedTimeline(const InputEventTimeline& timeline);
69 /**
70 * Timelines can be received in any order (order is not guaranteed). So if we are expecting more
71 * than 1 timeline, use this function to check that the set of received timelines matches
72 * what we expected.
73 */
74 void assertReceivedTimelines(const std::vector<InputEventTimeline>& timelines);
75
76 private:
processTimeline(const InputEventTimeline & timeline)77 void processTimeline(const InputEventTimeline& timeline) override {
78 mReceivedTimelines.push_back(timeline);
79 }
80 std::deque<InputEventTimeline> mReceivedTimelines;
81 };
82
83 /**
84 * Send an event that would trigger the reporting of all of the events that are at least as old as
85 * the provided 'lastEventTime'.
86 */
triggerEventReporting(nsecs_t lastEventTime)87 void LatencyTrackerTest::triggerEventReporting(nsecs_t lastEventTime) {
88 const nsecs_t triggerEventTime =
89 lastEventTime + std::chrono::nanoseconds(ANR_TIMEOUT).count() + 1;
90 mTracker->trackListener(1 /*inputEventId*/, true /*isDown*/, triggerEventTime, 3 /*readTime*/);
91 }
92
assertReceivedTimeline(const InputEventTimeline & timeline)93 void LatencyTrackerTest::assertReceivedTimeline(const InputEventTimeline& timeline) {
94 ASSERT_FALSE(mReceivedTimelines.empty());
95 const InputEventTimeline& t = mReceivedTimelines.front();
96 ASSERT_EQ(timeline, t);
97 mReceivedTimelines.pop_front();
98 }
99
100 /**
101 * We are essentially comparing two multisets, but without constructing them.
102 * This comparison is inefficient, but it avoids having to construct a set, and also avoids the
103 * declaration of copy constructor for ConnectionTimeline.
104 * We ensure that collections A and B have the same size, that for every element in A, there is an
105 * equal element in B, and for every element in B there is an equal element in A.
106 */
assertReceivedTimelines(const std::vector<InputEventTimeline> & timelines)107 void LatencyTrackerTest::assertReceivedTimelines(const std::vector<InputEventTimeline>& timelines) {
108 ASSERT_EQ(timelines.size(), mReceivedTimelines.size());
109 for (const InputEventTimeline& expectedTimeline : timelines) {
110 bool found = false;
111 for (const InputEventTimeline& receivedTimeline : mReceivedTimelines) {
112 if (receivedTimeline == expectedTimeline) {
113 found = true;
114 break;
115 }
116 }
117 ASSERT_TRUE(found) << "Could not find expected timeline with eventTime="
118 << expectedTimeline.eventTime;
119 }
120 for (const InputEventTimeline& receivedTimeline : mReceivedTimelines) {
121 bool found = false;
122 for (const InputEventTimeline& expectedTimeline : timelines) {
123 if (receivedTimeline == expectedTimeline) {
124 found = true;
125 break;
126 }
127 }
128 ASSERT_TRUE(found) << "Could not find received timeline with eventTime="
129 << receivedTimeline.eventTime;
130 }
131 mReceivedTimelines.clear();
132 }
133
134 /**
135 * Ensure that calling 'trackListener' in isolation only creates an inputflinger timeline, without
136 * any additional ConnectionTimeline's.
137 */
TEST_F(LatencyTrackerTest,TrackListener_DoesNotTriggerReporting)138 TEST_F(LatencyTrackerTest, TrackListener_DoesNotTriggerReporting) {
139 mTracker->trackListener(1 /*inputEventId*/, false /*isDown*/, 2 /*eventTime*/, 3 /*readTime*/);
140 triggerEventReporting(2 /*eventTime*/);
141 assertReceivedTimeline(InputEventTimeline{false, 2, 3});
142 }
143
144 /**
145 * A single call to trackFinishedEvent should not cause a timeline to be reported.
146 */
TEST_F(LatencyTrackerTest,TrackFinishedEvent_DoesNotTriggerReporting)147 TEST_F(LatencyTrackerTest, TrackFinishedEvent_DoesNotTriggerReporting) {
148 mTracker->trackFinishedEvent(1 /*inputEventId*/, connection1, 2 /*deliveryTime*/,
149 3 /*consumeTime*/, 4 /*finishTime*/);
150 triggerEventReporting(4 /*eventTime*/);
151 assertReceivedTimelines({});
152 }
153
154 /**
155 * A single call to trackGraphicsLatency should not cause a timeline to be reported.
156 */
TEST_F(LatencyTrackerTest,TrackGraphicsLatency_DoesNotTriggerReporting)157 TEST_F(LatencyTrackerTest, TrackGraphicsLatency_DoesNotTriggerReporting) {
158 std::array<nsecs_t, GraphicsTimeline::SIZE> graphicsTimeline;
159 graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME] = 2;
160 graphicsTimeline[GraphicsTimeline::PRESENT_TIME] = 3;
161 mTracker->trackGraphicsLatency(1 /*inputEventId*/, connection2, graphicsTimeline);
162 triggerEventReporting(3 /*eventTime*/);
163 assertReceivedTimelines({});
164 }
165
TEST_F(LatencyTrackerTest,TrackAllParameters_ReportsFullTimeline)166 TEST_F(LatencyTrackerTest, TrackAllParameters_ReportsFullTimeline) {
167 constexpr int32_t inputEventId = 1;
168 InputEventTimeline expected = getTestTimeline();
169
170 const auto& [connectionToken, expectedCT] = *expected.connectionTimelines.begin();
171
172 mTracker->trackListener(inputEventId, expected.isDown, expected.eventTime, expected.readTime);
173 mTracker->trackFinishedEvent(inputEventId, connectionToken, expectedCT.deliveryTime,
174 expectedCT.consumeTime, expectedCT.finishTime);
175 mTracker->trackGraphicsLatency(inputEventId, connectionToken, expectedCT.graphicsTimeline);
176
177 triggerEventReporting(expected.eventTime);
178 assertReceivedTimeline(expected);
179 }
180
181 /**
182 * Send 2 events with the same inputEventId, but different eventTime's. Ensure that no crash occurs,
183 * and that the tracker drops such events completely.
184 */
TEST_F(LatencyTrackerTest,WhenDuplicateEventsAreReported_DoesNotCrash)185 TEST_F(LatencyTrackerTest, WhenDuplicateEventsAreReported_DoesNotCrash) {
186 constexpr nsecs_t inputEventId = 1;
187 constexpr nsecs_t readTime = 3; // does not matter for this test
188 constexpr bool isDown = true; // does not matter for this test
189
190 // In the following 2 calls to trackListener, the inputEventId's are the same, but event times
191 // are different.
192 mTracker->trackListener(inputEventId, isDown, 1 /*eventTime*/, readTime);
193 mTracker->trackListener(inputEventId, isDown, 2 /*eventTime*/, readTime);
194
195 triggerEventReporting(2 /*eventTime*/);
196 // Since we sent duplicate input events, the tracker should just delete all of them, because it
197 // does not have enough information to properly track them.
198 assertReceivedTimelines({});
199 }
200
TEST_F(LatencyTrackerTest,MultipleEvents_AreReportedConsistently)201 TEST_F(LatencyTrackerTest, MultipleEvents_AreReportedConsistently) {
202 constexpr int32_t inputEventId1 = 1;
203 InputEventTimeline timeline1(
204 /*isDown*/ true,
205 /*eventTime*/ 2,
206 /*readTime*/ 3);
207 timeline1.connectionTimelines.emplace(connection1,
208 ConnectionTimeline(/*deliveryTime*/ 6, /*consumeTime*/ 7,
209 /*finishTime*/ 8));
210 ConnectionTimeline& connectionTimeline1 = timeline1.connectionTimelines.begin()->second;
211 std::array<nsecs_t, GraphicsTimeline::SIZE> graphicsTimeline1;
212 graphicsTimeline1[GraphicsTimeline::GPU_COMPLETED_TIME] = 9;
213 graphicsTimeline1[GraphicsTimeline::PRESENT_TIME] = 10;
214 connectionTimeline1.setGraphicsTimeline(std::move(graphicsTimeline1));
215
216 constexpr int32_t inputEventId2 = 10;
217 InputEventTimeline timeline2(
218 /*isDown*/ false,
219 /*eventTime*/ 20,
220 /*readTime*/ 30);
221 timeline2.connectionTimelines.emplace(connection2,
222 ConnectionTimeline(/*deliveryTime*/ 60,
223 /*consumeTime*/ 70,
224 /*finishTime*/ 80));
225 ConnectionTimeline& connectionTimeline2 = timeline2.connectionTimelines.begin()->second;
226 std::array<nsecs_t, GraphicsTimeline::SIZE> graphicsTimeline2;
227 graphicsTimeline2[GraphicsTimeline::GPU_COMPLETED_TIME] = 90;
228 graphicsTimeline2[GraphicsTimeline::PRESENT_TIME] = 100;
229 connectionTimeline2.setGraphicsTimeline(std::move(graphicsTimeline2));
230
231 // Start processing first event
232 mTracker->trackListener(inputEventId1, timeline1.isDown, timeline1.eventTime,
233 timeline1.readTime);
234 // Start processing second event
235 mTracker->trackListener(inputEventId2, timeline2.isDown, timeline2.eventTime,
236 timeline2.readTime);
237 mTracker->trackFinishedEvent(inputEventId1, connection1, connectionTimeline1.deliveryTime,
238 connectionTimeline1.consumeTime, connectionTimeline1.finishTime);
239
240 mTracker->trackFinishedEvent(inputEventId2, connection2, connectionTimeline2.deliveryTime,
241 connectionTimeline2.consumeTime, connectionTimeline2.finishTime);
242 mTracker->trackGraphicsLatency(inputEventId1, connection1,
243 connectionTimeline1.graphicsTimeline);
244 mTracker->trackGraphicsLatency(inputEventId2, connection2,
245 connectionTimeline2.graphicsTimeline);
246 // Now both events should be completed
247 triggerEventReporting(timeline2.eventTime);
248 assertReceivedTimelines({timeline1, timeline2});
249 }
250
251 /**
252 * Check that LatencyTracker consistently tracks events even if there are many incomplete events.
253 */
TEST_F(LatencyTrackerTest,IncompleteEvents_AreHandledConsistently)254 TEST_F(LatencyTrackerTest, IncompleteEvents_AreHandledConsistently) {
255 InputEventTimeline timeline = getTestTimeline();
256 std::vector<InputEventTimeline> expectedTimelines;
257 const ConnectionTimeline& expectedCT = timeline.connectionTimelines.begin()->second;
258 const sp<IBinder>& token = timeline.connectionTimelines.begin()->first;
259
260 for (size_t i = 1; i <= 100; i++) {
261 mTracker->trackListener(i /*inputEventId*/, timeline.isDown, timeline.eventTime,
262 timeline.readTime);
263 expectedTimelines.push_back(
264 InputEventTimeline{timeline.isDown, timeline.eventTime, timeline.readTime});
265 }
266 // Now, complete the first event that was sent.
267 mTracker->trackFinishedEvent(1 /*inputEventId*/, token, expectedCT.deliveryTime,
268 expectedCT.consumeTime, expectedCT.finishTime);
269 mTracker->trackGraphicsLatency(1 /*inputEventId*/, token, expectedCT.graphicsTimeline);
270
271 expectedTimelines[0].connectionTimelines.emplace(token, std::move(expectedCT));
272 triggerEventReporting(timeline.eventTime);
273 assertReceivedTimelines(expectedTimelines);
274 }
275
276 /**
277 * For simplicity of the implementation, LatencyTracker only starts tracking an event when
278 * 'trackListener' is invoked.
279 * Both 'trackFinishedEvent' and 'trackGraphicsLatency' should not start a new event.
280 * If they are received before 'trackListener' (which should not be possible), they are ignored.
281 */
TEST_F(LatencyTrackerTest,EventsAreTracked_WhenTrackListenerIsCalledFirst)282 TEST_F(LatencyTrackerTest, EventsAreTracked_WhenTrackListenerIsCalledFirst) {
283 constexpr int32_t inputEventId = 1;
284 InputEventTimeline expected = getTestTimeline();
285 const ConnectionTimeline& expectedCT = expected.connectionTimelines.begin()->second;
286 mTracker->trackFinishedEvent(inputEventId, connection1, expectedCT.deliveryTime,
287 expectedCT.consumeTime, expectedCT.finishTime);
288 mTracker->trackGraphicsLatency(inputEventId, connection1, expectedCT.graphicsTimeline);
289
290 mTracker->trackListener(inputEventId, expected.isDown, expected.eventTime, expected.readTime);
291 triggerEventReporting(expected.eventTime);
292 assertReceivedTimeline(
293 InputEventTimeline{expected.isDown, expected.eventTime, expected.readTime});
294 }
295
296 } // namespace android::inputdispatcher
297