December 2, 2016

Monitor Android Looper

As I write in the previous post Android Message Handling Mechanism, all messages dispatched to main thread will be handled in the looper of main thread. If a message cost a long time, Android will report an ANR. It's necessary for a monitor library to detect ANR, so I need to log time costs for handling each message and report when the time reaches a threshold.
Let's begin with the code of Looper.loop():

public static void loop() {  
    final Looper me = myLooper();
    if (me == null) {
        throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");
    }
    final MessageQueue queue = me.mQueue;

    // Make sure the identity of this thread is that of the local process,
    // and keep track of what that identity token actually is.
    Binder.clearCallingIdentity();
    final long ident = Binder.clearCallingIdentity();

    for (;;) {
        Message msg = queue.next(); // might block
        if (msg == null) {
            // No message indicates that the message queue is quitting.
            return;
        }

        // This must be in a local variable, in case a UI event sets the logger
        Printer logging = me.mLogging;
        if (logging != null) {
            logging.println(">>>>> Dispatching to " + msg.target + " " +
                    msg.callback + ": " + msg.what);
        }

        msg.target.dispatchMessage(msg);

        if (logging != null) {
            logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
        }

        // Make sure that during the course of dispatching the
        // identity of the thread wasn't corrupted.
        final long newIdent = Binder.clearCallingIdentity();
        if (ident != newIdent) {
            Log.wtf(TAG, "Thread identity changed from 0x"
                    + Long.toHexString(ident) + " to 0x"
                    + Long.toHexString(newIdent) + " while dispatching to "
                    + msg.target.getClass().getName() + " "
                    + msg.callback + " what=" + msg.what);
        }

        msg.recycle();
    }
}

Obviously, we only need to care about the execution time of msg.target.dispatchMessage(msg). I was thinking about hook Handler.dispatchMessage(Message msg) via Xposed, but Xposed works on class-level, I'll get the execution time of all handler instance. Actually, I just wanna monitor the message handling time of main looper. So can we do it with a lighter way?
Look at these lines:

Printer logging = me.mLogging;
if (logging != null) {
    logging.println(">>>>> Dispatching to " + msg.target + " " +
            msg.callback + ": " + msg.what);
}

msg.target.dispatchMessage(msg);

if (logging != null) {
    logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}

Looper will print logs before and after handling message. We can consider the time difference as message handling time cost. All we need to do, is replace the mLogging with a customized printer. I write a monitor class to do this work:

package com.shunix.droidsentry.monitor;

import android.os.Looper;
import android.util.Printer;

/**
 * @author rayewang
 * @since 2016/11/23
 */
public class LooperMonitor {
    private final static int INTERVAL_THRESHOLD = 50;

    private static ThreadLocal<LooperMonitor> sInstance = new ThreadLocal<LooperMonitor>();

    public static void monitor() {
        if (sInstance.get() != null) {
            throw new RuntimeException("One looper can only be monitored once!");
        }
        Looper myLooper = Looper.myLooper();
        if (myLooper == null) {
            throw new IllegalStateException("The current thread must have a looper!");
        }
        sInstance.set(new LooperMonitor());
        myLooper.setMessageLogging(new LooperPrinter(myLooper));
    }

    static class LooperPrinter implements Printer {
        private final static String START_TAG = ">>>>> Dispatching to ";
        private final static String END_TAG = "<<<<< Finished to ";

        private Looper mLooper;
        private long mStartTime;
        private long mEndTime;

        public LooperPrinter(Looper looper) {
            mLooper = looper;
        }

        @Override
        public void println(String s) {
            if (s.startsWith(START_TAG)) {
                mStartTime = System.currentTimeMillis();
            } else if (s.startsWith(END_TAG)) {
                mEndTime = System.currentTimeMillis();
                if (mStartTime != 0) {
                    long interval = mEndTime - mStartTime;
                    if (interval > INTERVAL_THRESHOLD) {
                        // TODO report to server
                    }
                }
            }
        }
    }
}

To use this class, just call LooperMonitor.monitor(), this class will monitor the looper of calling thread automatically.