Android之输出Handler日志

发表于 更新于 评论： 阅读次数：

今天看到一篇文章提到了给Looper加日志以观察GC，发现这个Looper打日志这个小技巧有助于调试UI卡顿问题，我们学学这个技巧吧。

通过统计主线程Looper中每个Message的耗时，很容易找出主线程耗时过多的操作。这些操作往往是导致UI卡顿的罪魁祸首。

你可能会说，我在Handler.handMessage()中也可以添加计时代码呀，在Looper中统计有什么好处？如果是你自己写的Handler的确也很容易统计，但如果是别人写的呢，如果是第三方库中的呢？另一方面，即便自己写的，如何保证新加的Handler不会遗漏计时代码？所以这种做法并不可取。看看更好的做法是怎样的。

setMessageLogging()

注释文档中说，setMessageLogging()用于当前Looper处理Message时打印日志。

  • 传null参数关闭日志功能，传非null的printer开启日志功能
  • 开启日志功能后，会在每个Message分发的开始以及结束时输出日志信息到printer，具体的日志信息包括区分Message的目标Hander以及Message内容

对照loop()方法源码(省略无关部分)，跟上面描述一致。所以这里不再赘述。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
// android.os.Looper.java
	
public static void loop() {
    final Looper me = myLooper();
    final MessageQueue queue = me.mQueue;
    ...
    for (;;) {
        Message msg = queue.next(); // might block
        ...
        // This must be in a local variable, in case a UI event sets the logger
        final 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);
        }
        ...
    }
}
	
/**
 * Control logging of messages as they are processed by this Looper.  If
 * enabled, a log message will be written to <var>printer</var>
 * at the beginning and ending of each message dispatch, identifying the
 * target Handler and message contents.
 *
 * @param printer A Printer object that will receive log messages, or
 * null to disable message logging.
 */
public void setMessageLogging(@Nullable Printer printer) {
    mLogging = printer;
}

输出Handler日志

界面上有一个使用Handler实现的轮播图，每隔5秒发消息切换到下一张图片。我们给它加上日志功能，代码如下：

1
2
3
4
5
6
7
8
9
Looper.getMainLooper().setMessageLogging(new Printer() {
    @Override
    public void println(String x) {
		// 为了便于logcat中观察, 我们只输出当前页面的日志
        if (x != null && x.contains("EventCenterFragment")) {
            Log.i(CmPerf.TAG, x);
        }
    }
});

每次切换图片时会输出如下格式的日志：

1
2
3
4
12-12 10:35:38.614 9542-9542 I: >>>>> Dispatching to Handler (com.tc.igame.view.common.fragment.EventCenterFragment$1) {101c258} null: 1
12-12 10:35:38.615 9542-9542 I: <<<<< Finished to Handler (com.tc.igame.view.common.fragment.EventCenterFragment$1) {101c258} null
12-12 10:35:43.617 9542-9542 I: >>>>> Dispatching to Handler (com.tc.igame.view.common.fragment.EventCenterFragment$1) {101c258} null: 1
12-12 10:35:43.618 9542-9542 I: <<<<< Finished to Handler (com.tc.igame.view.common.fragment.EventCenterFragment$1) {101c258} null

Dispatching to Handler和Finished to Handler对应首一次Message处理过程。我们可以根据这种特定的日志格式为每个Message处理加上耗时统计。具体做这可参考《为你的android程序加上gc监控吧！》，这里不展开。

补充

《为你的android程序加上gc监控吧！》中提到的gc监控做法太过复杂，并不可取。实际上，Android 6.0(API 23)之后art虚拟机支持如下方式获取gc次数和gc耗时：

1
2
Debug.getRuntimeStat("art.gc.gc-count");
Debug.getRuntimeStat("art.gc.gc-time");

我们直接调用系统API即可很方便地获取到gc次数和gc耗时。

添加如下代码并在Android Monitor中强制gc，观察输出的日志。

1
2
3
4
5
6
7
8
9
Looper.getMainLooper().setMessageLogging(new Printer() {
    @Override
    public void println(String x) {
        if (x != null && x.contains("EventCenter") && x.contains("Finished to Handler")) {
            Log.i(CmPerf.TAG, "looper println: count=" + Debug.getRuntimeStat("art.gc.gc-count"));
            //Log.i(CmPerf.TAG, "looper println: time=" + Debug.getRuntimeStat("art.gc.gc-time"));
        }
    }
});

GC日志参考