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.