From 6876f3210764559a2fcccdd16079f7a66a871570 Mon Sep 17 00:00:00 2001 From: Jeff Brown Date: Wed, 7 Aug 2013 16:46:50 -0700 Subject: [PATCH] Dump information about recent input events. To help track down ANRs, include more information about recent events in the input dispatcher dumps. Bug: 9774124 Change-Id: I94732f173d3518c2f4780668d2eb3ee9ae9fcb10 --- services/input/InputDispatcher.cpp | 64 ++++++++++++++++++++++++++++++++++---- services/input/InputDispatcher.h | 4 +++ 2 files changed, 62 insertions(+), 6 deletions(-) diff --git a/services/input/InputDispatcher.cpp b/services/input/InputDispatcher.cpp index 23a846b7ce95..32247e75e066 100644 --- a/services/input/InputDispatcher.cpp +++ b/services/input/InputDispatcher.cpp @@ -84,6 +84,8 @@ const 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 +// Number of recent events to keep for debugging purposes. +const size_t RECENT_QUEUE_MAX_SIZE = 10; static inline nsecs_t now() { return systemTime(SYSTEM_TIME_MONOTONIC); @@ -455,6 +457,14 @@ bool InputDispatcher::enqueueInboundEventLocked(EventEntry* entry) { return needWake; } +void InputDispatcher::addRecentEventLocked(EventEntry* entry) { + entry->refCount += 1; + mRecentQueue.enqueueAtTail(entry); + if (mRecentQueue.count() > RECENT_QUEUE_MAX_SIZE) { + mRecentQueue.dequeueAtHead()->release(); + } +} + sp InputDispatcher::findTouchedWindowAtLocked(int32_t displayId, int32_t x, int32_t y) { // Traverse windows from front to back to find touched window. @@ -624,6 +634,7 @@ void InputDispatcher::releaseInboundEventLocked(EventEntry* entry) { if (entry == mNextUnblockedEvent) { mNextUnblockedEvent = NULL; } + addRecentEventLocked(entry); entry->release(); } @@ -3161,6 +3172,31 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { nsecs_t currentTime = now(); + // Dump recently dispatched or dropped events from oldest to newest. + if (!mRecentQueue.isEmpty()) { + dump.appendFormat(INDENT "RecentQueue: length=%u\n", mRecentQueue.count()); + for (EventEntry* entry = mRecentQueue.head; entry; entry = entry->next) { + dump.append(INDENT2); + entry->appendDescription(dump); + dump.appendFormat(", age=%0.1fms\n", + (currentTime - entry->eventTime) * 0.000001f); + } + } else { + dump.append(INDENT "RecentQueue: \n"); + } + + // Dump event currently being dispatched. + if (mPendingEvent) { + dump.append(INDENT "PendingEvent:\n"); + dump.append(INDENT2); + mPendingEvent->appendDescription(dump); + dump.appendFormat(", age=%0.1fms\n", + (currentTime - mPendingEvent->eventTime) * 0.000001f); + } else { + dump.append(INDENT "PendingEvent: \n"); + } + + // Dump inbound events from oldest to newest. if (!mInboundQueue.isEmpty()) { dump.appendFormat(INDENT "InboundQueue: length=%u\n", mInboundQueue.count()); for (EventEntry* entry = mInboundQueue.head; entry; entry = entry->next) { @@ -3809,7 +3845,8 @@ InputDispatcher::ConfigurationChangedEntry::~ConfigurationChangedEntry() { } void InputDispatcher::ConfigurationChangedEntry::appendDescription(String8& msg) const { - msg.append("ConfigurationChangedEvent()"); + msg.append("ConfigurationChangedEvent(), policyFlags=0x%08x", + policyFlags); } @@ -3824,7 +3861,8 @@ InputDispatcher::DeviceResetEntry::~DeviceResetEntry() { } void InputDispatcher::DeviceResetEntry::appendDescription(String8& msg) const { - msg.appendFormat("DeviceResetEvent(deviceId=%d)", deviceId); + msg.appendFormat("DeviceResetEvent(deviceId=%d), policyFlags=0x%08x", + deviceId, policyFlags); } @@ -3846,8 +3884,11 @@ InputDispatcher::KeyEntry::~KeyEntry() { } void InputDispatcher::KeyEntry::appendDescription(String8& msg) const { - msg.appendFormat("KeyEvent(action=%d, deviceId=%d, source=0x%08x)", - action, deviceId, source); + msg.appendFormat("KeyEvent(deviceId=%d, source=0x%08x, action=%d, " + "flags=0x%08x, keyCode=%d, scanCode=%d, metaState=0x%08x, " + "repeatCount=%d), policyFlags=0x%08x", + deviceId, source, action, flags, keyCode, scanCode, metaState, + repeatCount, policyFlags); } void InputDispatcher::KeyEntry::recycle() { @@ -3884,8 +3925,19 @@ InputDispatcher::MotionEntry::~MotionEntry() { } void InputDispatcher::MotionEntry::appendDescription(String8& msg) const { - msg.appendFormat("MotionEvent(action=%d, deviceId=%d, source=0x%08x, displayId=%d)", - action, deviceId, source, displayId); + msg.appendFormat("MotionEvent(deviceId=%d, source=0x%08x, action=%d, " + "flags=0x%08x, metaState=0x%08x, buttonState=0x%08x, edgeFlags=0x%08x, " + "xPrecision=%.1f, yPrecision=%.1f, displayId=%d, pointers=[", + deviceId, source, action, flags, metaState, buttonState, edgeFlags, + xPrecision, yPrecision, displayId); + for (uint32_t i = 0; i < pointerCount; i++) { + if (i) { + msg.append(", "); + } + msg.appendFormat("%d: (%.1f, %.1f)", pointerProperties[i].id, + pointerCoords[i].getX(), pointerCoords[i].getY()); + } + msg.appendFormat("]), policyFlags=0x%08x", policyFlags); } diff --git a/services/input/InputDispatcher.h b/services/input/InputDispatcher.h index 63ea7818f137..0273dc4d62d7 100644 --- a/services/input/InputDispatcher.h +++ b/services/input/InputDispatcher.h @@ -846,6 +846,7 @@ private: EventEntry* mPendingEvent; Queue mInboundQueue; + Queue mRecentQueue; Queue mCommandQueue; void dispatchOnceInnerLocked(nsecs_t* nextWakeupTime); @@ -856,6 +857,9 @@ private: // Cleans up input state when dropping an inbound event. void dropInboundEventLocked(EventEntry* entry, DropReason dropReason); + // Adds an event to a queue of recent events for debugging purposes. + void addRecentEventLocked(EventEntry* entry); + // App switch latency optimization. bool mAppSwitchSawKeyDown; nsecs_t mAppSwitchDueTime; -- 2.11.0