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

Commit 076a3683 authored by Lee Shombert's avatar Lee Shombert
Browse files

Add ANR expiration trace points 

This adds a trace point to the AnrTimer track for every expired
ANR. The trace point is the formatted string "%s(%d,%d,%s,%d)":
 * The operation (currently "expired")
 * The Linux pid that expired
 * The Linux uid that expired
 * The ANR category
 * The elapsed time (in ms) since the timer was scheduled

The elapsed time can be used to look backward in a trace to create a
synthetic slice that covers the span from when the timer was scheduled
to when it expired.

The trace point begins a slice, which ends when the client accepts or
discards the ANR.

This tracing is always on.  ANR expiration is uncommon, so there are
no performance issues.

Tested manually by generating an ANR and examining the resulting
perfetto trace.

Test: atest
 * FrameworksServicesTests:com.android.server.am
 * FrameworksMockingServicesTests:com.android.server.am
 * CtsAppTestCases
 * FrameworksServicesTests:AnrTimerTest

Bug: 319454931
Change-Id: Ie8c2ee28bca2b105fafebbbe84930e8f58e90598
parent 2014926d

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

+23 −32
Original line number Diff line number Diff line
@@ -96,16 +96,10 @@ public class AnrTimer<V> implements AutoCloseable { 
    private static boolean DEBUG = false;



    /**

     * The trace tag.

     * The trace tag is the same usd by ActivityManager.

     */

    private static final long TRACE_TAG = Trace.TRACE_TAG_ACTIVITY_MANAGER;



    /**

     * Enable tracing from the time a timer expires until it is accepted or discarded.  This is

     * used to diagnose long latencies in the client.

     */

    private static final boolean ENABLE_TRACING = false;



    /**

     * Return true if the feature is enabled.  By default, the value is take from the Flags class

     * but it can be changed for local testing.
@@ -320,24 +314,21 @@ public class AnrTimer<V> implements AutoCloseable { 
    }



    /**

     * Start a trace on the timer.  The trace is laid down in the AnrTimerTrack.

     * Generate a trace point with full timer information.  The meaning of milliseconds depends on

     * the caller.

     */

    private void traceBegin(int timerId, int pid, int uid, String what) {

        if (ENABLE_TRACING) {

            final String label = formatSimple("%s(%d,%d,%s)", what, pid, uid, mLabel);

            final int cookie = timerId;

            Trace.asyncTraceForTrackBegin(TRACE_TAG, TRACK, label, cookie);

        }

    private void trace(String op, int timerId, int pid, int uid, long milliseconds) {

        final String label =

                formatSimple("%s(%d,%d,%d,%s,%d)", op, timerId, pid, uid, mLabel, milliseconds);

        Trace.instantForTrack(TRACE_TAG, TRACK, label);

    }



    /**

     * End a trace on the timer.

     * Generate a trace point with just the timer ID.

     */

    private void traceEnd(int timerId) {

        if (ENABLE_TRACING) {

            final int cookie = timerId;

            Trace.asyncTraceForTrackEnd(TRACE_TAG, TRACK, cookie);

        }

    private void trace(String op, int timerId) {

        final String label = formatSimple("%s(%d)", op, timerId);

        Trace.instantForTrack(TRACE_TAG, TRACK, label);

    }



    /**
@@ -492,7 +483,7 @@ public class AnrTimer<V> implements AutoCloseable { 
                    return false;

                }

                nativeAnrTimerAccept(mNative, timer);

                traceEnd(timer);

                trace("accept", timer);

                return true;

            }

        }
@@ -511,7 +502,7 @@ public class AnrTimer<V> implements AutoCloseable { 
                    return false;

                }

                nativeAnrTimerDiscard(mNative, timer);

                traceEnd(timer);

                trace("discard", timer);

                return true;

            }

        }
@@ -629,13 +620,18 @@ public class AnrTimer<V> implements AutoCloseable { 
    }



    /**

     * The notifier that a timer has fired.  The timerId and original pid/uid are supplied.  This

     * method is called from native code.  This method takes mLock so that a timer cannot expire

     * in the middle of another operation (like start or cancel).

     * The notifier that a timer has fired.  The timerId and original pid/uid are supplied.  The

     * elapsed time is the actual time since the timer was scheduled, which may be different from

     * the original timeout if the timer was extended or if other delays occurred. This method

     * takes mLock so that a timer cannot expire in the middle of another operation (like start or

     * cancel).

     *

     * This method is called from native code.  The function must return true if the expiration

     * 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) {

        traceBegin(timerId, pid, uid, "expired");

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

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

        V arg = null;

        synchronized (mLock) {

            arg = mTimerArgMap.get(timerId);
@@ -815,9 +811,4 @@ public class AnrTimer<V> implements AutoCloseable { 


    /** Prod the native library to log a few statistics. */

    private static native void nativeAnrTimerDump(long service, boolean verbose);



    // This is not a native method but it is a native interface, in the sense that it is called from

    // the native layer to report timer expiration.  The function must return true if the expiration

    // message is delivered to the upper layers and false if it could not be delivered.

    // private boolean expire(int timerId, int pid, int uid);

}

services/core/jni/com_android_server_utils_AnrTimer.cpp

+20 −7
Original line number Diff line number Diff line
@@ -113,8 +113,10 @@ class AnrTimerService { 
    static const timer_id_t NOTIMER = 0;



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

    using notifier_t = bool (*)(timer_id_t, int pid, int uid, void* cookie, jweak object);

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



    enum Status {

        Invalid,
@@ -278,6 +280,9 @@ class AnrTimerService::Timer { 
    // The state of this timer.

    Status status;



    // The time at which the timer was started.

    nsecs_t started;



    // The scheduled timeout.  This is an absolute time.  It may be extended.

    nsecs_t scheduled;
@@ -297,6 +302,7 @@ class AnrTimerService::Timer { 
            timeout(0),

            extend(false),

            status(Invalid),

            started(0),

            scheduled(0),

            extended(false) {

    }
@@ -310,6 +316,7 @@ class AnrTimerService::Timer { 
            timeout(0),

            extend(false),

            status(Invalid),

            started(0),

            scheduled(0),

            extended(false) {

    }
@@ -322,7 +329,8 @@ class AnrTimerService::Timer { 
            timeout(timeout),

            extend(extend),

            status(Running),

            scheduled(now() + timeout),

            started(now()),

            scheduled(started + timeout),

            extended(false) {

        if (extend && pid != 0) {

            initial.fill(pid);
@@ -714,6 +722,7 @@ void AnrTimerService::expire(timer_id_t timerId) { 
    // Save the timer attributes for the notification

    int pid = 0;

    int uid = 0;

    nsecs_t elapsed = 0;

    bool expired = false;

    {

        AutoMutex _l(lock_);
@@ -727,11 +736,14 @@ void AnrTimerService::expire(timer_id_t timerId) { 
            // accept or discard).

            insert(t);

        }

        pid = t.pid;

        uid = t.uid;

        elapsed = now() - t.started;

    }



    // Deliver the notification outside of the lock.

    if (expired) {

        if (!notifier_(timerId, pid, uid, notifierCookie_, notifierObject_)) {

        if (!notifier_(timerId, pid, uid, elapsed, notifierCookie_, notifierObject_)) {

            AutoMutex _l(lock_);

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

            // discard().  Do not reinsert the timer.
@@ -804,7 +816,7 @@ 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,

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

                      void* cookie, jweak jtimer) {

    AutoMutex _l(gAnrLock);

    AnrArgs* target = reinterpret_cast<AnrArgs* >(cookie);
@@ -816,7 +828,8 @@ static bool anrNotify(AnrTimerService::timer_id_t timerId, int pid, int uid, 
    jboolean r = false;

    jobject timer = env->NewGlobalRef(jtimer);

    if (timer != nullptr) {

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

        // Convert the elsapsed time from ns (native) to ms (Java)

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

        env->DeleteGlobalRef(timer);

    }

    target->vm->DetachCurrentThread();
@@ -909,7 +922,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", "(III)Z");

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

    env->GetJavaVM(&gAnrArgs.vm);



    nativeSupportEnabled = NATIVE_SUPPORT;