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/Android.bp b/services/inputflinger/dispatcher/Android.bp
index 1a0ec48..8b2b843 100644
--- a/services/inputflinger/dispatcher/Android.bp
+++ b/services/inputflinger/dispatcher/Android.bp
@@ -46,6 +46,7 @@
"InputState.cpp",
"InputTarget.cpp",
"LatencyAggregator.cpp",
+ "LatencyAggregatorWithHistograms.cpp",
"LatencyTracker.cpp",
"Monitor.cpp",
"TouchedWindow.cpp",
diff --git a/services/inputflinger/dispatcher/InputDispatcher.cpp b/services/inputflinger/dispatcher/InputDispatcher.cpp
index 250e72c..da3ac20 100644
--- a/services/inputflinger/dispatcher/InputDispatcher.cpp
+++ b/services/inputflinger/dispatcher/InputDispatcher.cpp
@@ -155,6 +155,10 @@
// Number of recent events to keep for debugging purposes.
constexpr size_t RECENT_QUEUE_MAX_SIZE = 10;
+// Interval at which we should push the atom gathering input event latencies in
+// LatencyAggregatorWithHistograms
+constexpr nsecs_t LATENCY_STATISTICS_PUSH_INTERVAL = 6 * 3600 * 1000000000LL; // 6 hours
+
// Event log tags. See EventLogTags.logtags for reference.
constexpr int LOGTAG_INPUT_INTERACTION = 62000;
constexpr int LOGTAG_INPUT_FOCUS = 62001;
@@ -944,8 +948,13 @@
mFocusedDisplayId(ui::LogicalDisplayId::DEFAULT),
mWindowTokenWithPointerCapture(nullptr),
mAwaitedApplicationDisplayId(ui::LogicalDisplayId::INVALID),
- mLatencyAggregator(),
- mLatencyTracker(&mLatencyAggregator) {
+ mInputEventTimelineProcessor(
+ input_flags::enable_per_device_input_latency_metrics()
+ ? std::move(std::unique_ptr<InputEventTimelineProcessor>(
+ new LatencyAggregatorWithHistograms()))
+ : std::move(std::unique_ptr<InputEventTimelineProcessor>(
+ new LatencyAggregator()))),
+ mLatencyTracker(*mInputEventTimelineProcessor) {
mLooper = sp<Looper>::make(false);
mReporter = createInputReporter();
@@ -1017,6 +1026,11 @@
const nsecs_t nextAnrCheck = processAnrsLocked();
nextWakeupTime = std::min(nextWakeupTime, nextAnrCheck);
+ if (input_flags::enable_per_device_input_latency_metrics()) {
+ const nsecs_t nextStatisticsPush = processLatencyStatisticsLocked();
+ nextWakeupTime = std::min(nextWakeupTime, nextStatisticsPush);
+ }
+
// We are about to enter an infinitely long sleep, because we have no commands or
// pending or queued events
if (nextWakeupTime == LLONG_MAX) {
@@ -1097,6 +1111,21 @@
return LLONG_MIN;
}
+/**
+ * Check if enough time has passed since the last latency statistics push.
+ * Return the time at which we should wake up next.
+ */
+nsecs_t InputDispatcher::processLatencyStatisticsLocked() {
+ const nsecs_t currentTime = now();
+ // Log the atom recording latency statistics if more than 6 hours passed from the last
+ // push
+ if (currentTime - mLastStatisticPushTime >= LATENCY_STATISTICS_PUSH_INTERVAL) {
+ mInputEventTimelineProcessor->pushLatencyStatistics();
+ mLastStatisticPushTime = currentTime;
+ }
+ return mLastStatisticPushTime + LATENCY_STATISTICS_PUSH_INTERVAL;
+}
+
std::chrono::nanoseconds InputDispatcher::getDispatchingTimeoutLocked(
const std::shared_ptr<Connection>& connection) {
if (connection->monitor) {
@@ -6055,7 +6084,7 @@
dump += StringPrintf(INDENT2 "KeyRepeatTimeout: %" PRId64 "ms\n",
ns2ms(mConfig.keyRepeatTimeout));
dump += mLatencyTracker.dump(INDENT2);
- dump += mLatencyAggregator.dump(INDENT2);
+ dump += mInputEventTimelineProcessor->dump(INDENT2);
dump += INDENT "InputTracer: ";
dump += mTracer == nullptr ? "Disabled" : "Enabled";
}
diff --git a/services/inputflinger/dispatcher/InputDispatcher.h b/services/inputflinger/dispatcher/InputDispatcher.h
index 87dfd1d..7060efa 100644
--- a/services/inputflinger/dispatcher/InputDispatcher.h
+++ b/services/inputflinger/dispatcher/InputDispatcher.h
@@ -28,6 +28,7 @@
#include "InputTarget.h"
#include "InputThread.h"
#include "LatencyAggregator.h"
+#include "LatencyAggregatorWithHistograms.h"
#include "LatencyTracker.h"
#include "Monitor.h"
#include "TouchState.h"
@@ -326,6 +327,7 @@
std::chrono::nanoseconds mMonitorDispatchingTimeout GUARDED_BY(mLock);
nsecs_t processAnrsLocked() REQUIRES(mLock);
+ nsecs_t processLatencyStatisticsLocked() REQUIRES(mLock);
std::chrono::nanoseconds getDispatchingTimeoutLocked(
const std::shared_ptr<Connection>& connection) REQUIRES(mLock);
@@ -697,7 +699,8 @@
DeviceId deviceId) const REQUIRES(mLock);
// Statistics gathering.
- LatencyAggregator mLatencyAggregator GUARDED_BY(mLock);
+ nsecs_t mLastStatisticPushTime = 0;
+ std::unique_ptr<InputEventTimelineProcessor> mInputEventTimelineProcessor GUARDED_BY(mLock);
LatencyTracker mLatencyTracker GUARDED_BY(mLock);
void traceInboundQueueLengthLocked() REQUIRES(mLock);
void traceOutboundQueueLength(const Connection& connection);
diff --git a/services/inputflinger/dispatcher/InputEventTimeline.h b/services/inputflinger/dispatcher/InputEventTimeline.h
index 951fcc8..4552708 100644
--- a/services/inputflinger/dispatcher/InputEventTimeline.h
+++ b/services/inputflinger/dispatcher/InputEventTimeline.h
@@ -121,13 +121,21 @@
class InputEventTimelineProcessor {
protected:
InputEventTimelineProcessor() {}
- virtual ~InputEventTimelineProcessor() {}
public:
+ virtual ~InputEventTimelineProcessor() {}
+
/**
* Process the provided timeline
*/
virtual void processTimeline(const InputEventTimeline& timeline) = 0;
+
+ /**
+ * Trigger a push for the input event latency statistics
+ */
+ virtual void pushLatencyStatistics() = 0;
+
+ virtual std::string dump(const char* prefix) const = 0;
};
} // namespace inputdispatcher
diff --git a/services/inputflinger/dispatcher/LatencyAggregator.cpp b/services/inputflinger/dispatcher/LatencyAggregator.cpp
index 4ddd2e9..d0e9d7c 100644
--- a/services/inputflinger/dispatcher/LatencyAggregator.cpp
+++ b/services/inputflinger/dispatcher/LatencyAggregator.cpp
@@ -28,6 +28,8 @@
using dist_proc::aggregation::KllQuantile;
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) {
@@ -74,6 +76,8 @@
return std::chrono::milliseconds(std::stoi(millis));
}
+} // namespace
+
namespace android::inputdispatcher {
/**
@@ -125,6 +129,9 @@
processSlowEvent(timeline);
}
+// This version of LatencyAggregator doesn't push any atoms
+void LatencyAggregator::pushLatencyStatistics() {}
+
void LatencyAggregator::processStatistics(const InputEventTimeline& timeline) {
std::scoped_lock lock(mLock);
// Before we do any processing, check that we have not yet exceeded MAX_SIZE
diff --git a/services/inputflinger/dispatcher/LatencyAggregator.h b/services/inputflinger/dispatcher/LatencyAggregator.h
index d6d1686..468add1 100644
--- a/services/inputflinger/dispatcher/LatencyAggregator.h
+++ b/services/inputflinger/dispatcher/LatencyAggregator.h
@@ -57,6 +57,8 @@
*/
void processTimeline(const InputEventTimeline& timeline) override;
+ void pushLatencyStatistics() override;
+
std::string dump(const char* prefix) const;
~LatencyAggregator();
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
diff --git a/services/inputflinger/dispatcher/LatencyAggregatorWithHistograms.h b/services/inputflinger/dispatcher/LatencyAggregatorWithHistograms.h
new file mode 100644
index 0000000..2ceb0e7
--- /dev/null
+++ b/services/inputflinger/dispatcher/LatencyAggregatorWithHistograms.h
@@ -0,0 +1,164 @@
+/*
+ * 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.
+ */
+
+#pragma once
+
+#include <android-base/thread_annotations.h>
+#include <utils/Timers.h>
+
+#include "InputEventTimeline.h"
+
+namespace android::inputdispatcher {
+
+static constexpr size_t NUM_BINS = 20;
+static constexpr size_t NUM_INPUT_EVENT_TYPES = 6;
+
+enum class LatencyStageIndex : size_t {
+ EVENT_TO_READ = 0,
+ READ_TO_DELIVER = 1,
+ DELIVER_TO_CONSUME = 2,
+ CONSUME_TO_FINISH = 3,
+ CONSUME_TO_GPU_COMPLETE = 4,
+ GPU_COMPLETE_TO_PRESENT = 5,
+ END_TO_END = 6,
+ SIZE = 7, // must be last
+};
+
+// Let's create a full timeline here:
+// eventTime
+// readTime
+// <---- after this point, the data becomes per-connection
+// deliveryTime // time at which the event was sent to the receiver
+// consumeTime // time at which the receiver read the event
+// finishTime // time at which the dispatcher reads the response from the receiver that the event
+// was processed
+// GraphicsTimeline::GPU_COMPLETED_TIME
+// GraphicsTimeline::PRESENT_TIME
+
+/**
+ * Keep histograms with latencies of the provided events
+ */
+class LatencyAggregatorWithHistograms final : public InputEventTimelineProcessor {
+public:
+ /**
+ * Record a complete event timeline
+ */
+ void processTimeline(const InputEventTimeline& timeline) override;
+
+ void pushLatencyStatistics() override;
+
+ std::string dump(const char* prefix) const override;
+
+private:
+ // ---------- Slow event handling ----------
+ void processSlowEvent(const InputEventTimeline& timeline);
+ nsecs_t mLastSlowEventTime = 0;
+ // How many slow events have been skipped due to rate limiting
+ size_t mNumSkippedSlowEvents = 0;
+ // How many events have been received since the last time we reported a slow event
+ size_t mNumEventsSinceLastSlowEventReport = 0;
+
+ // ---------- Statistics handling ----------
+ /**
+ * Data structure to gather time samples into NUM_BINS buckets
+ */
+ class Histogram {
+ public:
+ Histogram(const std::array<int, NUM_BINS - 1>& binSizes) : mBinSizes(binSizes) {
+ mBinCounts.fill(0);
+ }
+
+ // Increments binCounts of the appropriate bin when adding a new sample
+ void addSample(int64_t sample) {
+ size_t binIndex = getSampleBinIndex(sample);
+ mBinCounts[binIndex]++;
+ }
+
+ const std::array<int32_t, NUM_BINS>& getBinCounts() const { return mBinCounts; }
+
+ private:
+ // reference to an array that represents the range of values each bin holds.
+ // in bin i+1 live samples such that *mBinSizes[i] <= sample < *mBinSizes[i+1]
+ const std::array<int, NUM_BINS - 1>& mBinSizes;
+ std::array<int32_t, NUM_BINS>
+ mBinCounts; // the number of samples that currently live in each bin
+
+ size_t getSampleBinIndex(int64_t sample) {
+ auto it = std::upper_bound(mBinSizes.begin(), mBinSizes.end(), sample);
+ return std::distance(mBinSizes.begin(), it);
+ }
+ };
+
+ void processStatistics(const InputEventTimeline& timeline);
+
+ // Identifier for the an input event. If two input events have the same identifiers we
+ // want to use the same histograms to count the latency samples
+ using InputEventLatencyIdentifier =
+ std::tuple<uint16_t /*vendorId*/, uint16_t /*productId*/,
+ const std::set<InputDeviceUsageSource> /*sources*/,
+ InputEventActionType /*inputEventActionType*/>;
+
+ // Maps an input event identifier to an array of 7 histograms, one for each latency
+ // stage. It is cleared after an atom push
+ std::map<InputEventLatencyIdentifier, std::array<Histogram, 7>> mHistograms;
+
+ void addSampleToHistogram(const InputEventLatencyIdentifier& identifier,
+ LatencyStageIndex latencyStageIndex, nsecs_t time);
+
+ // Stores all possible arrays of bin sizes. The order in the vector does not matter, as long
+ // as binSizesMappings points to the right index
+ static constexpr std::array<std::array<int, NUM_BINS - 1>, 6> allBinSizes = {
+ {{10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 60, 65, 70, 75, 80, 85, 90, 95, 100},
+ {1, 2, 3, 4, 5, 6, 8, 10, 12, 14, 16, 18, 20, 22, 24, 26, 28, 30, 32},
+ {15, 30, 45, 60, 75, 90, 105, 120, 135, 150, 165, 180, 195, 210, 225, 240, 255, 270,
+ 285},
+ {40, 80, 120, 160, 200, 240, 280, 320, 360, 400, 440, 480, 520, 560, 600, 640, 680,
+ 720, 760},
+ {20, 40, 60, 80, 100, 120, 140, 160, 180, 200, 220, 240, 260, 280, 300, 320, 340, 360,
+ 380},
+ {200, 300, 400, 500, 600, 700, 800, 900, 1000, 1100, 1200, 1300, 1400, 1500, 1600,
+ 1700, 1800, 1900, 2000}}};
+
+ // Stores indexes in allBinSizes to use with each {LatencyStage, InputEventType} pair.
+ // Bin sizes for a certain latencyStage and inputEventType are at:
+ // *(allBinSizes[binSizesMappings[latencyStageIndex][inputEventTypeIndex]])
+ // inputEventTypeIndex is the int value of InputEventActionType enum decreased by 1 since we
+ // don't want to record latencies for unknown events.
+ // e.g. MOTION_ACTION_DOWN is 0, MOTION_ACTION_MOVE is 1...
+ static constexpr std::array<std::array<int8_t, NUM_INPUT_EVENT_TYPES>,
+ static_cast<size_t>(LatencyStageIndex::SIZE)>
+ binSizesMappings = {{{0, 0, 0, 0, 0, 0},
+ {1, 1, 1, 1, 1, 1},
+ {1, 1, 1, 1, 1, 1},
+ {2, 2, 2, 2, 2, 2},
+ {3, 3, 3, 3, 3, 3},
+ {4, 4, 4, 4, 4, 4},
+ {5, 5, 5, 5, 5, 5}}};
+
+ // Similar to binSizesMappings, but holds the index of the array of bin ranges to use on the
+ // server. The index gets pushed with the atom within the histogram_version field.
+ static constexpr std::array<std::array<int8_t, NUM_INPUT_EVENT_TYPES>,
+ static_cast<size_t>(LatencyStageIndex::SIZE)>
+ histogramVersions = {{{0, 0, 0, 0, 0, 0},
+ {1, 1, 1, 1, 1, 1},
+ {1, 1, 1, 1, 1, 1},
+ {2, 2, 2, 2, 2, 2},
+ {3, 3, 3, 3, 3, 3},
+ {4, 4, 4, 4, 4, 4},
+ {5, 5, 5, 5, 5, 5}}};
+};
+
+} // namespace android::inputdispatcher
diff --git a/services/inputflinger/dispatcher/LatencyTracker.cpp b/services/inputflinger/dispatcher/LatencyTracker.cpp
index 69024b3..d203fba 100644
--- a/services/inputflinger/dispatcher/LatencyTracker.cpp
+++ b/services/inputflinger/dispatcher/LatencyTracker.cpp
@@ -62,10 +62,8 @@
}
}
-LatencyTracker::LatencyTracker(InputEventTimelineProcessor* processor)
- : mTimelineProcessor(processor) {
- LOG_ALWAYS_FATAL_IF(processor == nullptr);
-}
+LatencyTracker::LatencyTracker(InputEventTimelineProcessor& processor)
+ : mTimelineProcessor(&processor) {}
void LatencyTracker::trackListener(int32_t inputEventId, nsecs_t eventTime, nsecs_t readTime,
DeviceId deviceId,
diff --git a/services/inputflinger/dispatcher/LatencyTracker.h b/services/inputflinger/dispatcher/LatencyTracker.h
index b4053ba..80d3f2f 100644
--- a/services/inputflinger/dispatcher/LatencyTracker.h
+++ b/services/inputflinger/dispatcher/LatencyTracker.h
@@ -42,7 +42,7 @@
* Create a LatencyTracker.
* param reportingFunction: the function that will be called in order to report full latency.
*/
- LatencyTracker(InputEventTimelineProcessor* processor);
+ LatencyTracker(InputEventTimelineProcessor& processor);
/**
* Start keeping track of an event identified by inputEventId. This must be called first.
* If duplicate events are encountered (events that have the same eventId), none of them will be
diff --git a/services/inputflinger/tests/LatencyTracker_test.cpp b/services/inputflinger/tests/LatencyTracker_test.cpp
index 0f92833..3f14c23 100644
--- a/services/inputflinger/tests/LatencyTracker_test.cpp
+++ b/services/inputflinger/tests/LatencyTracker_test.cpp
@@ -87,7 +87,7 @@
connection1 = sp<BBinder>::make();
connection2 = sp<BBinder>::make();
- mTracker = std::make_unique<LatencyTracker>(this);
+ mTracker = std::make_unique<LatencyTracker>(*this);
setDefaultInputDeviceInfo(*mTracker);
}
void TearDown() override {}
@@ -106,6 +106,8 @@
void processTimeline(const InputEventTimeline& timeline) override {
mReceivedTimelines.push_back(timeline);
}
+ void pushLatencyStatistics() override {}
+ std::string dump(const char* prefix) const { return ""; };
std::deque<InputEventTimeline> mReceivedTimelines;
};
diff --git a/services/inputflinger/tests/fuzzers/LatencyTrackerFuzzer.cpp b/services/inputflinger/tests/fuzzers/LatencyTrackerFuzzer.cpp
index 695eb3c..908fa40 100644
--- a/services/inputflinger/tests/fuzzers/LatencyTrackerFuzzer.cpp
+++ b/services/inputflinger/tests/fuzzers/LatencyTrackerFuzzer.cpp
@@ -38,6 +38,10 @@
connectionTimeline.isComplete();
}
};
+
+ void pushLatencyStatistics() override {}
+
+ std::string dump(const char* prefix) const { return ""; };
};
static sp<IBinder> getConnectionToken(FuzzedDataProvider& fdp,
@@ -53,7 +57,7 @@
FuzzedDataProvider fdp(data, size);
EmptyProcessor emptyProcessor;
- LatencyTracker tracker(&emptyProcessor);
+ LatencyTracker tracker(emptyProcessor);
// Make some pre-defined tokens to ensure that some timelines are complete.
std::array<sp<IBinder> /*token*/, 10> predefinedTokens;