Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit e182d890 authored by Jeff Brown's avatar Jeff Brown Committed by The Android Automerger
Browse files

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
parent 45a9c67c

services/input/InputDispatcher.cpp

+37 −12
Original line number Original line Diff line number Diff line
@@ -53,6 +53,7 @@ 
#include <unistd.h>

#include <unistd.h>

#include <errno.h>

#include <errno.h>

#include <limits.h>

#include <limits.h>

#include <time.h>





#define INDENT "  "

#define INDENT "  "

#define INDENT2 "    "

#define INDENT2 "    "
@@ -1073,7 +1074,7 @@ Unresponsive: 
            injectionResult, timeSpentWaitingForApplication);

            injectionResult, timeSpentWaitingForApplication);

#if DEBUG_FOCUS

#if DEBUG_FOCUS

    ALOGD("findFocusedWindow finished: injectionResult=%d, "

    ALOGD("findFocusedWindow finished: injectionResult=%d, "

            "timeSpendWaitingForApplication=%0.1fms",

            "timeSpentWaitingForApplication=%0.1fms",

            injectionResult, timeSpentWaitingForApplication / 1000000.0);

            injectionResult, timeSpentWaitingForApplication / 1000000.0);

#endif

#endif

    return injectionResult;

    return injectionResult;
@@ -3100,7 +3101,7 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { 
        for (EventEntry* entry = mInboundQueue.head; entry; entry = entry->next) {

        for (EventEntry* entry = mInboundQueue.head; entry; entry = entry->next) {

            dump.append(INDENT2);

            dump.append(INDENT2);

            entry->appendDescription(dump);

            entry->appendDescription(dump);

            dump.appendFormat(", age=%01.1fms\n",

            dump.appendFormat(", age=%0.1fms\n",

                    (currentTime - entry->eventTime) * 0.000001f);

                    (currentTime - entry->eventTime) * 0.000001f);

        }

        }

    } else {

    } else {
@@ -3124,7 +3125,7 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { 
                        entry = entry->next) {

                        entry = entry->next) {

                    dump.append(INDENT4);

                    dump.append(INDENT4);

                    entry->eventEntry->appendDescription(dump);

                    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,

                            entry->targetFlags, entry->resolvedAction,

                            (currentTime - entry->eventEntry->eventTime) * 0.000001f);

                            (currentTime - entry->eventEntry->eventTime) * 0.000001f);

                }

                }
@@ -3140,7 +3141,7 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { 
                    dump.append(INDENT4);

                    dump.append(INDENT4);

                    entry->eventEntry->appendDescription(dump);

                    entry->eventEntry->appendDescription(dump);

                    dump.appendFormat(", targetFlags=0x%08x, resolvedAction=%d, "

                    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,

                            entry->targetFlags, entry->resolvedAction,

                            (currentTime - entry->eventEntry->eventTime) * 0.000001f,

                            (currentTime - entry->eventEntry->eventTime) * 0.000001f,

                            (currentTime - entry->deliveryTime) * 0.000001f);

                            (currentTime - entry->deliveryTime) * 0.000001f);
@@ -3154,11 +3155,17 @@ void InputDispatcher::dumpDispatchStateLocked(String8& dump) { 
    }

    }





    if (isAppSwitchPendingLocked()) {

    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);

                (mAppSwitchDueTime - now()) / 1000000.0);

    } else {

    } else {

        dump.append(INDENT "AppSwitch: not pending\n");

        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,

status_t InputDispatcher::registerInputChannel(const sp<InputChannel>& inputChannel,
@@ -3285,11 +3292,28 @@ void InputDispatcher::onANRLocked( 
        nsecs_t currentTime, const sp<InputApplicationHandle>& applicationHandle,

        nsecs_t currentTime, const sp<InputApplicationHandle>& applicationHandle,

        const sp<InputWindowHandle>& windowHandle,

        const sp<InputWindowHandle>& windowHandle,

        nsecs_t eventTime, nsecs_t waitStartTime, const char* reason) {

        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.  "

    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(),

            getApplicationWindowLabelLocked(applicationHandle, windowHandle).string(),

            (currentTime - eventTime) / 1000000.0,

            dispatchLatency, waitDuration, reason);

            (currentTime - waitStartTime) / 1000000.0, 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(

    CommandEntry* commandEntry = postCommandLocked(

            & InputDispatcher::doNotifyANRLockedInterruptible);

            & InputDispatcher::doNotifyANRLockedInterruptible);
@@ -3371,7 +3395,7 @@ void InputDispatcher::doDispatchCycleFinishedLockedInterruptible( 
        nsecs_t eventDuration = finishTime - dispatchEntry->deliveryTime;

        nsecs_t eventDuration = finishTime - dispatchEntry->deliveryTime;

        if (eventDuration > SLOW_EVENT_PROCESSING_WARNING_TIMEOUT) {

        if (eventDuration > SLOW_EVENT_PROCESSING_WARNING_TIMEOUT) {

            String8 msg;

            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);

                    connection->getWindowName(), eventDuration * 0.000001f);

            dispatchEntry->eventEntry->appendDescription(msg);

            dispatchEntry->eventEntry->appendDescription(msg);

            ALOGI("%s", msg.string());

            ALOGI("%s", msg.string());
@@ -3634,9 +3658,10 @@ void InputDispatcher::dump(String8& dump) { 
    dump.append("Input Dispatcher State:\n");

    dump.append("Input Dispatcher State:\n");

    dumpDispatchStateLocked(dump);

    dumpDispatchStateLocked(dump);





    dump.append(INDENT "Configuration:\n");

    if (!mLastANRState.isEmpty()) {

    dump.appendFormat(INDENT2 "KeyRepeatDelay: %0.1fms\n", mConfig.keyRepeatDelay * 0.000001f);

        dump.append("\nInput Dispatcher State at time of last ANR:\n");

    dump.appendFormat(INDENT2 "KeyRepeatTimeout: %0.1fms\n", mConfig.keyRepeatTimeout * 0.000001f);

        dump.append(mLastANRState);

    }

}

}





void InputDispatcher::monitor() {

void InputDispatcher::monitor() {

services/input/InputDispatcher.h

+3 −0
Original line number Original line Diff line number Diff line
@@ -948,6 +948,9 @@ private: 
    // Focused application.

    // Focused application.

    sp<InputApplicationHandle> mFocusedApplicationHandle;

    sp<InputApplicationHandle> mFocusedApplicationHandle;





    // Dispatcher state at time of last ANR.

    String8 mLastANRState;



    // Dispatch inbound events.

    // Dispatch inbound events.

    bool dispatchConfigurationChangedLocked(

    bool dispatchConfigurationChangedLocked(

            nsecs_t currentTime, ConfigurationChangedEntry* entry);

            nsecs_t currentTime, ConfigurationChangedEntry* entry);