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

2 files changed, 40 insertions, 12 deletions

diff --git a/services/input/InputDispatcher.cpp b/services/input/InputDispatcher.cpp
index 7e1a80c..e63da05 100644
--- a/services/input/InputDispatcher.cpp
+++ b/services/input/InputDispatcher.cpp
@@ -53,6 +53,7 @@
 #include <unistd.h>
 #include <errno.h>
 #include <limits.h>
+#include <time.h>
 
 #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>& inputChannel,
@@ -3285,11 +3292,28 @@ void InputDispatcher::onANRLocked(
         nsecs_t currentTime, const sp<InputApplicationHandle>& applicationHandle,
         const sp<InputWindowHandle>& 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 c5b8cd7..d0824fc 100644
--- a/services/input/InputDispatcher.h
+++ b/services/input/InputDispatcher.h
@@ -948,6 +948,9 @@ private:
     // Focused application.
     sp<InputApplicationHandle> mFocusedApplicationHandle;
 
+    // Dispatcher state at time of last ANR.
+    String8 mLastANRState;
+
     // Dispatch inbound events.
     bool dispatchConfigurationChangedLocked(
             nsecs_t currentTime, ConfigurationChangedEntry* entry);