Log warnings for slow input event interceptions.
InputDispatcher is mostly self-contained, but reaches out to the rest of
the world when it checks to see if an event needs to be intercepted. We
should make sure these interceptions stay fast as it blocks the whole
input system when they aren't. Worse, if the reason we're slow is that
we've called into an ANRing part of the system, we won't actually be
able to trigger the ANR and dump stacks until after its already
recovered.
Also, apply constexpr to a few more constants.
Bug: 72113907
Test: build, flash, see it complain if I make it artificially slow
Change-Id: Iff4a4fbeda963a00538720eebdb3fd5bd81f9875
diff --git a/services/inputflinger/InputDispatcher.cpp b/services/inputflinger/InputDispatcher.cpp
index 86492fd..c3f4f58 100644
--- a/services/inputflinger/InputDispatcher.cpp
+++ b/services/inputflinger/InputDispatcher.cpp
@@ -52,6 +52,7 @@
#include <time.h>
#include <unistd.h>
+#include <android-base/chrono_utils.h>
#include <android-base/stringprintf.h>
#include <log/log.h>
#include <utils/Trace.h>
@@ -69,28 +70,32 @@
// Default input dispatching timeout if there is no focused application or paused window
// from which to determine an appropriate dispatching timeout.
-const nsecs_t DEFAULT_INPUT_DISPATCHING_TIMEOUT = 5000 * 1000000LL; // 5 sec
+constexpr nsecs_t DEFAULT_INPUT_DISPATCHING_TIMEOUT = 5000 * 1000000LL; // 5 sec
// Amount of time to allow for all pending events to be processed when an app switch
// key is on the way. This is used to preempt input dispatch and drop input events
// when an application takes too long to respond and the user has pressed an app switch key.
-const nsecs_t APP_SWITCH_TIMEOUT = 500 * 1000000LL; // 0.5sec
+constexpr nsecs_t APP_SWITCH_TIMEOUT = 500 * 1000000LL; // 0.5sec
// Amount of time to allow for an event to be dispatched (measured since its eventTime)
// before considering it stale and dropping it.
-const nsecs_t STALE_EVENT_TIMEOUT = 10000 * 1000000LL; // 10sec
+constexpr nsecs_t STALE_EVENT_TIMEOUT = 10000 * 1000000LL; // 10sec
// Amount of time to allow touch events to be streamed out to a connection before requiring
// that the first event be finished. This value extends the ANR timeout by the specified
// amount. For example, if streaming is allowed to get ahead by one second relative to the
// queue of waiting unfinished events, then ANRs will similarly be delayed by one second.
-const nsecs_t STREAM_AHEAD_EVENT_TIMEOUT = 500 * 1000000LL; // 0.5sec
+constexpr nsecs_t STREAM_AHEAD_EVENT_TIMEOUT = 500 * 1000000LL; // 0.5sec
// Log a warning when an event takes longer than this to process, even if an ANR does not occur.
-const nsecs_t SLOW_EVENT_PROCESSING_WARNING_TIMEOUT = 2000 * 1000000LL; // 2sec
+constexpr nsecs_t SLOW_EVENT_PROCESSING_WARNING_TIMEOUT = 2000 * 1000000LL; // 2sec
+
+// Log a warning when an interception call takes longer than this to process.
+constexpr std::chrono::milliseconds SLOW_INTERCEPTION_THRESHOLD = 50ms;
// Number of recent events to keep for debugging purposes.
-const size_t RECENT_QUEUE_MAX_SIZE = 10;
+constexpr size_t RECENT_QUEUE_MAX_SIZE = 10;
+
static inline nsecs_t now() {
return systemTime(SYSTEM_TIME_MONOTONIC);
@@ -2448,7 +2453,12 @@
flags, keyCode, args->scanCode, metaState, 0,
args->downTime, args->eventTime);
+ android::base::Timer t;
mPolicy->interceptKeyBeforeQueueing(&event, /*byref*/ policyFlags);
+ if (t.duration() > SLOW_INTERCEPTION_THRESHOLD) {
+ ALOGW("Excessive delay in interceptKeyBeforeQueueing; took %s ms",
+ std::to_string(t.duration().count()).c_str());
+ }
bool needWake;
{ // acquire lock
@@ -2517,7 +2527,13 @@
uint32_t policyFlags = args->policyFlags;
policyFlags |= POLICY_FLAG_TRUSTED;
+
+ android::base::Timer t;
mPolicy->interceptMotionBeforeQueueing(args->eventTime, /*byref*/ policyFlags);
+ if (t.duration() > SLOW_INTERCEPTION_THRESHOLD) {
+ ALOGW("Excessive delay in interceptMotionBeforeQueueing; took %s ms",
+ std::to_string(t.duration().count()).c_str());
+ }
bool needWake;
{ // acquire lock
@@ -2629,7 +2645,12 @@
}
if (!(policyFlags & POLICY_FLAG_FILTERED)) {
+ android::base::Timer t;
mPolicy->interceptKeyBeforeQueueing(keyEvent, /*byref*/ policyFlags);
+ if (t.duration() > SLOW_INTERCEPTION_THRESHOLD) {
+ ALOGW("Excessive delay in interceptKeyBeforeQueueing; took %s ms",
+ std::to_string(t.duration().count()).c_str());
+ }
}
mLock.lock();
@@ -2654,7 +2675,12 @@
if (!(policyFlags & POLICY_FLAG_FILTERED)) {
nsecs_t eventTime = motionEvent->getEventTime();
+ android::base::Timer t;
mPolicy->interceptMotionBeforeQueueing(eventTime, /*byref*/ policyFlags);
+ if (t.duration() > SLOW_INTERCEPTION_THRESHOLD) {
+ ALOGW("Excessive delay in interceptMotionBeforeQueueing; took %s ms",
+ std::to_string(t.duration().count()).c_str());
+ }
}
mLock.lock();
@@ -3540,8 +3566,13 @@
mLock.unlock();
+ android::base::Timer t;
nsecs_t delay = mPolicy->interceptKeyBeforeDispatching(commandEntry->inputWindowHandle,
&event, entry->policyFlags);
+ if (t.duration() > SLOW_INTERCEPTION_THRESHOLD) {
+ ALOGW("Excessive delay in interceptKeyBeforeDispatching; took %s ms",
+ std::to_string(t.duration().count()).c_str());
+ }
mLock.lock();