From 3a6cc55a2ea651c99e5449416e996f46014e1ade Mon Sep 17 00:00:00 2001 From: Bcan Date: Mon, 29 Jul 2024 17:15:17 +0800 Subject: [PATCH] Add debug messages for losing OK key (2/2) --- .../dispatcher/InputDispatcher.cpp | 31 +++++++++++++------ services/inputflinger/reader/EventHub.cpp | 12 +++++++ services/inputflinger/reader/InputDevice.cpp | 1 + services/inputflinger/reader/InputReader.cpp | 8 +++++ .../reader/mapper/KeyboardInputMapper.cpp | 1 + 5 files changed, 44 insertions(+), 9 deletions(-) diff --git a/services/inputflinger/dispatcher/InputDispatcher.cpp b/services/inputflinger/dispatcher/InputDispatcher.cpp index 09561fb2be..71d3554d40 100644 --- a/services/inputflinger/dispatcher/InputDispatcher.cpp +++ b/services/inputflinger/dispatcher/InputDispatcher.cpp @@ -19,35 +19,35 @@ #define ATRACE_TAG ATRACE_TAG_INPUT -#define LOG_NDEBUG 1 +#define LOG_NDEBUG 0 // Log detailed debug messages about each inbound event notification to the dispatcher. -#define DEBUG_INBOUND_EVENT_DETAILS 0 +#define DEBUG_INBOUND_EVENT_DETAILS 1 // Log detailed debug messages about each outbound event processed by the dispatcher. -#define DEBUG_OUTBOUND_EVENT_DETAILS 0 +#define DEBUG_OUTBOUND_EVENT_DETAILS 1 // Log debug messages about the dispatch cycle. -#define DEBUG_DISPATCH_CYCLE 0 +#define DEBUG_DISPATCH_CYCLE 1 // Log debug messages about channel creation -#define DEBUG_CHANNEL_CREATION 0 +#define DEBUG_CHANNEL_CREATION 1 // Log debug messages about input event injection. -#define DEBUG_INJECTION 0 +#define DEBUG_INJECTION 1 // Log debug messages about input focus tracking. -static constexpr bool DEBUG_FOCUS = false; +static constexpr bool DEBUG_FOCUS = true; // Log debug messages about touch occlusion // STOPSHIP(b/169067926): Set to false static constexpr bool DEBUG_TOUCH_OCCLUSION = true; // Log debug messages about the app switch latency optimization. -#define DEBUG_APP_SWITCH 0 +#define DEBUG_APP_SWITCH 1 // Log debug messages about hover events. -#define DEBUG_HOVER 0 +#define DEBUG_HOVER 1 #include #include @@ -685,6 +685,7 @@ std::chrono::nanoseconds InputDispatcher::getDispatchingTimeoutLocked(const sp traceKey A10, mDispatchEnabled=%d, mDispatchFrozen=%d in %s of %s line %d" ,mDispatchEnabled ,mDispatchFrozen ,__func__ ,__FILE__ ,__LINE__); // Reset the key repeat timer whenever normal dispatch is suspended while the // device is in a non-interactive state. This is to ensure that we abort a key // repeat if the device is just coming out of sleep. @@ -697,6 +698,7 @@ void InputDispatcher::dispatchOnceInnerLocked(nsecs_t* nextWakeupTime) { if (DEBUG_FOCUS) { ALOGD("Dispatch frozen. Waiting some more."); } + ALOGI("===> traceKey A9.2 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); return; } @@ -732,6 +734,7 @@ void InputDispatcher::dispatchOnceInnerLocked(nsecs_t* nextWakeupTime) { // Nothing to do if there is no pending event. if (!mPendingEvent) { + ALOGI("===> traceKey A9.1 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); return; } } else { @@ -747,6 +750,7 @@ void InputDispatcher::dispatchOnceInnerLocked(nsecs_t* nextWakeupTime) { } } + ALOGI("===> traceKey A9 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); // Now we have an event to dispatch. // All events are eventually dequeued and processed this way, even if we intend to drop them. ALOG_ASSERT(mPendingEvent != nullptr); @@ -820,6 +824,7 @@ void InputDispatcher::dispatchOnceInnerLocked(nsecs_t* nextWakeupTime) { if (dropReason == DropReason::NOT_DROPPED && mNextUnblockedEvent) { dropReason = DropReason::BLOCKED; } + ALOGI("===> traceKey A8, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); done = dispatchKeyLocked(currentTime, keyEntry, &dropReason, nextWakeupTime); break; } @@ -1363,6 +1368,7 @@ void InputDispatcher::dispatchPointerCaptureChangedLocked( bool InputDispatcher::dispatchKeyLocked(nsecs_t currentTime, std::shared_ptr entry, DropReason* dropReason, nsecs_t* nextWakeupTime) { + ALOGI("===> traceKey A7.2, keycode=%d, interceptKeyResult=%d, in %s of %s line %d" ,entry->keyCode ,entry->interceptKeyResult ,__func__ ,__FILE__ ,__LINE__); // Preprocessing. if (!entry->dispatchInProgress) { if (entry->repeatCount == 0 && entry->action == AKEY_EVENT_ACTION_DOWN && @@ -1416,15 +1422,18 @@ bool InputDispatcher::dispatchKeyLocked(nsecs_t currentTime, std::shared_ptrinterceptKeyWakeupTime < *nextWakeupTime) { *nextWakeupTime = entry->interceptKeyWakeupTime; } + ALOGI("===> traceKey A7.1, keycode=%d, interceptKeyResult=%d, in %s of %s line %d" ,entry->keyCode ,entry->interceptKeyResult ,__func__ ,__FILE__ ,__LINE__); return false; // wait until next wakeup } entry->interceptKeyResult = KeyEntry::INTERCEPT_KEY_RESULT_UNKNOWN; entry->interceptKeyWakeupTime = 0; } + ALOGI("===> traceKey A7, keycode=%d, interceptKeyResult=%d, in %s of %s line %d" ,entry->keyCode ,entry->interceptKeyResult ,__func__ ,__FILE__ ,__LINE__); // Give the policy a chance to intercept the key. if (entry->interceptKeyResult == KeyEntry::INTERCEPT_KEY_RESULT_UNKNOWN) { if (entry->policyFlags & POLICY_FLAG_PASS_TO_USER) { + ALOGI("===> traceKey A6, keycode=%d, interceptKeyResult=%d, in %s of %s line %d" ,entry->keyCode ,entry->interceptKeyResult ,__func__ ,__FILE__ ,__LINE__); std::unique_ptr commandEntry = std::make_unique( &InputDispatcher::doInterceptKeyBeforeDispatchingLockedInterruptible); sp focusedWindowToken = @@ -1448,6 +1457,7 @@ bool InputDispatcher::dispatchKeyLocked(nsecs_t currentTime, std::shared_ptrreportDroppedKey(entry->id); + ALOGI("===> traceKey A5.4, keycode=%d, interceptKeyResult=%d in %s of %s line %d", entry->keyCode, entry->interceptKeyResult, __func__, __FILE__, __LINE__); return true; } @@ -1456,11 +1466,13 @@ bool InputDispatcher::dispatchKeyLocked(nsecs_t currentTime, std::shared_ptr traceKey A5.3, keycode=%d, interceptKeyResult=%d in %s of %s line %d", entry->keyCode, entry->interceptKeyResult, __func__, __FILE__, __LINE__); return false; } setInjectionResult(*entry, injectionResult); if (injectionResult != InputEventInjectionResult::SUCCEEDED) { + ALOGI("===> traceKey A5.2, keycode=%d, interceptKeyResult=%d in %s of %s line %d", entry->keyCode, entry->interceptKeyResult, __func__, __FILE__, __LINE__); return true; } @@ -5704,6 +5716,7 @@ void InputDispatcher::doInterceptKeyBeforeDispatchingLockedInterruptible( android::base::Timer t; const sp& token = commandEntry->connectionToken; + ALOGI("===> traceKey A5, keycode=%d in %s of %s line %d", event.getKeyCode(), __func__, __FILE__, __LINE__); nsecs_t delay = mPolicy->interceptKeyBeforeDispatching(token, &event, entry.policyFlags); if (t.duration() > SLOW_INTERCEPTION_THRESHOLD) { ALOGW("Excessive delay in interceptKeyBeforeDispatching; took %s ms", diff --git a/services/inputflinger/reader/EventHub.cpp b/services/inputflinger/reader/EventHub.cpp index b19b4195d1..de1135e754 100644 --- a/services/inputflinger/reader/EventHub.cpp +++ b/services/inputflinger/reader/EventHub.cpp @@ -1545,6 +1545,7 @@ size_t EventHub::getEvents(int timeoutMillis, RawEvent* buffer, size_t bufferSiz } } + ALOGI("===> traceKey D7, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); // Grab the next input event. bool deviceChanged = false; while (mPendingEventIndex < mPendingEventCount) { @@ -1601,27 +1602,34 @@ size_t EventHub::getEvents(int timeoutMillis, RawEvent* buffer, size_t bufferSiz } continue; } + + ALOGI("===> traceKey D6, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); // This must be an input event if (eventItem.events & EPOLLIN) { int32_t readSize = read(device->fd, readBuffer, sizeof(struct input_event) * capacity); + ALOGI("===> traceKey D6-1, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); if (readSize == 0 || (readSize < 0 && errno == ENODEV)) { // Device was removed before INotify noticed. ALOGW("could not get event, removed? (fd: %d size: %" PRId32 " bufferSize: %zu capacity: %zu errno: %d)\n", device->fd, readSize, bufferSize, capacity, errno); + ALOGI("===> traceKey D6-1a, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); deviceChanged = true; closeDeviceLocked(*device); } else if (readSize < 0) { + ALOGI("===> traceKey D6-1b, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); if (errno != EAGAIN && errno != EINTR) { ALOGW("could not get event (errno=%d)", errno); } } else if ((readSize % sizeof(struct input_event)) != 0) { + ALOGI("===> traceKey D6-1c, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); ALOGE("could not get event (wrong size: %d)", readSize); } else { int32_t deviceId = device->id == mBuiltInKeyboardId ? 0 : device->id; size_t count = size_t(readSize) / sizeof(struct input_event); + ALOGI("===> traceKey D6-1d, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); for (size_t i = 0; i < count; i++) { struct input_event& iev = readBuffer[i]; event->when = processEventTimestamp(iev); @@ -1634,6 +1642,7 @@ size_t EventHub::getEvents(int timeoutMillis, RawEvent* buffer, size_t bufferSiz capacity -= 1; } if (capacity == 0) { + ALOGI("===> traceKey D6-1d buffer full, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); // The result buffer is full. Reset the pending event index // so we will try to read the device again on the next iteration. mPendingEventIndex -= 1; @@ -1641,16 +1650,19 @@ size_t EventHub::getEvents(int timeoutMillis, RawEvent* buffer, size_t bufferSiz } } } else if (eventItem.events & EPOLLHUP) { + ALOGI("===> traceKey D6-2, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); ALOGI("Removing device %s due to epoll hang-up event.", device->identifier.name.c_str()); deviceChanged = true; closeDeviceLocked(*device); } else { + ALOGI("===> traceKey D6-3, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); ALOGW("Received unexpected epoll event 0x%08x for device %s.", eventItem.events, device->identifier.name.c_str()); } } + ALOGI("===> traceKey D5, in getEvents, in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); // readNotify() will modify the list of devices so this must be done after // processing all other events to ensure that we read all remaining events // before closing the devices. diff --git a/services/inputflinger/reader/InputDevice.cpp b/services/inputflinger/reader/InputDevice.cpp index 7af014cb34..a476bf7108 100644 --- a/services/inputflinger/reader/InputDevice.cpp +++ b/services/inputflinger/reader/InputDevice.cpp @@ -401,6 +401,7 @@ void InputDevice::process(const RawEvent* rawEvents, size_t count) { reset(rawEvent->when); } else { for_each_mapper_in_subdevice(rawEvent->deviceId, [rawEvent](InputMapper& mapper) { + ALOGI("===> traceKey C0.2 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); mapper.process(rawEvent); }); } diff --git a/services/inputflinger/reader/InputReader.cpp b/services/inputflinger/reader/InputReader.cpp index 10c04f606c..74c7963b84 100644 --- a/services/inputflinger/reader/InputReader.cpp +++ b/services/inputflinger/reader/InputReader.cpp @@ -34,6 +34,8 @@ #include "InputDevice.h" +#define BLOGI(...) ALOG(LOG_INFO, "BFXBTF-484", __VA_ARGS__) + using android::base::StringPrintf; namespace android { @@ -112,6 +114,7 @@ void InputReader::loopOnce() { mReaderIsAliveCondition.notify_all(); if (count) { + ALOGI("===> traceKey C3 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); processEventsLocked(mEventBuffer, count); } @@ -144,6 +147,7 @@ void InputReader::loopOnce() { // resulting in a deadlock. This situation is actually quite plausible because the // listener is actually the input dispatcher, which calls into the window manager, // which occasionally calls into the input reader. + ALOGI("===> traceKey C0 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); mQueuedListener->flush(); } @@ -163,6 +167,7 @@ void InputReader::processEventsLocked(const RawEvent* rawEvents, size_t count) { #if DEBUG_RAW_EVENTS ALOGD("BatchSize: %zu Count: %zu", batchSize, count); #endif + ALOGI("===> traceKey C2 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); processEventsForDeviceLocked(deviceId, rawEvent, batchSize); } else { switch (rawEvent->type) { @@ -298,15 +303,18 @@ void InputReader::processEventsForDeviceLocked(int32_t eventHubId, const RawEven auto deviceIt = mDevices.find(eventHubId); if (deviceIt == mDevices.end()) { ALOGW("Discarding event for unknown eventHubId %d.", eventHubId); + BLOGI("===> traceKey C1.2 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); return; } std::shared_ptr& device = deviceIt->second; if (device->isIgnored()) { // ALOGD("Discarding event for ignored deviceId %d.", deviceId); + BLOGI("===> traceKey C1.1 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); return; } + ALOGI("===> traceKey C1 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); device->process(rawEvents, count); } diff --git a/services/inputflinger/reader/mapper/KeyboardInputMapper.cpp b/services/inputflinger/reader/mapper/KeyboardInputMapper.cpp index 2ebca43c57..8860b18394 100644 --- a/services/inputflinger/reader/mapper/KeyboardInputMapper.cpp +++ b/services/inputflinger/reader/mapper/KeyboardInputMapper.cpp @@ -214,6 +214,7 @@ void KeyboardInputMapper::process(const RawEvent* rawEvent) { mCurrentHidUsage = 0; if (isKeyboardOrGamepadKey(scanCode)) { + ALOGI("===> traceKey C0.1 in %s of %s line %d" ,__func__ ,__FILE__ ,__LINE__); processKey(rawEvent->when, rawEvent->readTime, rawEvent->value != 0, scanCode, usageCode); } -- 2.25.1