From 011ca3db7f66293e6e34d2028042008ccb96405d Mon Sep 17 00:00:00 2001 From: Prabir Pradhan Date: Wed, 22 Feb 2023 21:31:39 +0000 Subject: Allow debug logging of raw events to be enabled on the fly Enabling debug logs via adb commands required a reboot of the shell. In order to debug flaky tests more easily, we allow raw event logs to be enabled and disabled without the need for a restart on debuggable builds. We limit this ability to debuggable builds ensure there is no performance overhead on user builds. This change allows us to enable more verbose logging on flaky tests that are hard to reproduce. Bug: 193231132 Test: Manual, using adb command to enable debug logs on userdebug builds Change-Id: I544dbf2ff8258e0bb202653b7ff3d3970f0b752e --- services/inputflinger/reader/Android.bp | 1 + services/inputflinger/reader/InputDevice.cpp | 6 +-- services/inputflinger/reader/InputReader.cpp | 4 +- services/inputflinger/reader/Macros.cpp | 43 ++++++++++++++++++++++ services/inputflinger/reader/Macros.h | 10 +++-- .../reader/mapper/TouchInputMapper.cpp | 2 +- 6 files changed, 57 insertions(+), 9 deletions(-) create mode 100644 services/inputflinger/reader/Macros.cpp diff --git a/services/inputflinger/reader/Android.bp b/services/inputflinger/reader/Android.bp index d29692cf05..132c3a1004 100644 --- a/services/inputflinger/reader/Android.bp +++ b/services/inputflinger/reader/Android.bp @@ -39,6 +39,7 @@ filegroup { "EventHub.cpp", "InputDevice.cpp", "InputReader.cpp", + "Macros.cpp", "TouchVideoDevice.cpp", "controller/PeripheralController.cpp", "mapper/CursorInputMapper.cpp", diff --git a/services/inputflinger/reader/InputDevice.cpp b/services/inputflinger/reader/InputDevice.cpp index c598c0a700..002de2933b 100644 --- a/services/inputflinger/reader/InputDevice.cpp +++ b/services/inputflinger/reader/InputDevice.cpp @@ -412,7 +412,7 @@ std::list InputDevice::process(const RawEvent* rawEvents, size_t cou // in the order received. std::list out; for (const RawEvent* rawEvent = rawEvents; count != 0; rawEvent++) { - if (DEBUG_RAW_EVENTS) { + if (debugRawEvents()) { ALOGD("Input event: device=%d type=0x%04x code=0x%04x value=0x%08x when=%" PRId64, rawEvent->deviceId, rawEvent->type, rawEvent->code, rawEvent->value, rawEvent->when); @@ -421,11 +421,11 @@ std::list InputDevice::process(const RawEvent* rawEvents, size_t cou if (mDropUntilNextSync) { if (rawEvent->type == EV_SYN && rawEvent->code == SYN_REPORT) { mDropUntilNextSync = false; - if (DEBUG_RAW_EVENTS) { + if (debugRawEvents()) { ALOGD("Recovered from input event buffer overrun."); } } else { - if (DEBUG_RAW_EVENTS) { + if (debugRawEvents()) { ALOGD("Dropped input event while waiting for next input sync."); } } diff --git a/services/inputflinger/reader/InputReader.cpp b/services/inputflinger/reader/InputReader.cpp index 57f679c022..9080cc1d26 100644 --- a/services/inputflinger/reader/InputReader.cpp +++ b/services/inputflinger/reader/InputReader.cpp @@ -146,7 +146,7 @@ void InputReader::loopOnce() { if (mNextTimeout != LLONG_MAX) { nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC); if (now >= mNextTimeout) { - if (DEBUG_RAW_EVENTS) { + if (debugRawEvents()) { ALOGD("Timeout expired, latency=%0.3fms", (now - mNextTimeout) * 0.000001f); } mNextTimeout = LLONG_MAX; @@ -199,7 +199,7 @@ std::list InputReader::processEventsLocked(const RawEvent* rawEvents } batchSize += 1; } - if (DEBUG_RAW_EVENTS) { + if (debugRawEvents()) { ALOGD("BatchSize: %zu Count: %zu", batchSize, count); } out += processEventsForDeviceLocked(deviceId, rawEvent, batchSize); diff --git a/services/inputflinger/reader/Macros.cpp b/services/inputflinger/reader/Macros.cpp new file mode 100644 index 0000000000..8841d0f14a --- /dev/null +++ b/services/inputflinger/reader/Macros.cpp @@ -0,0 +1,43 @@ +/* + * Copyright (C) 2023 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. + */ + +#include "Macros.h" + +#include + +namespace { + +const bool IS_DEBUGGABLE_BUILD = +#if defined(__ANDROID__) + android::base::GetBoolProperty("ro.debuggable", false); +#else + true; +#endif + +} // namespace + +namespace android { + +bool debugRawEvents() { + if (!IS_DEBUGGABLE_BUILD) { + static const bool DEBUG_RAW_EVENTS = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "RawEvents", ANDROID_LOG_INFO); + return DEBUG_RAW_EVENTS; + } + return __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "RawEvents", ANDROID_LOG_INFO); +} + +} // namespace android diff --git a/services/inputflinger/reader/Macros.h b/services/inputflinger/reader/Macros.h index d2a7ced864..2bce215b3c 100644 --- a/services/inputflinger/reader/Macros.h +++ b/services/inputflinger/reader/Macros.h @@ -25,12 +25,14 @@ #include namespace android { + /** * Log debug messages for each raw event received from the EventHub. - * Enable this via "adb shell setprop log.tag.InputReaderRawEvents DEBUG" (requires restart) + * Enable this via "adb shell setprop log.tag.InputReaderRawEvents DEBUG". + * This requires a restart on non-debuggable (e.g. user) builds, but should take effect immediately + * on debuggable builds (e.g. userdebug). */ -const bool DEBUG_RAW_EVENTS = - __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "RawEvents", ANDROID_LOG_INFO); +bool debugRawEvents(); /** * Log debug messages about virtual key processing. @@ -52,6 +54,7 @@ const bool DEBUG_POINTERS = */ const bool DEBUG_POINTER_ASSIGNMENT = __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "PointerAssignment", ANDROID_LOG_INFO); + /** * Log debug messages about gesture detection. * Enable this via "adb shell setprop log.tag.InputReaderGestures DEBUG" (requires restart) @@ -79,6 +82,7 @@ const bool DEBUG_STYLUS_FUSION = */ const bool DEBUG_LIGHT_DETAILS = __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "LightDetails", ANDROID_LOG_INFO); + } // namespace android #define INDENT " " diff --git a/services/inputflinger/reader/mapper/TouchInputMapper.cpp b/services/inputflinger/reader/mapper/TouchInputMapper.cpp index 31fdac9ffc..3ba6cd08e6 100644 --- a/services/inputflinger/reader/mapper/TouchInputMapper.cpp +++ b/services/inputflinger/reader/mapper/TouchInputMapper.cpp @@ -1446,7 +1446,7 @@ std::list TouchInputMapper::sync(nsecs_t when, nsecs_t readTime) { assignPointerIds(last, next); } - ALOGD_IF(DEBUG_RAW_EVENTS, + ALOGD_IF(debugRawEvents(), "syncTouch: pointerCount %d -> %d, touching ids 0x%08x -> 0x%08x, " "hovering ids 0x%08x -> 0x%08x, canceled ids 0x%08x", last.rawPointerData.pointerCount, next.rawPointerData.pointerCount, -- cgit v1.2.3-59-g8ed1b From 65613809ef0779360a64d7d73ebd6bd894aaded6 Mon Sep 17 00:00:00 2001 From: Prabir Pradhan Date: Wed, 22 Feb 2023 23:36:58 +0000 Subject: Allow debug logging of dispatcher's inbound events to be enabled on the fly Enabling debug logs via adb commands required a reboot of the shell. In order to debug flaky tests more easily, we allow raw event logs to be enabled and disabled without the need for a restart on debuggable builds. We limit this ability to debuggable builds ensure there is no performance overhead on user builds. This change allows us to enable more verbose logging on flaky tests that are hard to reproduce. Bug: 193231132 Test: Manual, using adb command to enable debug logs on userdebug builds Change-Id: Idf6f7fb35ad02e059582b1f0e7b3b2d006ff0730 --- services/inputflinger/dispatcher/Android.bp | 1 + services/inputflinger/dispatcher/DebugConfig.cpp | 40 ++++++++++++++++++++++ services/inputflinger/dispatcher/DebugConfig.h | 15 ++++++-- services/inputflinger/dispatcher/Entry.cpp | 17 ++++----- .../inputflinger/dispatcher/InputDispatcher.cpp | 22 ++++++------ 5 files changed, 70 insertions(+), 25 deletions(-) create mode 100644 services/inputflinger/dispatcher/DebugConfig.cpp diff --git a/services/inputflinger/dispatcher/Android.bp b/services/inputflinger/dispatcher/Android.bp index ab5c5ef99c..da4e42f4fe 100644 --- a/services/inputflinger/dispatcher/Android.bp +++ b/services/inputflinger/dispatcher/Android.bp @@ -34,6 +34,7 @@ filegroup { srcs: [ "AnrTracker.cpp", "Connection.cpp", + "DebugConfig.cpp", "DragState.cpp", "Entry.cpp", "FocusResolver.cpp", diff --git a/services/inputflinger/dispatcher/DebugConfig.cpp b/services/inputflinger/dispatcher/DebugConfig.cpp new file mode 100644 index 0000000000..764194d3d0 --- /dev/null +++ b/services/inputflinger/dispatcher/DebugConfig.cpp @@ -0,0 +1,40 @@ +/* + * Copyright (C) 2023 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. + */ + +#include "DebugConfig.h" + +#include + +namespace android::inputdispatcher { + +const bool IS_DEBUGGABLE_BUILD = +#if defined(__ANDROID__) + android::base::GetBoolProperty("ro.debuggable", false); +#else + true; +#endif + +bool debugInboundEventDetails() { + if (!IS_DEBUGGABLE_BUILD) { + static const bool DEBUG_INBOUND_EVENT_DETAILS = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "InboundEvent", + ANDROID_LOG_INFO); + return DEBUG_INBOUND_EVENT_DETAILS; + } + return __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "InboundEvent", ANDROID_LOG_INFO); +} + +} // namespace android::inputdispatcher diff --git a/services/inputflinger/dispatcher/DebugConfig.h b/services/inputflinger/dispatcher/DebugConfig.h index d2ad40754a..0e260a7a03 100644 --- a/services/inputflinger/dispatcher/DebugConfig.h +++ b/services/inputflinger/dispatcher/DebugConfig.h @@ -22,12 +22,20 @@ #include namespace android::inputdispatcher { + +/** + * Signals whether this is a debuggable Android build. + * This is populated by reading the value of the "ro.debuggable" property. + */ +extern const bool IS_DEBUGGABLE_BUILD; + /** * Log detailed debug messages about each inbound event notification to the dispatcher. - * Enable this via "adb shell setprop log.tag.InputDispatcherInboundEvent DEBUG" (requires restart) + * Enable this via "adb shell setprop log.tag.InputDispatcherInboundEvent DEBUG". + * This requires a restart on non-debuggable (e.g. user) builds, but should take effect immediately + * on debuggable builds (e.g. userdebug). */ -const bool DEBUG_INBOUND_EVENT_DETAILS = - __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "InboundEvent", ANDROID_LOG_INFO); +bool debugInboundEventDetails(); /** * Log detailed debug messages about each outbound event processed by the dispatcher. @@ -90,4 +98,5 @@ const bool DEBUG_APP_SWITCH = */ const bool DEBUG_HOVER = __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Hover", ANDROID_LOG_INFO); + } // namespace android::inputdispatcher diff --git a/services/inputflinger/dispatcher/Entry.cpp b/services/inputflinger/dispatcher/Entry.cpp index 621543a1ee..b625a1b95b 100644 --- a/services/inputflinger/dispatcher/Entry.cpp +++ b/services/inputflinger/dispatcher/Entry.cpp @@ -14,11 +14,13 @@ * limitations under the License. */ +#define LOG_TAG "InputDispatcher" + #include "Entry.h" #include "Connection.h" +#include "DebugConfig.h" -#include #include #include #include @@ -27,13 +29,6 @@ using android::base::StringPrintf; namespace android::inputdispatcher { -static const bool DEBUGGABLE = -#if defined(__ANDROID__) - android::base::GetBoolProperty("ro.debuggable", false); -#else - true; -#endif - VerifiedKeyEvent verifiedKeyEventFromKeyEntry(const KeyEntry& entry) { return {{VerifiedInputEvent::Type::KEY, entry.deviceId, entry.eventTime, entry.source, entry.displayId}, @@ -178,7 +173,7 @@ KeyEntry::KeyEntry(int32_t id, nsecs_t eventTime, int32_t deviceId, uint32_t sou KeyEntry::~KeyEntry() {} std::string KeyEntry::getDescription() const { - if (!DEBUGGABLE) { + if (!IS_DEBUGGABLE_BUILD) { return "KeyEvent"; } return StringPrintf("KeyEvent(deviceId=%d, eventTime=%" PRIu64 ", source=%s, displayId=%" PRId32 @@ -248,7 +243,7 @@ MotionEntry::MotionEntry(int32_t id, nsecs_t eventTime, int32_t deviceId, uint32 MotionEntry::~MotionEntry() {} std::string MotionEntry::getDescription() const { - if (!DEBUGGABLE) { + if (!IS_DEBUGGABLE_BUILD) { return "MotionEvent"; } std::string msg; @@ -298,7 +293,7 @@ std::string SensorEntry::getDescription() const { deviceId, inputEventSourceToString(source).c_str(), ftl::enum_string(sensorType).c_str(), accuracy, hwTimestamp); - if (DEBUGGABLE) { + if (IS_DEBUGGABLE_BUILD) { for (size_t i = 0; i < values.size(); i++) { if (i > 0) { msg += ", "; diff --git a/services/inputflinger/dispatcher/InputDispatcher.cpp b/services/inputflinger/dispatcher/InputDispatcher.cpp index c9f7512d47..ab6a1161bc 100644 --- a/services/inputflinger/dispatcher/InputDispatcher.cpp +++ b/services/inputflinger/dispatcher/InputDispatcher.cpp @@ -1207,7 +1207,7 @@ void InputDispatcher::dropInboundEventLocked(const EventEntry& entry, DropReason const char* reason; switch (dropReason) { case DropReason::POLICY: - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("Dropped event because policy consumed it."); } reason = "inbound event was dropped because the policy consumed it"; @@ -1596,7 +1596,7 @@ bool InputDispatcher::dispatchKeyLocked(nsecs_t currentTime, std::shared_ptraction == AKEY_EVENT_ACTION_UP && mKeyRepeatState.lastKeyEntry && mKeyRepeatState.lastKeyEntry->deviceId != entry->deviceId) { // The key on device 'deviceId' is still down, do not stop key repeat - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("deviceId=%d got KEY_UP as stale", entry->deviceId); } } else if (!entry->syntheticRepeat) { @@ -4016,7 +4016,7 @@ std::unique_ptr InputDispatcher::splitMotionEvent( } void InputDispatcher::notifyConfigurationChanged(const NotifyConfigurationChangedArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifyConfigurationChanged - eventTime=%" PRId64, args->eventTime); } @@ -4072,7 +4072,7 @@ void InputDispatcher::accelerateMetaShortcuts(const int32_t deviceId, const int3 } void InputDispatcher::notifyKey(const NotifyKeyArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifyKey - eventTime=%" PRId64 ", deviceId=%d, source=0x%x, displayId=%" PRId32 "policyFlags=0x%x, action=0x%x, " "flags=0x%x, keyCode=0x%x, scanCode=0x%x, metaState=0x%x, downTime=%" PRId64, @@ -4150,7 +4150,7 @@ bool InputDispatcher::shouldSendKeyToInputFilterLocked(const NotifyKeyArgs* args } void InputDispatcher::notifyMotion(const NotifyMotionArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifyMotion - id=%" PRIx32 " eventTime=%" PRId64 ", deviceId=%d, source=0x%x, " "displayId=%" PRId32 ", policyFlags=0x%x, " "action=%s, actionButton=0x%x, flags=0x%x, metaState=0x%x, buttonState=0x%x, " @@ -4261,7 +4261,7 @@ void InputDispatcher::notifyMotion(const NotifyMotionArgs* args) { } void InputDispatcher::notifySensor(const NotifySensorArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifySensor - id=%" PRIx32 " eventTime=%" PRId64 ", deviceId=%d, source=0x%x, " " sensorType=%s", args->id, args->eventTime, args->deviceId, args->source, @@ -4289,7 +4289,7 @@ void InputDispatcher::notifySensor(const NotifySensorArgs* args) { } void InputDispatcher::notifyVibratorState(const NotifyVibratorStateArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifyVibratorState - eventTime=%" PRId64 ", device=%d, isOn=%d", args->eventTime, args->deviceId, args->isOn); } @@ -4301,7 +4301,7 @@ bool InputDispatcher::shouldSendMotionToInputFilterLocked(const NotifyMotionArgs } void InputDispatcher::notifySwitch(const NotifySwitchArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifySwitch - eventTime=%" PRId64 ", policyFlags=0x%x, switchValues=0x%08x, " "switchMask=0x%08x", args->eventTime, args->policyFlags, args->switchValues, args->switchMask); @@ -4313,7 +4313,7 @@ void InputDispatcher::notifySwitch(const NotifySwitchArgs* args) { } void InputDispatcher::notifyDeviceReset(const NotifyDeviceResetArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifyDeviceReset - eventTime=%" PRId64 ", deviceId=%d", args->eventTime, args->deviceId); } @@ -4333,7 +4333,7 @@ void InputDispatcher::notifyDeviceReset(const NotifyDeviceResetArgs* args) { } void InputDispatcher::notifyPointerCaptureChanged(const NotifyPointerCaptureChangedArgs* args) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("notifyPointerCaptureChanged - eventTime=%" PRId64 ", enabled=%s", args->eventTime, args->request.enable ? "true" : "false"); } @@ -4356,7 +4356,7 @@ InputEventInjectionResult InputDispatcher::injectInputEvent(const InputEvent* ev InputEventInjectionSync syncMode, std::chrono::milliseconds timeout, uint32_t policyFlags) { - if (DEBUG_INBOUND_EVENT_DETAILS) { + if (debugInboundEventDetails()) { ALOGD("injectInputEvent - eventType=%d, targetUid=%s, syncMode=%d, timeout=%lld, " "policyFlags=0x%08x", event->getType(), targetUid ? std::to_string(*targetUid).c_str() : "none", syncMode, -- cgit v1.2.3-59-g8ed1b From 60dd97a5a926433e57d5fc5886908f79ae6cc53c Mon Sep 17 00:00:00 2001 From: Prabir Pradhan Date: Thu, 23 Feb 2023 02:23:02 +0000 Subject: Control logging in InputTransport using sysprops read at boot time Also, split the DEBUG_TRANSPORT_ACTIONS tag into DEBUG_TRANSPORT_PUBLISHER and DEBUG_TRANSPORT_CONSUMER, and add logging for all published events for completeness. Also, improve type, key event, and motion event loggging for readability. Bug: 193231132 Test: Manual, using adb commands to enable debug logs Change-Id: Icae62629fb833aad2ed0f6ad9fa837e4ef9713c0 --- libs/input/InputTransport.cpp | 310 +++++++++++++++++++++--------------------- 1 file changed, 156 insertions(+), 154 deletions(-) diff --git a/libs/input/InputTransport.cpp b/libs/input/InputTransport.cpp index d1cd50ccff..1d57607067 100644 --- a/libs/input/InputTransport.cpp +++ b/libs/input/InputTransport.cpp @@ -5,20 +5,6 @@ // #define LOG_TAG "InputTransport" -//#define LOG_NDEBUG 0 - -// Log debug messages about channel messages (send message, receive message) -#define DEBUG_CHANNEL_MESSAGES 0 - -// Log debug messages whenever InputChannel objects are created/destroyed -static constexpr bool DEBUG_CHANNEL_LIFECYCLE = false; - -// Log debug messages about transport actions -static constexpr bool DEBUG_TRANSPORT_ACTIONS = false; - -// Log debug messages about touch event resampling -#define DEBUG_RESAMPLING 0 - #include #include #include @@ -36,6 +22,48 @@ static constexpr bool DEBUG_TRANSPORT_ACTIONS = false; #include +namespace { + +/** + * Log debug messages about channel messages (send message, receive message). + * Enable this via "adb shell setprop log.tag.InputTransportMessages DEBUG" + * (requires restart) + */ +const bool DEBUG_CHANNEL_MESSAGES = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Messages", ANDROID_LOG_INFO); + +/** + * Log debug messages whenever InputChannel objects are created/destroyed. + * Enable this via "adb shell setprop log.tag.InputTransportLifecycle DEBUG" + * (requires restart) + */ +const bool DEBUG_CHANNEL_LIFECYCLE = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Lifecycle", ANDROID_LOG_INFO); + +/** + * Log debug messages relating to the consumer end of the transport channel. + * Enable this via "adb shell setprop log.tag.InputTransportConsumer DEBUG" (requires restart) + */ + +const bool DEBUG_TRANSPORT_CONSUMER = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Consumer", ANDROID_LOG_INFO); + +/** + * Log debug messages relating to the producer end of the transport channel. + * Enable this via "adb shell setprop log.tag.InputTransportPublisher DEBUG" (requires restart) + */ +const bool DEBUG_TRANSPORT_PUBLISHER = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Publisher", ANDROID_LOG_INFO); + +/** + * Log debug messages about touch event resampling. + * Enable this via "adb shell setprop log.tag.InputTransportResampling DEBUG" (requires restart) + */ +const bool DEBUG_RESAMPLING = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Resampling", ANDROID_LOG_INFO); + +} // namespace + using android::base::StringPrintf; namespace android { @@ -140,7 +168,7 @@ bool InputMessage::isValid(size_t actualSize) const { return valid; } } - ALOGE("Invalid message type: %" PRIu32, header.type); + ALOGE("Invalid message type: %s", ftl::enum_string(header.type).c_str()); return false; } @@ -330,15 +358,13 @@ std::unique_ptr InputChannel::create(const std::string& name, InputChannel::InputChannel(const std::string name, android::base::unique_fd fd, sp token) : mName(std::move(name)), mFd(std::move(fd)), mToken(std::move(token)) { - if (DEBUG_CHANNEL_LIFECYCLE) { - ALOGD("Input channel constructed: name='%s', fd=%d", getName().c_str(), getFd().get()); - } + ALOGD_IF(DEBUG_CHANNEL_LIFECYCLE, "Input channel constructed: name='%s', fd=%d", + getName().c_str(), getFd().get()); } InputChannel::~InputChannel() { - if (DEBUG_CHANNEL_LIFECYCLE) { - ALOGD("Input channel destroyed: name='%s', fd=%d", getName().c_str(), getFd().get()); - } + ALOGD_IF(DEBUG_CHANNEL_LIFECYCLE, "Input channel destroyed: name='%s', fd=%d", + getName().c_str(), getFd().get()); } status_t InputChannel::openInputChannelPair(const std::string& name, @@ -383,10 +409,8 @@ status_t InputChannel::sendMessage(const InputMessage* msg) { if (nWrite < 0) { int error = errno; -#if DEBUG_CHANNEL_MESSAGES - ALOGD("channel '%s' ~ error sending message of type %d, %s", mName.c_str(), - msg->header.type, strerror(error)); -#endif + ALOGD_IF(DEBUG_CHANNEL_MESSAGES, "channel '%s' ~ error sending message of type %s, %s", + mName.c_str(), ftl::enum_string(msg->header.type).c_str(), strerror(error)); if (error == EAGAIN || error == EWOULDBLOCK) { return WOULD_BLOCK; } @@ -397,16 +421,14 @@ status_t InputChannel::sendMessage(const InputMessage* msg) { } if (size_t(nWrite) != msgLength) { -#if DEBUG_CHANNEL_MESSAGES - ALOGD("channel '%s' ~ error sending message type %d, send was incomplete", - mName.c_str(), msg->header.type); -#endif + ALOGD_IF(DEBUG_CHANNEL_MESSAGES, + "channel '%s' ~ error sending message type %s, send was incomplete", mName.c_str(), + ftl::enum_string(msg->header.type).c_str()); return DEAD_OBJECT; } -#if DEBUG_CHANNEL_MESSAGES - ALOGD("channel '%s' ~ sent message of type %d", mName.c_str(), msg->header.type); -#endif + ALOGD_IF(DEBUG_CHANNEL_MESSAGES, "channel '%s' ~ sent message of type %s", mName.c_str(), + ftl::enum_string(msg->header.type).c_str()); return OK; } @@ -418,9 +440,8 @@ status_t InputChannel::receiveMessage(InputMessage* msg) { if (nRead < 0) { int error = errno; -#if DEBUG_CHANNEL_MESSAGES - ALOGD("channel '%s' ~ receive message failed, errno=%d", mName.c_str(), errno); -#endif + ALOGD_IF(DEBUG_CHANNEL_MESSAGES, "channel '%s' ~ receive message failed, errno=%d", + mName.c_str(), errno); if (error == EAGAIN || error == EWOULDBLOCK) { return WOULD_BLOCK; } @@ -431,9 +452,8 @@ status_t InputChannel::receiveMessage(InputMessage* msg) { } if (nRead == 0) { // check for EOF -#if DEBUG_CHANNEL_MESSAGES - ALOGD("channel '%s' ~ receive message failed because peer was closed", mName.c_str()); -#endif + ALOGD_IF(DEBUG_CHANNEL_MESSAGES, + "channel '%s' ~ receive message failed because peer was closed", mName.c_str()); return DEAD_OBJECT; } @@ -442,9 +462,8 @@ status_t InputChannel::receiveMessage(InputMessage* msg) { return BAD_VALUE; } -#if DEBUG_CHANNEL_MESSAGES - ALOGD("channel '%s' ~ received message of type %d", mName.c_str(), msg->header.type); -#endif + ALOGD_IF(DEBUG_CHANNEL_MESSAGES, "channel '%s' ~ received message of type %s", mName.c_str(), + ftl::enum_string(msg->header.type).c_str()); return OK; } @@ -513,17 +532,19 @@ status_t InputPublisher::publishKeyEvent(uint32_t seq, int32_t eventId, int32_t int32_t metaState, int32_t repeatCount, nsecs_t downTime, nsecs_t eventTime) { if (ATRACE_ENABLED()) { - std::string message = StringPrintf("publishKeyEvent(inputChannel=%s, keyCode=%" PRId32 ")", - mChannel->getName().c_str(), keyCode); + std::string message = + StringPrintf("publishKeyEvent(inputChannel=%s, action=%s, keyCode=%s)", + mChannel->getName().c_str(), KeyEvent::actionToString(action), + KeyEvent::getLabel(keyCode)); ATRACE_NAME(message.c_str()); } - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' publisher ~ publishKeyEvent: seq=%u, deviceId=%d, source=0x%x, " - "action=0x%x, flags=0x%x, keyCode=%d, scanCode=%d, metaState=0x%x, repeatCount=%d," - "downTime=%" PRId64 ", eventTime=%" PRId64, - mChannel->getName().c_str(), seq, deviceId, source, action, flags, keyCode, scanCode, - metaState, repeatCount, downTime, eventTime); - } + ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, + "channel '%s' publisher ~ %s: seq=%u, deviceId=%d, source=%s, " + "action=%s, flags=0x%x, keyCode=%s, scanCode=%d, metaState=0x%x, repeatCount=%d," + "downTime=%" PRId64 ", eventTime=%" PRId64, + mChannel->getName().c_str(), __func__, seq, deviceId, + inputEventSourceToString(source).c_str(), KeyEvent::actionToString(action), flags, + KeyEvent::getLabel(keyCode), scanCode, metaState, repeatCount, downTime, eventTime); if (!seq) { ALOGE("Attempted to publish a key event with sequence number 0."); @@ -559,28 +580,29 @@ status_t InputPublisher::publishMotionEvent( uint32_t pointerCount, const PointerProperties* pointerProperties, const PointerCoords* pointerCoords) { if (ATRACE_ENABLED()) { - std::string message = StringPrintf( - "publishMotionEvent(inputChannel=%s, action=%" PRId32 ")", - mChannel->getName().c_str(), action); + std::string message = StringPrintf("publishMotionEvent(inputChannel=%s, action=%s)", + mChannel->getName().c_str(), + MotionEvent::actionToString(action).c_str()); ATRACE_NAME(message.c_str()); } if (verifyEvents()) { mInputVerifier.processMovement(deviceId, action, pointerCount, pointerProperties, pointerCoords, flags); } - if (DEBUG_TRANSPORT_ACTIONS) { + if (DEBUG_TRANSPORT_PUBLISHER) { std::string transformString; transform.dump(transformString, "transform", " "); - ALOGD("channel '%s' publisher ~ publishMotionEvent: seq=%u, deviceId=%d, source=0x%x, " + ALOGD("channel '%s' publisher ~ %s: seq=%u, deviceId=%d, source=%s, " "displayId=%" PRId32 ", " - "action=0x%x, actionButton=0x%08x, flags=0x%x, edgeFlags=0x%x, " + "action=%s, actionButton=0x%08x, flags=0x%x, edgeFlags=0x%x, " "metaState=0x%x, buttonState=0x%x, classification=%s," "xPrecision=%f, yPrecision=%f, downTime=%" PRId64 ", eventTime=%" PRId64 ", " "pointerCount=%" PRIu32 " \n%s", - mChannel->getName().c_str(), seq, deviceId, source, displayId, action, actionButton, - flags, edgeFlags, metaState, buttonState, - motionClassificationToString(classification), xPrecision, yPrecision, downTime, - eventTime, pointerCount, transformString.c_str()); + mChannel->getName().c_str(), __func__, seq, deviceId, + inputEventSourceToString(source).c_str(), displayId, + MotionEvent::actionToString(action).c_str(), actionButton, flags, edgeFlags, + metaState, buttonState, motionClassificationToString(classification), xPrecision, + yPrecision, downTime, eventTime, pointerCount, transformString.c_str()); } if (!seq) { @@ -642,6 +664,8 @@ status_t InputPublisher::publishFocusEvent(uint32_t seq, int32_t eventId, bool h mChannel->getName().c_str(), toString(hasFocus)); ATRACE_NAME(message.c_str()); } + ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, "channel '%s' publisher ~ %s: seq=%u, hasFocus=%s", + mChannel->getName().c_str(), __func__, seq, toString(hasFocus)); InputMessage msg; msg.header.type = InputMessage::Type::FOCUS; @@ -659,6 +683,9 @@ status_t InputPublisher::publishCaptureEvent(uint32_t seq, int32_t eventId, mChannel->getName().c_str(), toString(pointerCaptureEnabled)); ATRACE_NAME(message.c_str()); } + ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, + "channel '%s' publisher ~ %s: seq=%u, pointerCaptureEnabled=%s", + mChannel->getName().c_str(), __func__, seq, toString(pointerCaptureEnabled)); InputMessage msg; msg.header.type = InputMessage::Type::CAPTURE; @@ -676,6 +703,9 @@ status_t InputPublisher::publishDragEvent(uint32_t seq, int32_t eventId, float x mChannel->getName().c_str(), x, y, toString(isExiting)); ATRACE_NAME(message.c_str()); } + ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, + "channel '%s' publisher ~ %s: seq=%u, x=%f, y=%f, isExiting=%s", + mChannel->getName().c_str(), __func__, seq, x, y, toString(isExiting)); InputMessage msg; msg.header.type = InputMessage::Type::DRAG; @@ -694,6 +724,8 @@ status_t InputPublisher::publishTouchModeEvent(uint32_t seq, int32_t eventId, bo mChannel->getName().c_str(), toString(isInTouchMode)); ATRACE_NAME(message.c_str()); } + ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, "channel '%s' publisher ~ %s: seq=%u, isInTouchMode=%s", + mChannel->getName().c_str(), __func__, seq, toString(isInTouchMode)); InputMessage msg; msg.header.type = InputMessage::Type::TOUCH_MODE; @@ -704,9 +736,8 @@ status_t InputPublisher::publishTouchModeEvent(uint32_t seq, int32_t eventId, bo } android::base::Result InputPublisher::receiveConsumerResponse() { - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' publisher ~ %s", mChannel->getName().c_str(), __func__); - } + ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, "channel '%s' publisher ~ %s", mChannel->getName().c_str(), + __func__); InputMessage msg; status_t result = mChannel->receiveMessage(&msg); @@ -751,10 +782,9 @@ bool InputConsumer::isTouchResamplingEnabled() { status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consumeBatches, nsecs_t frameTime, uint32_t* outSeq, InputEvent** outEvent) { - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ consume: consumeBatches=%s, frameTime=%" PRId64, - mChannel->getName().c_str(), toString(consumeBatches), frameTime); - } + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ consume: consumeBatches=%s, frameTime=%" PRId64, + mChannel->getName().c_str(), toString(consumeBatches), frameTime); *outSeq = 0; *outEvent = nullptr; @@ -780,10 +810,9 @@ status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consum if (consumeBatches || result != WOULD_BLOCK) { result = consumeBatch(factory, frameTime, outSeq, outEvent); if (*outEvent) { - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ consumed batch event, seq=%u", - mChannel->getName().c_str(), *outSeq); - } + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ consumed batch event, seq=%u", + mChannel->getName().c_str(), *outSeq); break; } } @@ -799,11 +828,10 @@ status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consum initializeKeyEvent(keyEvent, &mMsg); *outSeq = mMsg.header.seq; *outEvent = keyEvent; - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ consumed key event, seq=%u", - mChannel->getName().c_str(), *outSeq); - } - break; + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ consumed key event, seq=%u", + mChannel->getName().c_str(), *outSeq); + break; } case InputMessage::Type::MOTION: { @@ -812,11 +840,10 @@ status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consum Batch& batch = mBatches[batchIndex]; if (canAddSample(batch, &mMsg)) { batch.samples.push_back(mMsg); - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ appended to batch event", - mChannel->getName().c_str()); - } - break; + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ appended to batch event", + mChannel->getName().c_str()); + break; } else if (isPointerEvent(mMsg.body.motion.source) && mMsg.body.motion.action == AMOTION_EVENT_ACTION_CANCEL) { // No need to process events that we are going to cancel anyways @@ -837,12 +864,11 @@ status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consum if (result) { return result; } - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ consumed batch event and " - "deferred current event, seq=%u", - mChannel->getName().c_str(), *outSeq); - } - break; + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ consumed batch event and " + "deferred current event, seq=%u", + mChannel->getName().c_str(), *outSeq); + break; } } @@ -852,10 +878,9 @@ status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consum Batch batch; batch.samples.push_back(mMsg); mBatches.push_back(batch); - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ started batch event", - mChannel->getName().c_str()); - } + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ started batch event", + mChannel->getName().c_str()); break; } @@ -867,10 +892,9 @@ status_t InputConsumer::consume(InputEventFactoryInterface* factory, bool consum *outSeq = mMsg.header.seq; *outEvent = motionEvent; - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ consumed motion event, seq=%u", - mChannel->getName().c_str(), *outSeq); - } + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ consumed motion event, seq=%u", + mChannel->getName().c_str(), *outSeq); break; } @@ -1087,11 +1111,9 @@ void InputConsumer::rewriteMessage(TouchState& state, InputMessage& msg) { state.recentCoordinatesAreIdentical(id)) { PointerCoords& msgCoords = msg.body.motion.pointers[i].coords; const PointerCoords& resampleCoords = state.lastResample.getPointerById(id); -#if DEBUG_RESAMPLING - ALOGD("[%d] - rewrite (%0.3f, %0.3f), old (%0.3f, %0.3f)", id, - resampleCoords.getX(), resampleCoords.getY(), - msgCoords.getX(), msgCoords.getY()); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "[%d] - rewrite (%0.3f, %0.3f), old (%0.3f, %0.3f)", id, + resampleCoords.getX(), resampleCoords.getY(), msgCoords.getX(), + msgCoords.getY()); msgCoords.setAxisValue(AMOTION_EVENT_AXIS_X, resampleCoords.getX()); msgCoords.setAxisValue(AMOTION_EVENT_AXIS_Y, resampleCoords.getY()); msgCoords.isResampled = true; @@ -1112,17 +1134,13 @@ void InputConsumer::resampleTouchState(nsecs_t sampleTime, MotionEvent* event, ssize_t index = findTouchState(event->getDeviceId(), event->getSource()); if (index < 0) { -#if DEBUG_RESAMPLING - ALOGD("Not resampled, no touch state for device."); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "Not resampled, no touch state for device."); return; } TouchState& touchState = mTouchStates[index]; if (touchState.historySize < 1) { -#if DEBUG_RESAMPLING - ALOGD("Not resampled, no history for device."); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "Not resampled, no history for device."); return; } @@ -1132,9 +1150,7 @@ void InputConsumer::resampleTouchState(nsecs_t sampleTime, MotionEvent* event, for (size_t i = 0; i < pointerCount; i++) { uint32_t id = event->getPointerId(i); if (!current->idBits.hasBit(id)) { -#if DEBUG_RESAMPLING - ALOGD("Not resampled, missing id %d", id); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "Not resampled, missing id %d", id); return; } } @@ -1150,9 +1166,8 @@ void InputConsumer::resampleTouchState(nsecs_t sampleTime, MotionEvent* event, other = &future; nsecs_t delta = future.eventTime - current->eventTime; if (delta < RESAMPLE_MIN_DELTA) { -#if DEBUG_RESAMPLING - ALOGD("Not resampled, delta time is too small: %" PRId64 " ns.", delta); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "Not resampled, delta time is too small: %" PRId64 " ns.", + delta); return; } alpha = float(sampleTime - current->eventTime) / delta; @@ -1162,30 +1177,25 @@ void InputConsumer::resampleTouchState(nsecs_t sampleTime, MotionEvent* event, other = touchState.getHistory(1); nsecs_t delta = current->eventTime - other->eventTime; if (delta < RESAMPLE_MIN_DELTA) { -#if DEBUG_RESAMPLING - ALOGD("Not resampled, delta time is too small: %" PRId64 " ns.", delta); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "Not resampled, delta time is too small: %" PRId64 " ns.", + delta); return; } else if (delta > RESAMPLE_MAX_DELTA) { -#if DEBUG_RESAMPLING - ALOGD("Not resampled, delta time is too large: %" PRId64 " ns.", delta); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "Not resampled, delta time is too large: %" PRId64 " ns.", + delta); return; } nsecs_t maxPredict = current->eventTime + min(delta / 2, RESAMPLE_MAX_PREDICTION); if (sampleTime > maxPredict) { -#if DEBUG_RESAMPLING - ALOGD("Sample time is too far in the future, adjusting prediction " - "from %" PRId64 " to %" PRId64 " ns.", - sampleTime - current->eventTime, maxPredict - current->eventTime); -#endif + ALOGD_IF(DEBUG_RESAMPLING, + "Sample time is too far in the future, adjusting prediction " + "from %" PRId64 " to %" PRId64 " ns.", + sampleTime - current->eventTime, maxPredict - current->eventTime); sampleTime = maxPredict; } alpha = float(current->eventTime - sampleTime) / delta; } else { -#if DEBUG_RESAMPLING - ALOGD("Not resampled, insufficient data."); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "Not resampled, insufficient data."); return; } @@ -1220,28 +1230,22 @@ void InputConsumer::resampleTouchState(nsecs_t sampleTime, MotionEvent* event, PointerCoords& resampledCoords = touchState.lastResample.pointers[i]; const PointerCoords& currentCoords = current->getPointerById(id); resampledCoords.copyFrom(currentCoords); - if (other->idBits.hasBit(id) - && shouldResampleTool(event->getToolType(i))) { + if (other->idBits.hasBit(id) && shouldResampleTool(event->getToolType(i))) { const PointerCoords& otherCoords = other->getPointerById(id); resampledCoords.setAxisValue(AMOTION_EVENT_AXIS_X, - lerp(currentCoords.getX(), otherCoords.getX(), alpha)); + lerp(currentCoords.getX(), otherCoords.getX(), alpha)); resampledCoords.setAxisValue(AMOTION_EVENT_AXIS_Y, - lerp(currentCoords.getY(), otherCoords.getY(), alpha)); + lerp(currentCoords.getY(), otherCoords.getY(), alpha)); resampledCoords.isResampled = true; -#if DEBUG_RESAMPLING - ALOGD("[%d] - out (%0.3f, %0.3f), cur (%0.3f, %0.3f), " - "other (%0.3f, %0.3f), alpha %0.3f", - id, resampledCoords.getX(), resampledCoords.getY(), - currentCoords.getX(), currentCoords.getY(), - otherCoords.getX(), otherCoords.getY(), - alpha); -#endif + ALOGD_IF(DEBUG_RESAMPLING, + "[%d] - out (%0.3f, %0.3f), cur (%0.3f, %0.3f), " + "other (%0.3f, %0.3f), alpha %0.3f", + id, resampledCoords.getX(), resampledCoords.getY(), currentCoords.getX(), + currentCoords.getY(), otherCoords.getX(), otherCoords.getY(), alpha); } else { -#if DEBUG_RESAMPLING - ALOGD("[%d] - out (%0.3f, %0.3f), cur (%0.3f, %0.3f)", - id, resampledCoords.getX(), resampledCoords.getY(), - currentCoords.getX(), currentCoords.getY()); -#endif + ALOGD_IF(DEBUG_RESAMPLING, "[%d] - out (%0.3f, %0.3f), cur (%0.3f, %0.3f)", id, + resampledCoords.getX(), resampledCoords.getY(), currentCoords.getX(), + currentCoords.getY()); } } @@ -1254,10 +1258,9 @@ bool InputConsumer::shouldResampleTool(int32_t toolType) { } status_t InputConsumer::sendFinishedSignal(uint32_t seq, bool handled) { - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ sendFinishedSignal: seq=%u, handled=%s", - mChannel->getName().c_str(), seq, toString(handled)); - } + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ sendFinishedSignal: seq=%u, handled=%s", + mChannel->getName().c_str(), seq, toString(handled)); if (!seq) { ALOGE("Attempted to send a finished signal with sequence number 0."); @@ -1304,13 +1307,12 @@ status_t InputConsumer::sendFinishedSignal(uint32_t seq, bool handled) { status_t InputConsumer::sendTimeline(int32_t inputEventId, std::array graphicsTimeline) { - if (DEBUG_TRANSPORT_ACTIONS) { - ALOGD("channel '%s' consumer ~ sendTimeline: inputEventId=%" PRId32 - ", gpuCompletedTime=%" PRId64 ", presentTime=%" PRId64, - mChannel->getName().c_str(), inputEventId, - graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME], - graphicsTimeline[GraphicsTimeline::PRESENT_TIME]); - } + ALOGD_IF(DEBUG_TRANSPORT_CONSUMER, + "channel '%s' consumer ~ sendTimeline: inputEventId=%" PRId32 + ", gpuCompletedTime=%" PRId64 ", presentTime=%" PRId64, + mChannel->getName().c_str(), inputEventId, + graphicsTimeline[GraphicsTimeline::GPU_COMPLETED_TIME], + graphicsTimeline[GraphicsTimeline::PRESENT_TIME]); InputMessage msg; msg.header.type = InputMessage::Type::TIMELINE; -- cgit v1.2.3-59-g8ed1b From b2bd83cb33bb9dce0a441c5f0ff178d9a0c7f6e9 Mon Sep 17 00:00:00 2001 From: Prabir Pradhan Date: Thu, 23 Feb 2023 02:34:40 +0000 Subject: Allow debug logging of input publisher to be enabled on the fly Enabling debug logs via adb commands required a reboot of the shell. In order to debug flaky tests more easily, we allow raw event logs to be enabled and disabled without the need for a restart on debuggable builds. We limit this ability to debuggable builds ensure there is no performance overhead on user builds. This change allows us to enable more verbose logging on flaky tests that are hard to reproduce. Bug: 193231132 Test: Manual, using adb command to enable debug logs on userdebug builds Change-Id: I6dd97fb3b59a8d6af9e35937024af81b0134ecfb --- libs/input/InputTransport.cpp | 36 ++++++++++++++++++++++++++---------- 1 file changed, 26 insertions(+), 10 deletions(-) diff --git a/libs/input/InputTransport.cpp b/libs/input/InputTransport.cpp index 1d57607067..bdbd708186 100644 --- a/libs/input/InputTransport.cpp +++ b/libs/input/InputTransport.cpp @@ -13,6 +13,7 @@ #include #include +#include #include #include #include @@ -48,12 +49,27 @@ const bool DEBUG_CHANNEL_LIFECYCLE = const bool DEBUG_TRANSPORT_CONSUMER = __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Consumer", ANDROID_LOG_INFO); +const bool IS_DEBUGGABLE_BUILD = +#if defined(__ANDROID__) + android::base::GetBoolProperty("ro.debuggable", false); +#else + true; +#endif + /** * Log debug messages relating to the producer end of the transport channel. - * Enable this via "adb shell setprop log.tag.InputTransportPublisher DEBUG" (requires restart) + * Enable this via "adb shell setprop log.tag.InputTransportPublisher DEBUG". + * This requires a restart on non-debuggable (e.g. user) builds, but should take effect immediately + * on debuggable builds (e.g. userdebug). */ -const bool DEBUG_TRANSPORT_PUBLISHER = - __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Publisher", ANDROID_LOG_INFO); +bool debugTransportPublisher() { + if (!IS_DEBUGGABLE_BUILD) { + static const bool DEBUG_TRANSPORT_PUBLISHER = + __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Publisher", ANDROID_LOG_INFO); + return DEBUG_TRANSPORT_PUBLISHER; + } + return __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Publisher", ANDROID_LOG_INFO); +} /** * Log debug messages about touch event resampling. @@ -538,7 +554,7 @@ status_t InputPublisher::publishKeyEvent(uint32_t seq, int32_t eventId, int32_t KeyEvent::getLabel(keyCode)); ATRACE_NAME(message.c_str()); } - ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, + ALOGD_IF(debugTransportPublisher(), "channel '%s' publisher ~ %s: seq=%u, deviceId=%d, source=%s, " "action=%s, flags=0x%x, keyCode=%s, scanCode=%d, metaState=0x%x, repeatCount=%d," "downTime=%" PRId64 ", eventTime=%" PRId64, @@ -589,7 +605,7 @@ status_t InputPublisher::publishMotionEvent( mInputVerifier.processMovement(deviceId, action, pointerCount, pointerProperties, pointerCoords, flags); } - if (DEBUG_TRANSPORT_PUBLISHER) { + if (debugTransportPublisher()) { std::string transformString; transform.dump(transformString, "transform", " "); ALOGD("channel '%s' publisher ~ %s: seq=%u, deviceId=%d, source=%s, " @@ -664,7 +680,7 @@ status_t InputPublisher::publishFocusEvent(uint32_t seq, int32_t eventId, bool h mChannel->getName().c_str(), toString(hasFocus)); ATRACE_NAME(message.c_str()); } - ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, "channel '%s' publisher ~ %s: seq=%u, hasFocus=%s", + ALOGD_IF(debugTransportPublisher(), "channel '%s' publisher ~ %s: seq=%u, hasFocus=%s", mChannel->getName().c_str(), __func__, seq, toString(hasFocus)); InputMessage msg; @@ -683,7 +699,7 @@ status_t InputPublisher::publishCaptureEvent(uint32_t seq, int32_t eventId, mChannel->getName().c_str(), toString(pointerCaptureEnabled)); ATRACE_NAME(message.c_str()); } - ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, + ALOGD_IF(debugTransportPublisher(), "channel '%s' publisher ~ %s: seq=%u, pointerCaptureEnabled=%s", mChannel->getName().c_str(), __func__, seq, toString(pointerCaptureEnabled)); @@ -703,7 +719,7 @@ status_t InputPublisher::publishDragEvent(uint32_t seq, int32_t eventId, float x mChannel->getName().c_str(), x, y, toString(isExiting)); ATRACE_NAME(message.c_str()); } - ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, + ALOGD_IF(debugTransportPublisher(), "channel '%s' publisher ~ %s: seq=%u, x=%f, y=%f, isExiting=%s", mChannel->getName().c_str(), __func__, seq, x, y, toString(isExiting)); @@ -724,7 +740,7 @@ status_t InputPublisher::publishTouchModeEvent(uint32_t seq, int32_t eventId, bo mChannel->getName().c_str(), toString(isInTouchMode)); ATRACE_NAME(message.c_str()); } - ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, "channel '%s' publisher ~ %s: seq=%u, isInTouchMode=%s", + ALOGD_IF(debugTransportPublisher(), "channel '%s' publisher ~ %s: seq=%u, isInTouchMode=%s", mChannel->getName().c_str(), __func__, seq, toString(isInTouchMode)); InputMessage msg; @@ -736,7 +752,7 @@ status_t InputPublisher::publishTouchModeEvent(uint32_t seq, int32_t eventId, bo } android::base::Result InputPublisher::receiveConsumerResponse() { - ALOGD_IF(DEBUG_TRANSPORT_PUBLISHER, "channel '%s' publisher ~ %s", mChannel->getName().c_str(), + ALOGD_IF(debugTransportPublisher(), "channel '%s' publisher ~ %s", mChannel->getName().c_str(), __func__); InputMessage msg; -- cgit v1.2.3-59-g8ed1b