From e182d8905fd2a9f8ec82040e5a4de2139c7e28ca Mon Sep 17 00:00:00 2001 From: Jeff Brown Date: Sun, 17 Jun 2012 12:01:06 -0700 Subject: [PATCH] Capture input dispatcher's last ANR state in bug report. Some ANR bugs are very difficult to localize because by the time the bug report has been captured, the relevant information is gone. Work around this by capturing a log of the input dispatcher's state at the exact time of the ANR before anything has changed and include this information in the bug report. Also fixed a nit related to some format strings that had improper field widths specified. Bug: 6680398 Change-Id: I5323bf18ec5e47a767cd053209753cc46852bf4c --- services/input/InputDispatcher.cpp | 49 ++++++++++++++++++++++-------- services/input/InputDispatcher.h | 3 ++ 2 files changed, 40 insertions(+), 12 deletions(-) diff --git a/services/input/InputDispatcher.cpp b/services/input/InputDispatcher.cpp index 7e1a80cecdd17..e63da05d8dfe4 100644 --- a/services/input/InputDispatcher.cpp +++ b/services/input/InputDispatcher.cpp @@ -53,6 +53,7 @@ #include #include #include +#include #define INDENT " " #define INDENT2 " " @@ -1073,7 +1074,7 @@ Unresponsive: injectionResult, timeSpentWaitingForApplication); #if DEBUG_FOCUS ALOGD("findFocusedWindow finished: injectionResult=%d, " - "timeSpendWaitingForApplication=%0.1fms", + "timeSpentWaitingForApplication=%0.1fms", injectionResult, timeSpentWaitingForApplication / 1000000.0); #endif return injectionResult; @@ -3100,7 +3101,7 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { for (EventEntry* entry = mInboundQueue.head; entry; entry = entry->next) { dump.append(INDENT2); entry->appendDescription(dump); - dump.appendFormat(", age=%01.1fms\n", + dump.appendFormat(", age=%0.1fms\n", (currentTime - entry->eventTime) * 0.000001f); } } else { @@ -3124,7 +3125,7 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { entry = entry->next) { dump.append(INDENT4); entry->eventEntry->appendDescription(dump); - dump.appendFormat(", targetFlags=0x%08x, resolvedAction=%d, age=%01.1fms\n", + dump.appendFormat(", targetFlags=0x%08x, resolvedAction=%d, age=%0.1fms\n", entry->targetFlags, entry->resolvedAction, (currentTime - entry->eventEntry->eventTime) * 0.000001f); } @@ -3140,7 +3141,7 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { dump.append(INDENT4); entry->eventEntry->appendDescription(dump); dump.appendFormat(", targetFlags=0x%08x, resolvedAction=%d, " - "age=%01.1fms, wait=%01.1fms\n", + "age=%0.1fms, wait=%0.1fms\n", entry->targetFlags, entry->resolvedAction, (currentTime - entry->eventEntry->eventTime) * 0.000001f, (currentTime - entry->deliveryTime) * 0.000001f); @@ -3154,11 +3155,17 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { } if (isAppSwitchPendingLocked()) { - dump.appendFormat(INDENT "AppSwitch: pending, due in %01.1fms\n", + dump.appendFormat(INDENT "AppSwitch: pending, due in %0.1fms\n", (mAppSwitchDueTime - now()) / 1000000.0); } else { dump.append(INDENT "AppSwitch: not pending\n"); } + + dump.append(INDENT "Configuration:\n"); + dump.appendFormat(INDENT2 "KeyRepeatDelay: %0.1fms\n", + mConfig.keyRepeatDelay * 0.000001f); + dump.appendFormat(INDENT2 "KeyRepeatTimeout: %0.1fms\n", + mConfig.keyRepeatTimeout * 0.000001f); } status_t InputDispatcher::registerInputChannel(const sp& inputChannel, @@ -3285,11 +3292,28 @@ void InputDispatcher::onANRLocked( nsecs_t currentTime, const sp& applicationHandle, const sp& windowHandle, nsecs_t eventTime, nsecs_t waitStartTime, const char* reason) { + float dispatchLatency = (currentTime - eventTime) * 0.000001f; + float waitDuration = (currentTime - waitStartTime) * 0.000001f; ALOGI("Application is not responding: %s. " - "It has been %01.1fms since event, %01.1fms since wait started. Reason: %s", + "It has been %0.1fms since event, %0.1fms since wait started. Reason: %s", getApplicationWindowLabelLocked(applicationHandle, windowHandle).string(), - (currentTime - eventTime) / 1000000.0, - (currentTime - waitStartTime) / 1000000.0, reason); + dispatchLatency, waitDuration, reason); + + // Capture a record of the InputDispatcher state at the time of the ANR. + time_t t = time(NULL); + struct tm tm; + localtime_r(&t, &tm); + char timestr[64]; + strftime(timestr, sizeof(timestr), "%F %T", &tm); + mLastANRState.clear(); + mLastANRState.append(INDENT "ANR:\n"); + mLastANRState.appendFormat(INDENT2 "Time: %s\n", timestr); + mLastANRState.appendFormat(INDENT2 "Window: %s\n", + getApplicationWindowLabelLocked(applicationHandle, windowHandle).string()); + mLastANRState.appendFormat(INDENT2 "DispatchLatency: %0.1fms\n", dispatchLatency); + mLastANRState.appendFormat(INDENT2 "WaitDuration: %0.1fms\n", waitDuration); + mLastANRState.appendFormat(INDENT2 "Reason: %s\n", reason); + dumpDispatchStateLocked(mLastANRState); CommandEntry* commandEntry = postCommandLocked( & InputDispatcher::doNotifyANRLockedInterruptible); @@ -3371,7 +3395,7 @@ void InputDispatcher::doDispatchCycleFinishedLockedInterruptible( 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: ", + msg.appendFormat("Window '%s' spent %0.1fms processing the last input event: ", connection->getWindowName(), eventDuration * 0.000001f); dispatchEntry->eventEntry->appendDescription(msg); ALOGI("%s", msg.string()); @@ -3634,9 +3658,10 @@ void InputDispatcher::dump(String8& dump) { dump.append("Input Dispatcher State:\n"); dumpDispatchStateLocked(dump); - dump.append(INDENT "Configuration:\n"); - dump.appendFormat(INDENT2 "KeyRepeatDelay: %0.1fms\n", mConfig.keyRepeatDelay * 0.000001f); - dump.appendFormat(INDENT2 "KeyRepeatTimeout: %0.1fms\n", mConfig.keyRepeatTimeout * 0.000001f); + if (!mLastANRState.isEmpty()) { + dump.append("\nInput Dispatcher State at time of last ANR:\n"); + dump.append(mLastANRState); + } } void InputDispatcher::monitor() { diff --git a/services/input/InputDispatcher.h b/services/input/InputDispatcher.h index c5b8cd72e88b0..d0824fcda0d74 100644 --- a/services/input/InputDispatcher.h +++ b/services/input/InputDispatcher.h @@ -948,6 +948,9 @@ private: // Focused application. sp mFocusedApplicationHandle; + // Dispatcher state at time of last ANR. + String8 mLastANRState; + // Dispatch inbound events. bool dispatchConfigurationChangedLocked( nsecs_t currentTime, ConfigurationChangedEntry* entry);