From 98a114e280d1d7961cd3e82fdaf13b5d4e915b7a Mon Sep 17 00:00:00 2001 From: Jeff Brown Date: Mon, 11 Jun 2012 18:01:06 -0700 Subject: [PATCH] Improve ANR diagnostics. When an ANR occurs, log the associated reason. When an event takes too long to process (currently more than 2 seconds) log basic information about the event including how long it actually took. Dump the contents of the inbound, outbound and wait queues as part of dumpsys input. Bug: 6574842 Change-Id: I9ab754c320f609cb86fe266c469a61e7032dfed6 --- core/java/android/view/Choreographer.java | 2 +- services/input/InputDispatcher.cpp | 167 ++++++++++++++++------ services/input/InputDispatcher.h | 11 +- 3 files changed, 134 insertions(+), 46 deletions(-) diff --git a/core/java/android/view/Choreographer.java b/core/java/android/view/Choreographer.java index 3072c672a5313..78dc86f4dd94f 100644 --- a/core/java/android/view/Choreographer.java +++ b/core/java/android/view/Choreographer.java @@ -493,7 +493,7 @@ public final class Choreographer { if (jitterNanos >= mFrameIntervalNanos) { final long skippedFrames = jitterNanos / mFrameIntervalNanos; if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) { - Log.w(TAG, "Skipped " + skippedFrames + " frames! " + Log.i(TAG, "Skipped " + skippedFrames + " frames! " + "The application may be doing too much work on its main thread."); } final long lastFrameOffset = jitterNanos % mFrameIntervalNanos; diff --git a/services/input/InputDispatcher.cpp b/services/input/InputDispatcher.cpp index c8e11c2218438..7e1a80cecdd17 100644 --- a/services/input/InputDispatcher.cpp +++ b/services/input/InputDispatcher.cpp @@ -56,6 +56,8 @@ #define INDENT " " #define INDENT2 " " +#define INDENT3 " " +#define INDENT4 " " namespace android { @@ -78,6 +80,9 @@ const nsecs_t STALE_EVENT_TIMEOUT = 10000 * 1000000LL; // 10sec // 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 +// 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 + static inline nsecs_t now() { return systemTime(SYSTEM_TIME_MONOTONIC); @@ -897,11 +902,11 @@ int32_t InputDispatcher::handleTargetsNotReadyLocked(nsecs_t currentTime, const EventEntry* entry, const sp& applicationHandle, const sp& windowHandle, - nsecs_t* nextWakeupTime) { + nsecs_t* nextWakeupTime, const char* reason) { if (applicationHandle == NULL && windowHandle == NULL) { if (mInputTargetWaitCause != INPUT_TARGET_WAIT_CAUSE_SYSTEM_NOT_READY) { #if DEBUG_FOCUS - ALOGD("Waiting for system to become ready for input."); + ALOGD("Waiting for system to become ready for input. Reason: %s", reason); #endif mInputTargetWaitCause = INPUT_TARGET_WAIT_CAUSE_SYSTEM_NOT_READY; mInputTargetWaitStartTime = currentTime; @@ -912,8 +917,9 @@ int32_t InputDispatcher::handleTargetsNotReadyLocked(nsecs_t currentTime, } else { if (mInputTargetWaitCause != INPUT_TARGET_WAIT_CAUSE_APPLICATION_NOT_READY) { #if DEBUG_FOCUS - ALOGD("Waiting for application to become ready for input: %s", - getApplicationWindowLabelLocked(applicationHandle, windowHandle).string()); + ALOGD("Waiting for application to become ready for input: %s. Reason: %s", + getApplicationWindowLabelLocked(applicationHandle, windowHandle).string(), + reason); #endif nsecs_t timeout; if (windowHandle != NULL) { @@ -946,7 +952,7 @@ int32_t InputDispatcher::handleTargetsNotReadyLocked(nsecs_t currentTime, if (currentTime >= mInputTargetWaitTimeoutTime) { onANRLocked(currentTime, applicationHandle, windowHandle, - entry->eventTime, mInputTargetWaitStartTime); + entry->eventTime, mInputTargetWaitStartTime, reason); // Force poll loop to wake up immediately on next iteration once we get the // ANR response back from the policy. @@ -1017,13 +1023,11 @@ int32_t InputDispatcher::findFocusedWindowTargetsLocked(nsecs_t currentTime, // then drop the event. if (mFocusedWindowHandle == NULL) { if (mFocusedApplicationHandle != NULL) { -#if DEBUG_FOCUS - ALOGD("Waiting because there is no focused window but there is a " - "focused application that may eventually add a window: %s.", - getApplicationWindowLabelLocked(mFocusedApplicationHandle, NULL).string()); -#endif injectionResult = handleTargetsNotReadyLocked(currentTime, entry, - mFocusedApplicationHandle, NULL, nextWakeupTime); + mFocusedApplicationHandle, NULL, nextWakeupTime, + "Waiting because no window has focus but there is a " + "focused application that may eventually add a window " + "when it finishes starting up."); goto Unresponsive; } @@ -1040,21 +1044,18 @@ int32_t InputDispatcher::findFocusedWindowTargetsLocked(nsecs_t currentTime, // If the currently focused window is paused then keep waiting. if (mFocusedWindowHandle->getInfo()->paused) { -#if DEBUG_FOCUS - ALOGD("Waiting because focused window is paused."); -#endif injectionResult = handleTargetsNotReadyLocked(currentTime, entry, - mFocusedApplicationHandle, mFocusedWindowHandle, nextWakeupTime); + mFocusedApplicationHandle, mFocusedWindowHandle, nextWakeupTime, + "Waiting because the focused window is paused."); goto Unresponsive; } // If the currently focused window is still working on previous events then keep waiting. if (!isWindowReadyForMoreInputLocked(currentTime, mFocusedWindowHandle, entry)) { -#if DEBUG_FOCUS - ALOGD("Waiting because focused window still processing previous input."); -#endif injectionResult = handleTargetsNotReadyLocked(currentTime, entry, - mFocusedApplicationHandle, mFocusedWindowHandle, nextWakeupTime); + mFocusedApplicationHandle, mFocusedWindowHandle, nextWakeupTime, + "Waiting because the focused window has not finished " + "processing the input events that were previously delivered to it."); goto Unresponsive; } @@ -1210,11 +1211,9 @@ int32_t InputDispatcher::findTouchedWindowTargetsLocked(nsecs_t currentTime, // it is invisible) then wait for it. Any other focused window may in // fact be in ANR state. if (topErrorWindowHandle != NULL && newTouchedWindowHandle != topErrorWindowHandle) { -#if DEBUG_FOCUS - ALOGD("Waiting because system error window is pending."); -#endif injectionResult = handleTargetsNotReadyLocked(currentTime, entry, - NULL, NULL, nextWakeupTime); + NULL, NULL, nextWakeupTime, + "Waiting because a system error window is about to be displayed."); injectionPermission = INJECTION_PERMISSION_UNKNOWN; goto Unresponsive; } @@ -1241,14 +1240,11 @@ int32_t InputDispatcher::findTouchedWindowTargetsLocked(nsecs_t currentTime, // but not yet put up a window and the user is starting to get impatient. if (maskedAction == AMOTION_EVENT_ACTION_DOWN && mFocusedApplicationHandle != NULL) { -#if DEBUG_FOCUS - ALOGD("Waiting because there is no touched window but there is a " - "focused application that may eventually add a new window: %s.", - getApplicationWindowLabelLocked( - mFocusedApplicationHandle, NULL).string()); -#endif injectionResult = handleTargetsNotReadyLocked(currentTime, entry, - mFocusedApplicationHandle, NULL, nextWakeupTime); + mFocusedApplicationHandle, NULL, nextWakeupTime, + "Waiting because there is no touchable window that can " + "handle the event but there is focused application that may " + "eventually add a new window when it finishes starting up."); goto Unresponsive; } @@ -1412,21 +1408,18 @@ int32_t InputDispatcher::findTouchedWindowTargetsLocked(nsecs_t currentTime, if (touchedWindow.targetFlags & InputTarget::FLAG_FOREGROUND) { // If the touched window is paused then keep waiting. if (touchedWindow.windowHandle->getInfo()->paused) { -#if DEBUG_FOCUS - ALOGD("Waiting because touched window is paused."); -#endif injectionResult = handleTargetsNotReadyLocked(currentTime, entry, - NULL, touchedWindow.windowHandle, nextWakeupTime); + NULL, touchedWindow.windowHandle, nextWakeupTime, + "Waiting because the touched window is paused."); goto Unresponsive; } // If the touched window is still working on previous events then keep waiting. if (!isWindowReadyForMoreInputLocked(currentTime, touchedWindow.windowHandle, entry)) { -#if DEBUG_FOCUS - ALOGD("Waiting because touched window still processing previous input."); -#endif injectionResult = handleTargetsNotReadyLocked(currentTime, entry, - NULL, touchedWindow.windowHandle, nextWakeupTime); + NULL, touchedWindow.windowHandle, nextWakeupTime, + "Waiting because the touched window has not finished " + "processing the input events that were previously delivered to it."); goto Unresponsive; } } @@ -1897,6 +1890,7 @@ void InputDispatcher::startDispatchCycleLocked(nsecs_t currentTime, while (connection->status == Connection::STATUS_NORMAL && !connection->outboundQueue.isEmpty()) { DispatchEntry* dispatchEntry = connection->outboundQueue.head; + dispatchEntry->deliveryTime = currentTime; // Publish the event. status_t status; @@ -3099,7 +3093,65 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { dump.append(INDENT "MonitoringChannels: \n"); } - dump.appendFormat(INDENT "InboundQueue: length=%u\n", mInboundQueue.count()); + nsecs_t currentTime = now(); + + if (!mInboundQueue.isEmpty()) { + dump.appendFormat(INDENT "InboundQueue: length=%u\n", mInboundQueue.count()); + for (EventEntry* entry = mInboundQueue.head; entry; entry = entry->next) { + dump.append(INDENT2); + entry->appendDescription(dump); + dump.appendFormat(", age=%01.1fms\n", + (currentTime - entry->eventTime) * 0.000001f); + } + } else { + dump.append(INDENT "InboundQueue: \n"); + } + + if (!mConnectionsByFd.isEmpty()) { + dump.append(INDENT "Connections:\n"); + for (size_t i = 0; i < mConnectionsByFd.size(); i++) { + const sp& connection = mConnectionsByFd.valueAt(i); + dump.appendFormat(INDENT2 "%d: channelName='%s', windowName='%s', " + "status=%s, monitor=%s, inputPublisherBlocked=%s\n", + i, connection->getInputChannelName(), connection->getWindowName(), + connection->getStatusLabel(), toString(connection->monitor), + toString(connection->inputPublisherBlocked)); + + if (!connection->outboundQueue.isEmpty()) { + dump.appendFormat(INDENT3 "OutboundQueue: length=%u\n", + connection->outboundQueue.count()); + for (DispatchEntry* entry = connection->outboundQueue.head; entry; + entry = entry->next) { + dump.append(INDENT4); + entry->eventEntry->appendDescription(dump); + dump.appendFormat(", targetFlags=0x%08x, resolvedAction=%d, age=%01.1fms\n", + entry->targetFlags, entry->resolvedAction, + (currentTime - entry->eventEntry->eventTime) * 0.000001f); + } + } else { + dump.append(INDENT3 "OutboundQueue: \n"); + } + + if (!connection->waitQueue.isEmpty()) { + dump.appendFormat(INDENT3 "WaitQueue: length=%u\n", + connection->waitQueue.count()); + for (DispatchEntry* entry = connection->waitQueue.head; entry; + entry = entry->next) { + dump.append(INDENT4); + entry->eventEntry->appendDescription(dump); + dump.appendFormat(", targetFlags=0x%08x, resolvedAction=%d, " + "age=%01.1fms, wait=%01.1fms\n", + entry->targetFlags, entry->resolvedAction, + (currentTime - entry->eventEntry->eventTime) * 0.000001f, + (currentTime - entry->deliveryTime) * 0.000001f); + } + } else { + dump.append(INDENT3 "WaitQueue: \n"); + } + } + } else { + dump.append(INDENT "Connections: \n"); + } if (isAppSwitchPendingLocked()) { dump.appendFormat(INDENT "AppSwitch: pending, due in %01.1fms\n", @@ -3214,6 +3266,7 @@ void InputDispatcher::onDispatchCycleFinishedLocked( CommandEntry* commandEntry = postCommandLocked( & InputDispatcher::doDispatchCycleFinishedLockedInterruptible); commandEntry->connection = connection; + commandEntry->eventTime = currentTime; commandEntry->seq = seq; commandEntry->handled = handled; } @@ -3231,12 +3284,12 @@ void InputDispatcher::onDispatchCycleBrokenLocked( void InputDispatcher::onANRLocked( nsecs_t currentTime, const sp& applicationHandle, const sp& windowHandle, - nsecs_t eventTime, nsecs_t waitStartTime) { + nsecs_t eventTime, nsecs_t waitStartTime, const char* reason) { ALOGI("Application is not responding: %s. " - "%01.1fms since event, %01.1fms since wait started", + "It has been %01.1fms since event, %01.1fms since wait started. Reason: %s", getApplicationWindowLabelLocked(applicationHandle, windowHandle).string(), (currentTime - eventTime) / 1000000.0, - (currentTime - waitStartTime) / 1000000.0); + (currentTime - waitStartTime) / 1000000.0, reason); CommandEntry* commandEntry = postCommandLocked( & InputDispatcher::doNotifyANRLockedInterruptible); @@ -3308,12 +3361,22 @@ void InputDispatcher::doInterceptKeyBeforeDispatchingLockedInterruptible( void InputDispatcher::doDispatchCycleFinishedLockedInterruptible( CommandEntry* commandEntry) { sp connection = commandEntry->connection; + nsecs_t finishTime = commandEntry->eventTime; uint32_t seq = commandEntry->seq; bool handled = commandEntry->handled; // Handle post-event policy actions. DispatchEntry* dispatchEntry = connection->findWaitQueueEntry(seq); if (dispatchEntry) { + nsecs_t eventDuration = finishTime - dispatchEntry->deliveryTime; + if (eventDuration > SLOW_EVENT_PROCESSING_WARNING_TIMEOUT) { + String8 msg; + msg.appendFormat("Window '%s' spent %01.1fms processing the last input event: ", + connection->getWindowName(), eventDuration * 0.000001f); + dispatchEntry->eventEntry->appendDescription(msg); + ALOGI("%s", msg.string()); + } + bool restartEvent; if (dispatchEntry->eventEntry->type == EventEntry::TYPE_KEY) { KeyEntry* keyEntry = static_cast(dispatchEntry->eventEntry); @@ -3656,6 +3719,10 @@ InputDispatcher::ConfigurationChangedEntry::ConfigurationChangedEntry(nsecs_t ev InputDispatcher::ConfigurationChangedEntry::~ConfigurationChangedEntry() { } +void InputDispatcher::ConfigurationChangedEntry::appendDescription(String8& msg) const { + msg.append("ConfigurationChangedEvent()"); +} + // --- InputDispatcher::DeviceResetEntry --- @@ -3667,6 +3734,10 @@ InputDispatcher::DeviceResetEntry::DeviceResetEntry(nsecs_t eventTime, int32_t d InputDispatcher::DeviceResetEntry::~DeviceResetEntry() { } +void InputDispatcher::DeviceResetEntry::appendDescription(String8& msg) const { + msg.appendFormat("DeviceResetEvent(deviceId=%d)", deviceId); +} + // --- InputDispatcher::KeyEntry --- @@ -3685,6 +3756,11 @@ InputDispatcher::KeyEntry::KeyEntry(nsecs_t eventTime, InputDispatcher::KeyEntry::~KeyEntry() { } +void InputDispatcher::KeyEntry::appendDescription(String8& msg) const { + msg.appendFormat("KeyEvent(action=%d, deviceId=%d, source=0x%08x)", + action, deviceId, source); +} + void InputDispatcher::KeyEntry::recycle() { releaseInjectionState(); @@ -3718,6 +3794,11 @@ InputDispatcher::MotionEntry::MotionEntry(nsecs_t eventTime, InputDispatcher::MotionEntry::~MotionEntry() { } +void InputDispatcher::MotionEntry::appendDescription(String8& msg) const { + msg.appendFormat("MotionEvent(action=%d, deviceId=%d, source=0x%08x)", + action, deviceId, source); +} + // --- InputDispatcher::DispatchEntry --- @@ -3728,7 +3809,7 @@ InputDispatcher::DispatchEntry::DispatchEntry(EventEntry* eventEntry, seq(nextSeq()), eventEntry(eventEntry), targetFlags(targetFlags), xOffset(xOffset), yOffset(yOffset), scaleFactor(scaleFactor), - resolvedAction(0), resolvedFlags(0) { + deliveryTime(0), resolvedAction(0), resolvedFlags(0) { eventEntry->refCount += 1; } diff --git a/services/input/InputDispatcher.h b/services/input/InputDispatcher.h index 06b8d648eca70..c5b8cd72e88b0 100644 --- a/services/input/InputDispatcher.h +++ b/services/input/InputDispatcher.h @@ -440,6 +440,8 @@ private: void release(); + virtual void appendDescription(String8& msg) const = 0; + protected: EventEntry(int32_t type, nsecs_t eventTime, uint32_t policyFlags); virtual ~EventEntry(); @@ -448,6 +450,7 @@ private: struct ConfigurationChangedEntry : EventEntry { ConfigurationChangedEntry(nsecs_t eventTime); + virtual void appendDescription(String8& msg) const; protected: virtual ~ConfigurationChangedEntry(); @@ -457,6 +460,7 @@ private: int32_t deviceId; DeviceResetEntry(nsecs_t eventTime, int32_t deviceId); + virtual void appendDescription(String8& msg) const; protected: virtual ~DeviceResetEntry(); @@ -488,6 +492,7 @@ private: int32_t deviceId, uint32_t source, uint32_t policyFlags, int32_t action, int32_t flags, int32_t keyCode, int32_t scanCode, int32_t metaState, int32_t repeatCount, nsecs_t downTime); + virtual void appendDescription(String8& msg) const; void recycle(); protected: @@ -516,6 +521,7 @@ private: float xPrecision, float yPrecision, nsecs_t downTime, uint32_t pointerCount, const PointerProperties* pointerProperties, const PointerCoords* pointerCoords); + virtual void appendDescription(String8& msg) const; protected: virtual ~MotionEntry(); @@ -530,6 +536,7 @@ private: float xOffset; float yOffset; float scaleFactor; + nsecs_t deliveryTime; // time when the event was actually delivered // Set to the resolved action and flags when the event is enqueued. int32_t resolvedAction; @@ -978,7 +985,7 @@ private: int32_t handleTargetsNotReadyLocked(nsecs_t currentTime, const EventEntry* entry, const sp& applicationHandle, const sp& windowHandle, - nsecs_t* nextWakeupTime); + nsecs_t* nextWakeupTime, const char* reason); void resumeAfterTargetsNotReadyTimeoutLocked(nsecs_t newTimeout, const sp& inputChannel); nsecs_t getTimeSpentWaitingForApplicationLocked(nsecs_t currentTime); @@ -1056,7 +1063,7 @@ private: void onANRLocked( nsecs_t currentTime, const sp& applicationHandle, const sp& windowHandle, - nsecs_t eventTime, nsecs_t waitStartTime); + nsecs_t eventTime, nsecs_t waitStartTime, const char* reason); // Outbound policy interactions. void doNotifyConfigurationChangedInterruptible(CommandEntry* commandEntry);