LatencyAggregatorWithHistograms for InputEventLatencyReported atom.
Currently, input latency metrics cannot be reported on a per-device/per
-source/per-input-event-type granular level. Moreover, regarding
implementation, the input event latencies are aggregated into KLL
sketches (per day) and serialized into the InputEventLatencySketch,
which is a pulled atom, using LatencyAggregator. This means that only
20,000 input event latencies can be recorded per day, the rest are
dropped.
We want to capture latency statistics that can be broken down by per
input device (characterized by its Product ID and Vendor ID), by
source(s) of the input event (such as stylus, touchpad, touchscreen) and
by specific types of input events (such as MOTION_ACTION_DOWN,
MOTION_ACTION_UP, MOTION_ACTION_MOVE, KEY).
The logic for per device input latency metrics lives in
LatencyAggregatorWithHistograms.
Once the flag is rolled out, this will replace LatencyAggregator.
Input events with the same identifier are mapped to an array of 7
histograms. Each histogram's bin sizes are custom to the latency stage
and input event type. When an input event timeline is received, the
relevant bin counter of the corresponding histogram is incremented.
The InputEventLatencyReported atom is pushed every 6 hours by calling
pushLatencyStatistics from InputDispatcher DispatchOnce. After a push,
histograms are cleared.
processSlowEvent was copied from LatencyAggregator to keep logging the
SLOW_iNPUT_EVENT_REPORTED atom.
Tests will be added in a separate CL.
Bug: 270049345
Test: atest inputflinger_tests
Test: manual tests with statsd_testdrive 932
Flag: com.android.input.flags.enable_per_device_input_latency_metrics
Change-Id: I64fb883f4a01889b3600043d21446613a5a5bce7
diff --git a/services/inputflinger/dispatcher/LatencyAggregatorWithHistograms.cpp b/services/inputflinger/dispatcher/LatencyAggregatorWithHistograms.cpp
new file mode 100644
index 0000000..881a96b
--- /dev/null
+++ b/services/inputflinger/dispatcher/LatencyAggregatorWithHistograms.cpp
@@ -0,0 +1,345 @@
+/*
+ * Copyright 2024 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 "LatencyAggregatorWithHistograms"
+#include "../InputDeviceMetricsSource.h"
+#include "InputDispatcher.h"
+
+#include <inttypes.h>
+#include <log/log_event_list.h>
+#include <statslog.h>
+
+#include <android-base/logging.h>
+#include <android-base/stringprintf.h>
+#include <input/Input.h>
+#include <log/log.h>
+#include <server_configurable_flags/get_flags.h>
+
+using android::base::StringPrintf;
+using std::chrono_literals::operator""ms;
+
+namespace {
+
+// Convert the provided nanoseconds into hundreds of microseconds.
+// Use hundreds of microseconds (as opposed to microseconds) to preserve space.
+static inline int64_t ns2hus(nsecs_t nanos) {
+ return ns2us(nanos) / 100;
+}
+
+// Category (=namespace) name for the input settings that are applied at boot time
+static const char* INPUT_NATIVE_BOOT = "input_native_boot";
+// Feature flag name for the threshold of end-to-end touch latency that would trigger
+// SlowEventReported atom to be pushed
+static const char* SLOW_EVENT_MIN_REPORTING_LATENCY_MILLIS =
+ "slow_event_min_reporting_latency_millis";
+// Feature flag name for the minimum delay before reporting a slow event after having just reported
+// a slow event. This helps limit the amount of data sent to the server
+static const char* SLOW_EVENT_MIN_REPORTING_INTERVAL_MILLIS =
+ "slow_event_min_reporting_interval_millis";
+
+// If an event has end-to-end latency > 200 ms, it will get reported as a slow event.
+std::chrono::milliseconds DEFAULT_SLOW_EVENT_MIN_REPORTING_LATENCY = 200ms;
+// If we receive two slow events less than 1 min apart, we will only report 1 of them.
+std::chrono::milliseconds DEFAULT_SLOW_EVENT_MIN_REPORTING_INTERVAL = 60000ms;
+
+static std::chrono::milliseconds getSlowEventMinReportingLatency() {
+ std::string millis = server_configurable_flags::
+ GetServerConfigurableFlag(INPUT_NATIVE_BOOT, SLOW_EVENT_MIN_REPORTING_LATENCY_MILLIS,
+ std::to_string(
+ DEFAULT_SLOW_EVENT_MIN_REPORTING_LATENCY.count()));
+ return std::chrono::milliseconds(std::stoi(millis));
+}
+
+static std::chrono::milliseconds getSlowEventMinReportingInterval() {
+ std::string millis = server_configurable_flags::
+ GetServerConfigurableFlag(INPUT_NATIVE_BOOT, SLOW_EVENT_MIN_REPORTING_INTERVAL_MILLIS,
+ std::to_string(
+ DEFAULT_SLOW_EVENT_MIN_REPORTING_INTERVAL.count()));
+ return std::chrono::milliseconds(std::stoi(millis));
+}
+
+} // namespace
+
+namespace android::inputdispatcher {
+
+int32_t LatencyStageIndexToAtomEnum(LatencyStageIndex latencyStageIndex) {
+ switch (latencyStageIndex) {
+ case LatencyStageIndex::EVENT_TO_READ:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__EVENT_TO_READ;
+ case LatencyStageIndex::READ_TO_DELIVER:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__READ_TO_DELIVER;
+ case LatencyStageIndex::DELIVER_TO_CONSUME:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__DELIVER_TO_CONSUME;
+ case LatencyStageIndex::CONSUME_TO_FINISH:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__CONSUME_TO_FINISH;
+ case LatencyStageIndex::CONSUME_TO_GPU_COMPLETE:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__CONSUME_TO_GPU_COMPLETE;
+ case LatencyStageIndex::GPU_COMPLETE_TO_PRESENT:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__GPU_COMPLETE_TO_PRESENT;
+ case LatencyStageIndex::END_TO_END:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__END_TO_END;
+ default:
+ return util::INPUT_EVENT_LATENCY_REPORTED__LATENCY_STAGE__UNKNOWN_LATENCY_STAGE;
+ }
+}
+
+int32_t InputEventTypeEnumToAtomEnum(InputEventActionType inputEventActionType) {
+ switch (inputEventActionType) {
+ case InputEventActionType::UNKNOWN_INPUT_EVENT:
+ return util::INPUT_EVENT_LATENCY_REPORTED__INPUT_EVENT_TYPE__UNKNOWN_INPUT_EVENT;
+ case InputEventActionType::MOTION_ACTION_DOWN:
+ return util::INPUT_EVENT_LATENCY_REPORTED__INPUT_EVENT_TYPE__MOTION_ACTION_DOWN;
+ case InputEventActionType::MOTION_ACTION_MOVE:
+ return util::INPUT_EVENT_LATENCY_REPORTED__INPUT_EVENT_TYPE__MOTION_ACTION_MOVE;
+ case InputEventActionType::MOTION_ACTION_UP:
+ return util::INPUT_EVENT_LATENCY_REPORTED__INPUT_EVENT_TYPE__MOTION_ACTION_UP;
+ case InputEventActionType::MOTION_ACTION_HOVER_MOVE:
+ return util::INPUT_EVENT_LATENCY_REPORTED__INPUT_EVENT_TYPE__MOTION_ACTION_HOVER_MOVE;
+ case InputEventActionType::MOTION_ACTION_SCROLL:
+ return util::INPUT_EVENT_LATENCY_REPORTED__INPUT_EVENT_TYPE__MOTION_ACTION_SCROLL;
+ case InputEventActionType::KEY:
+ return util::INPUT_EVENT_LATENCY_REPORTED__INPUT_EVENT_TYPE__KEY;
+ }
+}
+
+void LatencyAggregatorWithHistograms::processTimeline(const InputEventTimeline& timeline) {
+ processStatistics(timeline);
+ processSlowEvent(timeline);
+}
+
+void LatencyAggregatorWithHistograms::addSampleToHistogram(
+ const InputEventLatencyIdentifier& identifier, LatencyStageIndex latencyStageIndex,
+ nsecs_t latency) {
+ // Only record positive values for the statistics
+ if (latency > 0) {
+ auto it = mHistograms.find(identifier);
+ if (it != mHistograms.end()) {
+ it->second[static_cast<size_t>(latencyStageIndex)].addSample(ns2hus(latency));
+ }
+ }
+}
+
+void LatencyAggregatorWithHistograms::processStatistics(const InputEventTimeline& timeline) {
+ // Only gather data for Down, Move and Up motion events and Key events
+ if (!(timeline.inputEventActionType == InputEventActionType::MOTION_ACTION_DOWN ||
+ timeline.inputEventActionType == InputEventActionType::MOTION_ACTION_MOVE ||
+ timeline.inputEventActionType == InputEventActionType::MOTION_ACTION_UP ||
+ timeline.inputEventActionType == InputEventActionType::KEY))
+ return;
+
+ // Don't collect data for unidentified devices. This situation can occur for the first few input
+ // events produced when an input device is first connected
+ if (timeline.vendorId == 0xFFFF && timeline.productId == 0xFFFF) return;
+
+ InputEventLatencyIdentifier identifier = {timeline.vendorId, timeline.productId,
+ timeline.sources, timeline.inputEventActionType};
+ // Check if there's a value in mHistograms map associated to identifier.
+ // If not, add an array with 7 empty histograms as an entry
+ if (mHistograms.count(identifier) == 0) {
+ if (static_cast<int32_t>(timeline.inputEventActionType) - 1 < 0) {
+ LOG(FATAL) << "Action index is smaller than 0. Action type: "
+ << ftl::enum_string(timeline.inputEventActionType);
+ return;
+ }
+ size_t actionIndex =
+ static_cast<size_t>(static_cast<int32_t>(timeline.inputEventActionType) - 1);
+ if (actionIndex >= NUM_INPUT_EVENT_TYPES) {
+ LOG(FATAL) << "Action index greater than the number of input event types. Action Type: "
+ << ftl::enum_string(timeline.inputEventActionType)
+ << "; Action Type Index: " << actionIndex;
+ return;
+ }
+
+ std::array<Histogram, 7> histograms =
+ {Histogram(allBinSizes[binSizesMappings[0][actionIndex]]),
+ Histogram(allBinSizes[binSizesMappings[1][actionIndex]]),
+ Histogram(allBinSizes[binSizesMappings[2][actionIndex]]),
+ Histogram(allBinSizes[binSizesMappings[3][actionIndex]]),
+ Histogram(allBinSizes[binSizesMappings[4][actionIndex]]),
+ Histogram(allBinSizes[binSizesMappings[5][actionIndex]]),
+ Histogram(allBinSizes[binSizesMappings[6][actionIndex]])};
+ mHistograms.insert({identifier, histograms});
+ }
+
+ // Process common ones first
+ const nsecs_t eventToRead = timeline.readTime - timeline.eventTime;
+ addSampleToHistogram(identifier, LatencyStageIndex::EVENT_TO_READ, eventToRead);
+
+ // Now process per-connection ones
+ for (const auto& [connectionToken, connectionTimeline] : timeline.connectionTimelines) {
+ if (!connectionTimeline.isComplete()) {
+ continue;
+ }
+ const nsecs_t readToDeliver = connectionTimeline.deliveryTime - timeline.readTime;
+ const nsecs_t deliverToConsume =
+ connectionTimeline.consumeTime - connectionTimeline.deliveryTime;
+ const nsecs_t consumeToFinish =
+ connectionTimeline.finishTime - connectionTimeline.consumeTime;
+ const nsecs_t gpuCompletedTime =
+ connectionTimeline.graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME];
+ const nsecs_t presentTime =
+ connectionTimeline.graphicsTimeline[GraphicsTimeline::PRESENT_TIME];
+ const nsecs_t consumeToGpuComplete = gpuCompletedTime - connectionTimeline.consumeTime;
+ const nsecs_t gpuCompleteToPresent = presentTime - gpuCompletedTime;
+ const nsecs_t endToEnd = presentTime - timeline.eventTime;
+
+ addSampleToHistogram(identifier, LatencyStageIndex::READ_TO_DELIVER, readToDeliver);
+ addSampleToHistogram(identifier, LatencyStageIndex::DELIVER_TO_CONSUME, deliverToConsume);
+ addSampleToHistogram(identifier, LatencyStageIndex::CONSUME_TO_FINISH, consumeToFinish);
+ addSampleToHistogram(identifier, LatencyStageIndex::CONSUME_TO_GPU_COMPLETE,
+ consumeToGpuComplete);
+ addSampleToHistogram(identifier, LatencyStageIndex::GPU_COMPLETE_TO_PRESENT,
+ gpuCompleteToPresent);
+ addSampleToHistogram(identifier, LatencyStageIndex::END_TO_END, endToEnd);
+ }
+}
+
+void LatencyAggregatorWithHistograms::pushLatencyStatistics() {
+ for (auto& [id, histograms] : mHistograms) {
+ auto [vendorId, productId, sources, action] = id;
+ for (size_t latencyStageIndex = static_cast<size_t>(LatencyStageIndex::EVENT_TO_READ);
+ latencyStageIndex < static_cast<size_t>(LatencyStageIndex::SIZE);
+ ++latencyStageIndex) {
+ // Convert sources set to vector for atom logging:
+ std::vector<int32_t> sourcesVector = {};
+ for (auto& elem : sources) {
+ sourcesVector.push_back(static_cast<int32_t>(elem));
+ }
+
+ // convert histogram bin counts array to vector for atom logging:
+ std::array arr = histograms[latencyStageIndex].getBinCounts();
+ std::vector<int32_t> binCountsVector(arr.begin(), arr.end());
+
+ if (static_cast<int32_t>(action) - 1 < 0) {
+ ALOGW("Action index is smaller than 0. Action type: %s",
+ ftl::enum_string(action).c_str());
+ continue;
+ }
+ size_t actionIndex = static_cast<size_t>(static_cast<int32_t>(action) - 1);
+ if (actionIndex >= NUM_INPUT_EVENT_TYPES) {
+ ALOGW("Action index greater than the number of input event types. Action Type: %s; "
+ "Action Type Index: %zu",
+ ftl::enum_string(action).c_str(), actionIndex);
+ continue;
+ }
+
+ stats_write(android::util::INPUT_EVENT_LATENCY_REPORTED, vendorId, productId,
+ sourcesVector, InputEventTypeEnumToAtomEnum(action),
+ LatencyStageIndexToAtomEnum(
+ static_cast<LatencyStageIndex>(latencyStageIndex)),
+ histogramVersions[latencyStageIndex][actionIndex], binCountsVector);
+ }
+ }
+ mHistograms.clear();
+}
+
+// TODO (b/270049345): For now, we just copied the code from LatencyAggregator to populate the old
+// atom, but eventually we should migrate this to use the new SlowEventReported atom
+void LatencyAggregatorWithHistograms::processSlowEvent(const InputEventTimeline& timeline) {
+ static const std::chrono::duration sSlowEventThreshold = getSlowEventMinReportingLatency();
+ static const std::chrono::duration sSlowEventReportingInterval =
+ getSlowEventMinReportingInterval();
+ for (const auto& [token, connectionTimeline] : timeline.connectionTimelines) {
+ if (!connectionTimeline.isComplete()) {
+ continue;
+ }
+ mNumEventsSinceLastSlowEventReport++;
+ const nsecs_t presentTime =
+ connectionTimeline.graphicsTimeline[GraphicsTimeline::PRESENT_TIME];
+ const std::chrono::nanoseconds endToEndLatency =
+ std::chrono::nanoseconds(presentTime - timeline.eventTime);
+ if (endToEndLatency < sSlowEventThreshold) {
+ continue;
+ }
+ // This is a slow event. Before we report it, check if we are reporting too often
+ const std::chrono::duration elapsedSinceLastReport =
+ std::chrono::nanoseconds(timeline.eventTime - mLastSlowEventTime);
+ if (elapsedSinceLastReport < sSlowEventReportingInterval) {
+ mNumSkippedSlowEvents++;
+ continue;
+ }
+
+ const nsecs_t eventToRead = timeline.readTime - timeline.eventTime;
+ const nsecs_t readToDeliver = connectionTimeline.deliveryTime - timeline.readTime;
+ const nsecs_t deliverToConsume =
+ connectionTimeline.consumeTime - connectionTimeline.deliveryTime;
+ const nsecs_t consumeToFinish =
+ connectionTimeline.finishTime - connectionTimeline.consumeTime;
+ const nsecs_t gpuCompletedTime =
+ connectionTimeline.graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME];
+ const nsecs_t consumeToGpuComplete = gpuCompletedTime - connectionTimeline.consumeTime;
+ const nsecs_t gpuCompleteToPresent = presentTime - gpuCompletedTime;
+
+ android::util::stats_write(android::util::SLOW_INPUT_EVENT_REPORTED,
+ timeline.inputEventActionType ==
+ InputEventActionType::MOTION_ACTION_DOWN,
+ static_cast<int32_t>(ns2us(eventToRead)),
+ static_cast<int32_t>(ns2us(readToDeliver)),
+ static_cast<int32_t>(ns2us(deliverToConsume)),
+ static_cast<int32_t>(ns2us(consumeToFinish)),
+ static_cast<int32_t>(ns2us(consumeToGpuComplete)),
+ static_cast<int32_t>(ns2us(gpuCompleteToPresent)),
+ static_cast<int32_t>(ns2us(endToEndLatency.count())),
+ static_cast<int32_t>(mNumEventsSinceLastSlowEventReport),
+ static_cast<int32_t>(mNumSkippedSlowEvents));
+ mNumEventsSinceLastSlowEventReport = 0;
+ mNumSkippedSlowEvents = 0;
+ mLastSlowEventTime = timeline.readTime;
+ }
+}
+
+std::string LatencyAggregatorWithHistograms::dump(const char* prefix) const {
+ std::string statisticsStr = StringPrintf("%s Histograms:\n", prefix);
+ for (const auto& [id, histograms] : mHistograms) {
+ auto [vendorId, productId, sources, action] = id;
+
+ std::string identifierStr =
+ StringPrintf("%s Identifier: vendor %d, product %d, sources: {", prefix, vendorId,
+ productId);
+ bool firstSource = true;
+ for (const auto& source : sources) {
+ if (!firstSource) {
+ identifierStr += ", ";
+ }
+ identifierStr += StringPrintf("%d", static_cast<int32_t>(source));
+ firstSource = false;
+ }
+ identifierStr += StringPrintf("}, action: %d\n", static_cast<int32_t>(action));
+
+ std::string histogramsStr;
+ for (size_t stageIndex = 0; stageIndex < static_cast<size_t>(LatencyStageIndex::SIZE);
+ stageIndex++) {
+ const auto& histogram = histograms[stageIndex];
+ const std::array<int, NUM_BINS>& binCounts = histogram.getBinCounts();
+
+ histogramsStr += StringPrintf("%s %zu: ", prefix, stageIndex);
+ histogramsStr += StringPrintf("%d", binCounts[0]);
+ for (size_t bin = 1; bin < NUM_BINS; bin++) {
+ histogramsStr += StringPrintf(", %d", binCounts[bin]);
+ }
+ histogramsStr += StringPrintf("\n");
+ }
+ statisticsStr += identifierStr + histogramsStr;
+ }
+
+ return StringPrintf("%sLatencyAggregatorWithHistograms:\n", prefix) + statisticsStr +
+ StringPrintf("%s mLastSlowEventTime=%" PRId64 "\n", prefix, mLastSlowEventTime) +
+ StringPrintf("%s mNumEventsSinceLastSlowEventReport = %zu\n", prefix,
+ mNumEventsSinceLastSlowEventReport) +
+ StringPrintf("%s mNumSkippedSlowEvents = %zu\n", prefix, mNumSkippedSlowEvents);
+}
+
+} // namespace android::inputdispatcher