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

Commit 712886fd authored by Makoto Onuki's avatar Makoto Onuki
Browse files

Log slow message delivery on Looper 

Sample log:
04-27 15:30:17.306  1000   942   942 W Looper  : Dispatch took 222ms on main, h=Handler (com.android.server.job.JobSchedulerService$JobHandler) {42042fc} cb=null msg=7 start=48162 end=48384
04-27 15:30:17.306  1000   942   942 W Looper  : Delivery took 235ms on main, h=Handler (com.android.server.job.JobSchedulerService$JobHandler) {42042fc} cb=null msg=4 start=48149 end=48384
04-27 15:30:17.773  1000   942   942 W Looper  : Dispatch took 445ms on main, h=Handler (android.app.ActivityThread$H) {5df4c77} cb=android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA@badd538 msg=0 start=48406 end=48851
04-27 15:30:17.828  1000   942   942 W Looper  : Drained
04-27 15:30:24.389  1000   942   942 W Looper  : Dispatch took 718ms on main, h=Handler (android.hardware.soundtrigger.SoundTriggerModule$NativeEventHandlerDelegate$1) {d7e9947} cb=null msg=4 start=54749 end=55467
04-27 15:30:24.389  1000   942   942 W Looper  : Delivery took 621ms on main, h=Handler (com.android.server.media.MediaSessionRecord$MessageHandler) {5851574} cb=null msg=7 start=54846 end=55467
04-27 15:30:24.499  1000   942   942 W Looper  : Drained

Bug: 78590632
Test: Boot and check log
Test: setprop log.looper.1000.android.bg 1 and runtime-restart and check log
Change-Id: Ief1fc65b40b8a3d583879f55a76288e3dba6be7d
parent 5d8dfe17

core/java/android/os/Looper.java

+70 −15
Original line number Diff line number Diff line
@@ -77,9 +77,17 @@ public final class Looper { 
    private Printer mLogging;

    private long mTraceTag;



    /* If set, the looper will show a warning log if a message dispatch takes longer than time. */

    /**

     * If set, the looper will show a warning log if a message dispatch takes longer than this.

     */

    private long mSlowDispatchThresholdMs;



    /**

     * If set, the looper will show a warning log if a message delivery (actual delivery time -

     * post time) takes longer than this.

     */

    private long mSlowDeliveryThresholdMs;



    /** Initialize the current thread as a looper.

      * This gives you a chance to create handlers that then reference

      * this looper, before actually starting the loop. Be sure to call
@@ -138,6 +146,16 @@ public final class Looper { 
        Binder.clearCallingIdentity();

        final long ident = Binder.clearCallingIdentity();



        // Allow overriding a threshold with a system prop. e.g.

        // adb shell 'setprop log.looper.1000.main.slow 1 && stop && start'

        final int thresholdOverride =

                SystemProperties.getInt("log.looper."

                        + Process.myUid() + "."

                        + Thread.currentThread().getName()

                        + ".slow", 0);



        boolean slowDeliveryDetected = false;



        for (;;) {

            Message msg = queue.next(); // might block

            if (msg == null) {
@@ -152,30 +170,50 @@ public final class Looper { 
                        msg.callback + ": " + msg.what);

            }



            final long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;



            final long traceTag = me.mTraceTag;

            long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;

            long slowDeliveryThresholdMs = me.mSlowDeliveryThresholdMs;

            if (thresholdOverride > 0) {

                slowDispatchThresholdMs = thresholdOverride;

                slowDeliveryThresholdMs = thresholdOverride;

            }

            final boolean logSlowDelivery = (slowDeliveryThresholdMs > 0) && (msg.when > 0);

            final boolean logSlowDispatch = (slowDispatchThresholdMs > 0);



            final boolean needStartTime = logSlowDelivery || logSlowDispatch;

            final boolean needEndTime = logSlowDispatch;



            if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {

                Trace.traceBegin(traceTag, msg.target.getTraceName(msg));

            }

            final long start = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();

            final long end;



            final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;

            final long dispatchEnd;

            try {

                msg.target.dispatchMessage(msg);

                end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();

                dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;

            } finally {

                if (traceTag != 0) {

                    Trace.traceEnd(traceTag);

                }

            }

            if (slowDispatchThresholdMs > 0) {

                final long time = end - start;

                if (time > slowDispatchThresholdMs) {

                    Slog.w(TAG, "Dispatch took " + time + "ms on "

                            + Thread.currentThread().getName() + ", h=" +

                            msg.target + " cb=" + msg.callback + " msg=" + msg.what);

            if (logSlowDelivery) {

                if (slowDeliveryDetected) {

                    if ((dispatchStart - msg.when) <= 10) {

                        Slog.w(TAG, "Drained");

                        slowDeliveryDetected = false;

                    }

                } else {

                    if (showSlowLog(slowDeliveryThresholdMs, msg.when, dispatchStart, "delivery",

                            msg)) {

                        // Once we write a slow delivery log, suppress until the queue drains.

                        slowDeliveryDetected = true;

                    }

                }

            }

            if (logSlowDispatch) {

                showSlowLog(slowDispatchThresholdMs, dispatchStart, dispatchEnd, "dispatch", msg);

            }



            if (logging != null) {

                logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
@@ -196,6 +234,19 @@ public final class Looper { 
        }

    }



    private static boolean showSlowLog(long threshold, long measureStart, long measureEnd,

            String what, Message msg) {

        final long actualTime = measureEnd - measureStart;

        if (actualTime < threshold) {

            return false;

        }

        // For slow delivery, the current message isn't really important, but log it anyway.

        Slog.w(TAG, "Slow " + what + " took " + actualTime + "ms "

                + Thread.currentThread().getName() + " h="

                + msg.target.getClass().getName() + " c=" + msg.callback + " m=" + msg.what);

        return true;

    }



    /**

     * Return the Looper object associated with the current thread.  Returns

     * null if the calling thread is not associated with a Looper.
@@ -243,9 +294,13 @@ public final class Looper { 
        mTraceTag = traceTag;

    }



    /** {@hide} */

    public void setSlowDispatchThresholdMs(long slowDispatchThresholdMs) {

    /**

     * Set a thresholds for slow dispatch/delivery log.

     * {@hide}

     */

    public void setSlowLogThresholdMs(long slowDispatchThresholdMs, long slowDeliveryThresholdMs) {

        mSlowDispatchThresholdMs = slowDispatchThresholdMs;

        mSlowDeliveryThresholdMs = slowDeliveryThresholdMs;

    }



    /**

core/java/com/android/internal/os/BackgroundThread.java

+7 −1
Original line number Diff line number Diff line
@@ -18,12 +18,15 @@ package com.android.internal.os; 


import android.os.Handler;

import android.os.HandlerThread;

import android.os.Looper;

import android.os.Trace;



/**

 * Shared singleton background thread for each process.

 */

public final class BackgroundThread extends HandlerThread {

    private static final long SLOW_DISPATCH_THRESHOLD_MS = 10_000;

    private static final long SLOW_DELIVERY_THRESHOLD_MS = 30_000;

    private static BackgroundThread sInstance;

    private static Handler sHandler;
@@ -35,7 +38,10 @@ public final class BackgroundThread extends HandlerThread { 
        if (sInstance == null) {

            sInstance = new BackgroundThread();

            sInstance.start();

            sInstance.getLooper().setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);

            final Looper looper = sInstance.getLooper();

            looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);

            looper.setSlowLogThresholdMs(

                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);

            sHandler = new Handler(sInstance.getLooper());

        }

    }

services/core/java/com/android/server/FgThread.java

+8 −1
Original line number Diff line number Diff line
@@ -17,6 +17,7 @@ 
package com.android.server;



import android.os.Handler;

import android.os.Looper;

import android.os.Trace;



/**
@@ -28,6 +29,9 @@ import android.os.Trace; 
 * to be delayed for a user-noticeable amount of time.

 */

public final class FgThread extends ServiceThread {

    private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;

    private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;



    private static FgThread sInstance;

    private static Handler sHandler;
@@ -39,7 +43,10 @@ public final class FgThread extends ServiceThread { 
        if (sInstance == null) {

            sInstance = new FgThread();

            sInstance.start();

            sInstance.getLooper().setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);

            final Looper looper = sInstance.getLooper();

            looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);

            looper.setSlowLogThresholdMs(

                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);

            sHandler = new Handler(sInstance.getLooper());

        }

    }

services/core/java/com/android/server/UiThread.java

+3 −1
Original line number Diff line number Diff line
@@ -28,6 +28,7 @@ import android.os.Trace; 
 */

public final class UiThread extends ServiceThread {

    private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;

    private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;

    private static UiThread sInstance;

    private static Handler sHandler;
@@ -48,7 +49,8 @@ public final class UiThread extends ServiceThread { 
            sInstance.start();

            final Looper looper = sInstance.getLooper();

            looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);

            looper.setSlowDispatchThresholdMs(SLOW_DISPATCH_THRESHOLD_MS);

            looper.setSlowLogThresholdMs(

                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);

            sHandler = new Handler(sInstance.getLooper());

        }

    }

services/java/com/android/server/SystemServer.java

+5 −0
Original line number Diff line number Diff line
@@ -156,6 +156,9 @@ public final class SystemServer { 
    // give any timezone code room without going into negative time.

    private static final long EARLIEST_SUPPORTED_TIME = 86400 * 1000;



    private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;

    private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;



    /*

     * Implementation class names. TODO: Move them to a codegen class or load

     * them from the build system somehow.
@@ -396,6 +399,8 @@ public final class SystemServer { 
                android.os.Process.THREAD_PRIORITY_FOREGROUND);

            android.os.Process.setCanSelfBackground(false);

            Looper.prepareMainLooper();

            Looper.getMainLooper().setSlowLogThresholdMs(

                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);



            // Initialize native services.

            System.loadLibrary("android_servers");