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

Commit 63cb7d3a authored by Ben Miles's avatar Ben Miles
Browse files

Include ANR duration & start time in the ANR report file 

ANR duration (ms) added as "Timeout: ...."
ANR start uptime (ms) added as "TimeoutStart: ..."

The rationale behind adding these is so that downstream debugging tools know when the unresponsive period started and how long it lasted for. Since the platform can dynamically extend timeouts (and OEMs can pick different timeouts) we can't depend on heuristics like "broadcast ANR timeout is always 10/60 seconds", etc.

Test: Triggered some ANRs & checked files in /data/anr
Bug: 409760497
Flag: EXEMPT small change to error logging

Change-Id: I58371b554de8c655d0671a6530a86f27aa78fd1a
parent 28b7f414

services/core/java/com/android/server/am/ProcessErrorStateRecord.java

+1 −1
Original line number Diff line number Diff line
@@ -538,7 +538,7 @@ class ProcessErrorStateRecord { 
                isSilentAnr ? null : processCpuTracker, isSilentAnr ? null : lastPids,

                nativePidsFuture, tracesFileException, firstPidEndOffset, annotation,

                criticalEventLog, memoryHeaders, auxiliaryTaskExecutor, firstPidFilePromise,

                latencyTracker);

                latencyTracker, timeoutRecord);



        if (isMonitorCpuUsage()) {

            // Wait for the first call to finish

services/core/java/com/android/server/am/StackTracesDumpHelper.java

+110 −22
Original line number Diff line number Diff line
@@ -33,7 +33,9 @@ import android.util.SparseBooleanArray; 


import com.android.internal.annotations.GuardedBy;

import com.android.internal.os.ProcessCpuTracker;

import com.android.internal.os.TimeoutRecord;

import com.android.internal.os.anr.AnrLatencyTracker;

import com.android.server.utils.AnrTimer;



import java.io.File;

import java.io.FileOutputStream;
@@ -84,25 +86,39 @@ public class StackTracesDumpHelper { 
    /**

     * If a stack trace dump file is configured, dump process stack traces.

     * @param firstPids of dalvik VM processes to dump stack traces for first

     * @param processCpuTracker

     * @param lastPids of dalvik VM processes to dump stack traces for last

     * @param nativePidsFuture optional future for a list of native pids to dump stack crawls

     * @param logExceptionCreatingFile optional writer to which we log errors creating the file

     * @param auxiliaryTaskExecutor executor to execute auxiliary tasks on

     * @param latencyTracker the latency tracker instance of the current ANR.

     */

    public static File dumpStackTraces(ArrayList<Integer> firstPids,

            ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids,

            Future<ArrayList<Integer>> nativePidsFuture, StringWriter logExceptionCreatingFile,

            @NonNull Executor auxiliaryTaskExecutor, AnrLatencyTracker latencyTracker) {

    public static File dumpStackTraces(

            ArrayList<Integer> firstPids,

            ProcessCpuTracker processCpuTracker,

            SparseBooleanArray lastPids,

            Future<ArrayList<Integer>> nativePidsFuture,

            StringWriter logExceptionCreatingFile,

            @NonNull Executor auxiliaryTaskExecutor,

            AnrLatencyTracker latencyTracker) {

        return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture,

                logExceptionCreatingFile, null, null, null, null, auxiliaryTaskExecutor, null,

                latencyTracker);

                latencyTracker, null);

    }



    /**

     * If a stack trace dump file is configured, dump process stack traces.

     *

     * @param firstPids of dalvik VM processes to dump stack traces for first

     * @param processCpuTracker of dalvik VM processes

     * @param lastPids of dalvik VM processes to dump stack traces for last

     * @param nativePidsFuture optional future for a list of native pids to dump stack crawls

     * @param logExceptionCreatingFile optional writer to which we log errors creating the file

     * @param subject the subject of the dumped traces

     * @param criticalEventSection the critical event log, passed as a string

     * @param extraHeaders Optional, Extra headers added by the dumping method

     * @param auxiliaryTaskExecutor executor to execute auxiliary tasks on

     * @param latencyTracker the latency tracker instance of the current ANR.

     */

    public static File dumpStackTraces(ArrayList<Integer> firstPids,

            ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids,
@@ -110,21 +126,75 @@ public class StackTracesDumpHelper { 
            String subject, String criticalEventSection,

            LinkedHashMap<String, String> extraHeaders, @NonNull Executor auxiliaryTaskExecutor,

            AnrLatencyTracker latencyTracker) {

        return dumpStackTraces(

                firstPids,

                processCpuTracker,

                lastPids,

                nativePidsFuture,

                logExceptionCreatingFile,

                /* firstPidEndOffset= */ null,

                subject,

                criticalEventSection,

                extraHeaders,

                auxiliaryTaskExecutor,

                /* firstPidFilePromise= */ null,

                latencyTracker,

                /* timeoutRecord= */ null);

    }





    /**

     * If a stack trace dump file is configured, dump process stack traces.

     *

     * @param firstPids of dalvik VM processes to dump stack traces for first

     * @param processCpuTracker of dalvik VM processes

     * @param lastPids of dalvik VM processes to dump stack traces for last

     * @param nativePidsFuture optional future for a list of native pids to dump stack crawls

     * @param logExceptionCreatingFile optional writer to which we log errors creating the file

     * @param subject the subject of the dumped traces

     * @param criticalEventSection the critical event log, passed as a string

     * @param extraHeaders Optional, Extra headers added by the dumping method

     * @param auxiliaryTaskExecutor executor to execute auxiliary tasks on

     * @param firstPidEndOffset Optional, when it's set, it receives the start/end offset of the

     *     very first pid to be dumped.

     * @param latencyTracker the latency tracker instance of the current ANR.

     */

    public static File dumpStackTraces(

            ArrayList<Integer> firstPids,

            ProcessCpuTracker processCpuTracker,

            SparseBooleanArray lastPids,

            Future<ArrayList<Integer>> nativePidsFuture,

            StringWriter logExceptionCreatingFile,

            AtomicLong firstPidEndOffset,

            String subject,

            String criticalEventSection,

            LinkedHashMap<String, String> extraHeaders,

            @NonNull Executor auxiliaryTaskExecutor,

            Future<File> firstPidFilePromise,

            AnrLatencyTracker latencyTracker) {

        return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture,

                logExceptionCreatingFile, null, subject, criticalEventSection,

                extraHeaders, auxiliaryTaskExecutor, null, latencyTracker);

                logExceptionCreatingFile, firstPidEndOffset, subject, criticalEventSection,

                extraHeaders, auxiliaryTaskExecutor, firstPidFilePromise, latencyTracker,

                null);

    }



    /**

     * @param firstPidEndOffset Optional, when it's set, it receives the start/end offset

     *                        of the very first pid to be dumped.

     * @param timeoutRecord the timeout record of the current ANR.

     */

    /* package */ static File dumpStackTraces(ArrayList<Integer> firstPids,

            ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids,

            Future<ArrayList<Integer>> nativePidsFuture, StringWriter logExceptionCreatingFile,

            AtomicLong firstPidEndOffset, String subject, String criticalEventSection,

            LinkedHashMap<String, String> extraHeaders, @NonNull Executor auxiliaryTaskExecutor,

           Future<File> firstPidFilePromise, AnrLatencyTracker latencyTracker) {

    public static File dumpStackTraces(

            ArrayList<Integer> firstPids,

            ProcessCpuTracker processCpuTracker,

            SparseBooleanArray lastPids,

            Future<ArrayList<Integer>> nativePidsFuture,

            StringWriter logExceptionCreatingFile,

            AtomicLong firstPidEndOffset,

            String subject,

            String criticalEventSection,

            LinkedHashMap<String, String> extraHeaders,

            @NonNull Executor auxiliaryTaskExecutor,

            Future<File> firstPidFilePromise,

            AnrLatencyTracker latencyTracker,

            TimeoutRecord timeoutRecord) {

        try {



            if (latencyTracker != null) {
@@ -163,13 +233,31 @@ public class StackTracesDumpHelper { 
                }

                return null;

            }

            boolean extraHeadersExist = extraHeaders != null && !extraHeaders.isEmpty();



            if (subject != null || criticalEventSection != null || extraHeadersExist) {

                appendtoANRFile(tracesFile.getAbsolutePath(),

                        (subject != null ? "Subject: " + subject + "\n" : "")

                        + (extraHeadersExist ? stringifyHeaders(extraHeaders) + "\n\n" : "")

                        + (criticalEventSection != null ? criticalEventSection : ""));

            StringBuilder headers = new StringBuilder();

            if (subject != null) {

                headers.append("Subject: ").append(subject).append("\n");

            }

            if (timeoutRecord != null) {

                AnrTimer.ExpiredTimer expiredTimer = AnrTimer.expiredTimer(timeoutRecord);

                if (expiredTimer != null && expiredTimer.mDurationMs > 0) {

                    headers.append("Timeout: ")

                            .append(expiredTimer.mDurationMs)

                            .append("\n");

                }

                if (expiredTimer != null && expiredTimer.mStartMs > 0) {

                    headers.append("TimeoutStart: ")

                            .append(expiredTimer.mStartMs)

                            .append("\n");

                }

            }

            if (extraHeaders != null && !extraHeaders.isEmpty()) {

                headers.append(stringifyHeaders(extraHeaders)).append("\n\n");

            }

            if (criticalEventSection != null) {

                headers.append(criticalEventSection);

            }

            if (!headers.isEmpty()) {

                appendtoANRFile(tracesFile.getAbsolutePath(), headers.toString());

            }



            long firstPidEndPos = dumpStackTraces(

services/core/java/com/android/server/utils/AnrTimer.java

+12 −3
Original line number Diff line number Diff line
@@ -304,8 +304,17 @@ public class AnrTimer<V> implements AutoCloseable { 
        // The timer ID.

        final int mTimerId;



        ExpiredTimer(int id) {

        // The start uptime of the timer in millis.

        public final long mStartMs;



        // The total duration uptime of the timer in millis.

        // Includes any extensions.

        public final long mDurationMs;



        ExpiredTimer(int id, long startMs, long durationMs) {

            mTimerId = id;

            mStartMs = startMs;

            mDurationMs = durationMs;

        }

    }
@@ -876,7 +885,7 @@ public class AnrTimer<V> implements AutoCloseable { 
     * message is delivered to the upper layers and false if it could not be delivered.

     */

    @Keep

    private boolean expire(int timerId, int pid, int uid, long elapsedMs) {

    private boolean expire(int timerId, int pid, int uid, long startMs, long elapsedMs) {

        trace("expired", timerId, pid, uid, mLabel, elapsedMs);

        final V arg;

        synchronized (mLock) {
@@ -887,7 +896,7 @@ public class AnrTimer<V> implements AutoCloseable { 
                mTotalErrors++;

                return false;

            }

            mExpiredTimers.put(timerId, new ExpiredTimer(timerId));

            mExpiredTimers.put(timerId, new ExpiredTimer(timerId, startMs, elapsedMs));

            mTotalExpired++;

        }

        final Message msg = Message.obtain(mHandler, mWhat, arg);

services/core/java/com/android/server/wm/AnrController.java

+18 −8
Original line number Diff line number Diff line
@@ -70,7 +70,7 @@ class AnrController { 
        try {

            timeoutRecord.mLatencyTracker.notifyAppUnresponsiveStarted();

            timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowStarted();

            preDumpIfLockTooSlow();

            preDumpIfLockTooSlow(timeoutRecord);

            timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowEnded();

            final ActivityRecord activity;

            timeoutRecord.mLatencyTracker.waitingOnGlobalLockStarted();
@@ -167,7 +167,7 @@ class AnrController { 
    private boolean notifyWindowUnresponsive(@NonNull IBinder inputToken,

            TimeoutRecord timeoutRecord) {

        timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowStarted();

        preDumpIfLockTooSlow();

        preDumpIfLockTooSlow(timeoutRecord);

        timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowEnded();

        final int pid;

        final boolean aboveSystem;
@@ -279,7 +279,7 @@ class AnrController { 
     * <p>

     * Do not hold the {@link WindowManagerGlobalLock} while calling this method.

     */

    private void preDumpIfLockTooSlow() {

    private void preDumpIfLockTooSlow(TimeoutRecord timeoutRecord) {

        if (!Build.IS_DEBUGGABLE)  {

            return;

        }
@@ -341,11 +341,21 @@ class AnrController { 


            String criticalEvents =

                    CriticalEventLog.getInstance().logLinesForSystemServerTraceFile();

            final File tracesFile = StackTracesDumpHelper.dumpStackTraces(firstPids,

                    null /* processCpuTracker */, null /* lastPids */,

            final File tracesFile =

                    StackTracesDumpHelper.dumpStackTraces(

                            firstPids,

                            null /* processCpuTracker */,

                            null /* lastPids */,

                            CompletableFuture.completedFuture(nativePids),

                    null /* logExceptionCreatingFile */, "Pre-dump", criticalEvents,

                    null /* extraHeaders */, Runnable::run, null/* AnrLatencyTracker */);

                            null /* logExceptionCreatingFile */,

                            null /* firstPidEndOffset */,

                            "Pre-dump",

                            criticalEvents,

                            null /* extraHeaders */,

                            Runnable::run /* auxiliaryTaskExecutor */,

                            null /* firstPidFilePromise */,

                            null /* latencyTracker */,

                            timeoutRecord);

            if (tracesFile != null) {

                tracesFile.renameTo(

                        new File(tracesFile.getParent(), tracesFile.getName() + "_pre"));

services/core/jni/com_android_server_utils_AnrTimer.cpp

+11 −8
Original line number Diff line number Diff line
@@ -683,8 +683,8 @@ class AnrTimerService { 
    // A notifier is called with a timer ID, the timer's tag, and the client's cookie.  The pid

    // and uid that were originally assigned to the timer are passed as well.  The elapsed time

    // is the time since the timer was scheduled.

    using notifier_t = bool (*)(timer_id_t, int pid, int uid, nsecs_t elapsed, void* cookie,

                                jweak object, bool expired, uint32_t token);

    using notifier_t = bool (*)(timer_id_t, int pid, int uid, nsecs_t started, nsecs_t elapsed,

                                void* cookie, jweak object, bool expired, uint32_t token);



    enum Status {

        Invalid,
@@ -1415,6 +1415,7 @@ void AnrTimerService::expire(timer_id_t timerId) { 
    // Save the timer attributes for the notification

    int pid = 0;

    int uid = 0;

    nsecs_t started = 0;

    nsecs_t elapsed = 0;

    SplitPoint meta;

    bool expired = false;
@@ -1435,6 +1436,7 @@ void AnrTimerService::expire(timer_id_t timerId) { 
        }

        pid = t.pid;

        uid = t.uid;

        started = t.started;

        elapsed = now() - t.started;

    }
@@ -1446,8 +1448,8 @@ void AnrTimerService::expire(timer_id_t timerId) { 


    // Deliver the notification outside of the lock.

    if (meta.action == SplitAction::Expire || meta.action == SplitAction::EarlyNotify) {

        if (!notifier_(timerId, pid, uid, elapsed, notifierCookie_, notifierObject_, expired,

                       meta.token)) {

        if (!notifier_(timerId, pid, uid, started, elapsed, notifierCookie_, notifierObject_,

                       expired, meta.token)) {

            // Notification failed, which means the listener will never call accept() or

            // discard().  Do not reinsert the timer.

            discard(timerId);
@@ -1530,8 +1532,8 @@ struct AnrArgs { 
static AnrArgs gAnrArgs;



// The cookie is the address of the AnrArgs object to which the notification should be sent.

static bool anrNotify(AnrTimerService::timer_id_t timerId, int pid, int uid, nsecs_t elapsed,

                      void* cookie, jweak jtimer, bool expired, uint32_t token) {

static bool anrNotify(AnrTimerService::timer_id_t timerId, int pid, int uid, nsecs_t started,

                      nsecs_t elapsed, void* cookie, jweak jtimer, bool expired, uint32_t token) {

    AutoMutex _l(gAnrLock);

    AnrArgs* target = reinterpret_cast<AnrArgs* >(cookie);

    JNIEnv *env;
@@ -1543,7 +1545,8 @@ static bool anrNotify(AnrTimerService::timer_id_t timerId, int pid, int uid, nse 
    jobject timer = env->NewGlobalRef(jtimer);

    if (timer != nullptr) {

        if (expired) {

            r = env->CallBooleanMethod(timer, target->func, timerId, pid, uid, ns2ms(elapsed));

            r = env->CallBooleanMethod(timer, target->func, timerId, pid, uid, ns2ms(started),

                                       ns2ms(elapsed));

        } else {

            env->CallVoidMethod(timer, target->funcEarly, timerId, pid, uid, ns2ms(elapsed), token);

            r = true;
@@ -1694,7 +1697,7 @@ int register_android_server_utils_AnrTimer(JNIEnv* env) 


    jclass service = FindClassOrDie(env, className);

    gAnrArgs.clazz = MakeGlobalRefOrDie(env, service);

    gAnrArgs.func = env->GetMethodID(gAnrArgs.clazz, "expire", "(IIIJ)Z");

    gAnrArgs.func = env->GetMethodID(gAnrArgs.clazz, "expire", "(IIIJJ)Z");

    gAnrArgs.funcEarly = env->GetMethodID(gAnrArgs.clazz, "notifyEarly", "(IIIJI)V");



    env->GetJavaVM(&gAnrArgs.vm);