android log输出参数,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 printer

* 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

9Looper.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

412-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

2Debug.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

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