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 #define LOG_TAG "LatencyAggregator"
18 #include "LatencyAggregator.h"
19
20 #include <inttypes.h>
21
22 #include <android-base/stringprintf.h>
23 #include <input/Input.h>
24 #include <log/log.h>
25 #include <server_configurable_flags/get_flags.h>
26
27 using android::base::StringPrintf;
28 using dist_proc::aggregation::KllQuantile;
29 using std::chrono_literals::operator""ms;
30
31 // Convert the provided nanoseconds into hundreds of microseconds.
32 // Use hundreds of microseconds (as opposed to microseconds) to preserve space.
ns2hus(nsecs_t nanos)33 static inline int64_t ns2hus(nsecs_t nanos) {
34 return ns2us(nanos) / 100;
35 }
36
37 // The maximum number of events that we will store in the statistics. Any events that we will
38 // receive after we have reached this number will be ignored. We could also implement this by
39 // checking the actual size of the current data and making sure that we do not go over. However,
40 // the serialization process of sketches is too heavy (1 ms for all 14 sketches), and would be too
41 // much to do (even if infrequently).
42 // The value here has been determined empirically.
43 static constexpr size_t MAX_EVENTS_FOR_STATISTICS = 20000;
44
45 // Category (=namespace) name for the input settings that are applied at boot time
46 static const char* INPUT_NATIVE_BOOT = "input_native_boot";
47 // Feature flag name for the threshold of end-to-end touch latency that would trigger
48 // SlowEventReported atom to be pushed
49 static const char* SLOW_EVENT_MIN_REPORTING_LATENCY_MILLIS =
50 "slow_event_min_reporting_latency_millis";
51 // Feature flag name for the minimum delay before reporting a slow event after having just reported
52 // a slow event. This helps limit the amount of data sent to the server
53 static const char* SLOW_EVENT_MIN_REPORTING_INTERVAL_MILLIS =
54 "slow_event_min_reporting_interval_millis";
55
56 // If an event has end-to-end latency > 200 ms, it will get reported as a slow event.
57 std::chrono::milliseconds DEFAULT_SLOW_EVENT_MIN_REPORTING_LATENCY = 200ms;
58 // If we receive two slow events less than 1 min apart, we will only report 1 of them.
59 std::chrono::milliseconds DEFAULT_SLOW_EVENT_MIN_REPORTING_INTERVAL = 60000ms;
60
getSlowEventMinReportingLatency()61 static std::chrono::milliseconds getSlowEventMinReportingLatency() {
62 std::string millis = server_configurable_flags::
63 GetServerConfigurableFlag(INPUT_NATIVE_BOOT, SLOW_EVENT_MIN_REPORTING_LATENCY_MILLIS,
64 std::to_string(
65 DEFAULT_SLOW_EVENT_MIN_REPORTING_LATENCY.count()));
66 return std::chrono::milliseconds(std::stoi(millis));
67 }
68
getSlowEventMinReportingInterval()69 static std::chrono::milliseconds getSlowEventMinReportingInterval() {
70 std::string millis = server_configurable_flags::
71 GetServerConfigurableFlag(INPUT_NATIVE_BOOT, SLOW_EVENT_MIN_REPORTING_INTERVAL_MILLIS,
72 std::to_string(
73 DEFAULT_SLOW_EVENT_MIN_REPORTING_INTERVAL.count()));
74 return std::chrono::milliseconds(std::stoi(millis));
75 }
76
77 namespace android::inputdispatcher {
78
79 /**
80 * Same as android::util::BytesField, but doesn't store raw pointers, and therefore deletes its
81 * resources automatically.
82 */
83 class SafeBytesField {
84 public:
SafeBytesField(dist_proc::aggregation::KllQuantile & quantile)85 explicit SafeBytesField(dist_proc::aggregation::KllQuantile& quantile) {
86 const zetasketch::android::AggregatorStateProto aggProto = quantile.SerializeToProto();
87 mBuffer.resize(aggProto.ByteSizeLong());
88 aggProto.SerializeToArray(mBuffer.data(), mBuffer.size());
89 }
getBytesField()90 android::util::BytesField getBytesField() {
91 return android::util::BytesField(mBuffer.data(), mBuffer.size());
92 }
93
94 private:
95 std::vector<char> mBuffer;
96 };
97
LatencyAggregator()98 LatencyAggregator::LatencyAggregator() {
99 AStatsManager_setPullAtomCallback(android::util::INPUT_EVENT_LATENCY_SKETCH, nullptr,
100 LatencyAggregator::pullAtomCallback, this);
101 dist_proc::aggregation::KllQuantileOptions options;
102 options.set_inv_eps(100); // Request precision of 1.0%, instead of default 0.1%
103 for (size_t i = 0; i < SketchIndex::SIZE; i++) {
104 mDownSketches[i] = KllQuantile::Create(options);
105 mMoveSketches[i] = KllQuantile::Create(options);
106 }
107 }
108
~LatencyAggregator()109 LatencyAggregator::~LatencyAggregator() {
110 AStatsManager_clearPullAtomCallback(android::util::INPUT_EVENT_LATENCY_SKETCH);
111 }
112
pullAtomCallback(int32_t atomTag,AStatsEventList * data,void * cookie)113 AStatsManager_PullAtomCallbackReturn LatencyAggregator::pullAtomCallback(int32_t atomTag,
114 AStatsEventList* data,
115 void* cookie) {
116 LatencyAggregator* pAggregator = reinterpret_cast<LatencyAggregator*>(cookie);
117 if (pAggregator == nullptr) {
118 LOG_ALWAYS_FATAL("pAggregator is null!");
119 }
120 return pAggregator->pullData(data);
121 }
122
processTimeline(const InputEventTimeline & timeline)123 void LatencyAggregator::processTimeline(const InputEventTimeline& timeline) {
124 processStatistics(timeline);
125 processSlowEvent(timeline);
126 }
127
processStatistics(const InputEventTimeline & timeline)128 void LatencyAggregator::processStatistics(const InputEventTimeline& timeline) {
129 std::scoped_lock lock(mLock);
130 // Before we do any processing, check that we have not yet exceeded MAX_SIZE
131 if (mNumSketchEventsProcessed >= MAX_EVENTS_FOR_STATISTICS) {
132 return;
133 }
134 mNumSketchEventsProcessed++;
135
136 std::array<std::unique_ptr<KllQuantile>, SketchIndex::SIZE>& sketches =
137 timeline.isDown ? mDownSketches : mMoveSketches;
138
139 // Process common ones first
140 const nsecs_t eventToRead = timeline.readTime - timeline.eventTime;
141 sketches[SketchIndex::EVENT_TO_READ]->Add(ns2hus(eventToRead));
142
143 // Now process per-connection ones
144 for (const auto& [connectionToken, connectionTimeline] : timeline.connectionTimelines) {
145 if (!connectionTimeline.isComplete()) {
146 continue;
147 }
148 const nsecs_t readToDeliver = connectionTimeline.deliveryTime - timeline.readTime;
149 const nsecs_t deliverToConsume =
150 connectionTimeline.consumeTime - connectionTimeline.deliveryTime;
151 const nsecs_t consumeToFinish =
152 connectionTimeline.finishTime - connectionTimeline.consumeTime;
153 const nsecs_t gpuCompletedTime =
154 connectionTimeline.graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME];
155 const nsecs_t presentTime =
156 connectionTimeline.graphicsTimeline[GraphicsTimeline::PRESENT_TIME];
157 const nsecs_t consumeToGpuComplete = gpuCompletedTime - connectionTimeline.consumeTime;
158 const nsecs_t gpuCompleteToPresent = presentTime - gpuCompletedTime;
159 const nsecs_t endToEnd = presentTime - timeline.eventTime;
160
161 sketches[SketchIndex::READ_TO_DELIVER]->Add(ns2hus(readToDeliver));
162 sketches[SketchIndex::DELIVER_TO_CONSUME]->Add(ns2hus(deliverToConsume));
163 sketches[SketchIndex::CONSUME_TO_FINISH]->Add(ns2hus(consumeToFinish));
164 sketches[SketchIndex::CONSUME_TO_GPU_COMPLETE]->Add(ns2hus(consumeToGpuComplete));
165 sketches[SketchIndex::GPU_COMPLETE_TO_PRESENT]->Add(ns2hus(gpuCompleteToPresent));
166 sketches[SketchIndex::END_TO_END]->Add(ns2hus(endToEnd));
167 }
168 }
169
pullData(AStatsEventList * data)170 AStatsManager_PullAtomCallbackReturn LatencyAggregator::pullData(AStatsEventList* data) {
171 std::scoped_lock lock(mLock);
172 std::array<std::unique_ptr<SafeBytesField>, SketchIndex::SIZE> serializedDownData;
173 std::array<std::unique_ptr<SafeBytesField>, SketchIndex::SIZE> serializedMoveData;
174 for (size_t i = 0; i < SketchIndex::SIZE; i++) {
175 serializedDownData[i] = std::make_unique<SafeBytesField>(*mDownSketches[i]);
176 serializedMoveData[i] = std::make_unique<SafeBytesField>(*mMoveSketches[i]);
177 }
178 android::util::
179 addAStatsEvent(data, android::util::INPUT_EVENT_LATENCY_SKETCH,
180 // DOWN sketches
181 serializedDownData[SketchIndex::EVENT_TO_READ]->getBytesField(),
182 serializedDownData[SketchIndex::READ_TO_DELIVER]->getBytesField(),
183 serializedDownData[SketchIndex::DELIVER_TO_CONSUME]->getBytesField(),
184 serializedDownData[SketchIndex::CONSUME_TO_FINISH]->getBytesField(),
185 serializedDownData[SketchIndex::CONSUME_TO_GPU_COMPLETE]
186 ->getBytesField(),
187 serializedDownData[SketchIndex::GPU_COMPLETE_TO_PRESENT]
188 ->getBytesField(),
189 serializedDownData[SketchIndex::END_TO_END]->getBytesField(),
190 // MOVE sketches
191 serializedMoveData[SketchIndex::EVENT_TO_READ]->getBytesField(),
192 serializedMoveData[SketchIndex::READ_TO_DELIVER]->getBytesField(),
193 serializedMoveData[SketchIndex::DELIVER_TO_CONSUME]->getBytesField(),
194 serializedMoveData[SketchIndex::CONSUME_TO_FINISH]->getBytesField(),
195 serializedMoveData[SketchIndex::CONSUME_TO_GPU_COMPLETE]
196 ->getBytesField(),
197 serializedMoveData[SketchIndex::GPU_COMPLETE_TO_PRESENT]
198 ->getBytesField(),
199 serializedMoveData[SketchIndex::END_TO_END]->getBytesField());
200
201 for (size_t i = 0; i < SketchIndex::SIZE; i++) {
202 mDownSketches[i]->Reset();
203 mMoveSketches[i]->Reset();
204 }
205 // Start new aggregations
206 mNumSketchEventsProcessed = 0;
207 return AStatsManager_PULL_SUCCESS;
208 }
209
processSlowEvent(const InputEventTimeline & timeline)210 void LatencyAggregator::processSlowEvent(const InputEventTimeline& timeline) {
211 static const std::chrono::duration sSlowEventThreshold = getSlowEventMinReportingLatency();
212 static const std::chrono::duration sSlowEventReportingInterval =
213 getSlowEventMinReportingInterval();
214 for (const auto& [token, connectionTimeline] : timeline.connectionTimelines) {
215 if (!connectionTimeline.isComplete()) {
216 continue;
217 }
218 mNumEventsSinceLastSlowEventReport++;
219 const nsecs_t presentTime =
220 connectionTimeline.graphicsTimeline[GraphicsTimeline::PRESENT_TIME];
221 const std::chrono::nanoseconds endToEndLatency =
222 std::chrono::nanoseconds(presentTime - timeline.eventTime);
223 if (endToEndLatency < sSlowEventThreshold) {
224 continue;
225 }
226 // This is a slow event. Before we report it, check if we are reporting too often
227 const std::chrono::duration elapsedSinceLastReport =
228 std::chrono::nanoseconds(timeline.eventTime - mLastSlowEventTime);
229 if (elapsedSinceLastReport < sSlowEventReportingInterval) {
230 mNumSkippedSlowEvents++;
231 continue;
232 }
233
234 const nsecs_t eventToRead = timeline.readTime - timeline.eventTime;
235 const nsecs_t readToDeliver = connectionTimeline.deliveryTime - timeline.readTime;
236 const nsecs_t deliverToConsume =
237 connectionTimeline.consumeTime - connectionTimeline.deliveryTime;
238 const nsecs_t consumeToFinish =
239 connectionTimeline.finishTime - connectionTimeline.consumeTime;
240 const nsecs_t gpuCompletedTime =
241 connectionTimeline.graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME];
242 const nsecs_t consumeToGpuComplete = gpuCompletedTime - connectionTimeline.consumeTime;
243 const nsecs_t gpuCompleteToPresent = presentTime - gpuCompletedTime;
244
245 android::util::stats_write(android::util::SLOW_INPUT_EVENT_REPORTED, timeline.isDown,
246 static_cast<int32_t>(ns2us(eventToRead)),
247 static_cast<int32_t>(ns2us(readToDeliver)),
248 static_cast<int32_t>(ns2us(deliverToConsume)),
249 static_cast<int32_t>(ns2us(consumeToFinish)),
250 static_cast<int32_t>(ns2us(consumeToGpuComplete)),
251 static_cast<int32_t>(ns2us(gpuCompleteToPresent)),
252 static_cast<int32_t>(ns2us(endToEndLatency.count())),
253 static_cast<int32_t>(mNumEventsSinceLastSlowEventReport),
254 static_cast<int32_t>(mNumSkippedSlowEvents));
255 mNumEventsSinceLastSlowEventReport = 0;
256 mNumSkippedSlowEvents = 0;
257 mLastSlowEventTime = timeline.readTime;
258 }
259 }
260
dump(const char * prefix) const261 std::string LatencyAggregator::dump(const char* prefix) const {
262 std::scoped_lock lock(mLock);
263 std::string sketchDump = StringPrintf("%s Sketches:\n", prefix);
264 for (size_t i = 0; i < SketchIndex::SIZE; i++) {
265 const int64_t numDown = mDownSketches[i]->num_values();
266 SafeBytesField downBytesField(*mDownSketches[i]);
267 const float downBytesKb = downBytesField.getBytesField().arg_length * 1E-3;
268 const int64_t numMove = mMoveSketches[i]->num_values();
269 SafeBytesField moveBytesField(*mMoveSketches[i]);
270 const float moveBytesKb = moveBytesField.getBytesField().arg_length * 1E-3;
271 sketchDump +=
272 StringPrintf("%s mDownSketches[%zu]->num_values = %" PRId64 " size = %.1fKB"
273 " mMoveSketches[%zu]->num_values = %" PRId64 " size = %.1fKB\n",
274 prefix, i, numDown, downBytesKb, i, numMove, moveBytesKb);
275 }
276
277 return StringPrintf("%sLatencyAggregator:\n", prefix) + sketchDump +
278 StringPrintf("%s mNumSketchEventsProcessed=%zu\n", prefix, mNumSketchEventsProcessed) +
279 StringPrintf("%s mLastSlowEventTime=%" PRId64 "\n", prefix, mLastSlowEventTime) +
280 StringPrintf("%s mNumEventsSinceLastSlowEventReport = %zu\n", prefix,
281 mNumEventsSinceLastSlowEventReport) +
282 StringPrintf("%s mNumSkippedSlowEvents = %zu\n", prefix, mNumSkippedSlowEvents);
283 }
284
285 } // namespace android::inputdispatcher
286