/* * 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 #include #include #include #include #include #include #include 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(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(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(static_cast(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 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(LatencyStageIndex::EVENT_TO_READ); latencyStageIndex < static_cast(LatencyStageIndex::SIZE); ++latencyStageIndex) { // Convert sources set to vector for atom logging: std::vector sourcesVector = {}; for (auto& elem : sources) { sourcesVector.push_back(static_cast(elem)); } // convert histogram bin counts array to vector for atom logging: std::array arr = histograms[latencyStageIndex].getBinCounts(); std::vector binCountsVector(arr.begin(), arr.end()); if (static_cast(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(static_cast(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)), 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(ns2us(eventToRead)), static_cast(ns2us(readToDeliver)), static_cast(ns2us(deliverToConsume)), static_cast(ns2us(consumeToFinish)), static_cast(ns2us(consumeToGpuComplete)), static_cast(ns2us(gpuCompleteToPresent)), static_cast(ns2us(endToEndLatency.count())), static_cast(mNumEventsSinceLastSlowEventReport), static_cast(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(source)); firstSource = false; } identifierStr += StringPrintf("}, action: %d\n", static_cast(action)); std::string histogramsStr; for (size_t stageIndex = 0; stageIndex < static_cast(LatencyStageIndex::SIZE); stageIndex++) { const auto& histogram = histograms[stageIndex]; const std::array& 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