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 日志参考