Android打印主线程所有方法执行时间、handler耗时_android 打印当前线程

前言：

我们知道Android卡顿主要是主线程中有耗时操作导致的，那么我们怎么能方便快捷的获取主线程中的所有耗时方法执行时间呢？今天我们来介绍两个方案

方案一：利用Looper.java中loop()方法的logging.print的特殊关键字进行耗时打印：

在消息分发时，主线程的looper.loop()方法会遍历所有的消息进行分发，执行耗时任务。我们看下源码的loop()方法：

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
            final Printer logging = me.mLogging;
            if (logging != null) {
                logging.println(">>>>> Dispatching to " + msg.target + " " +
                        msg.callback + ": " + msg.what);
            }
 
            final long traceTag = me.mTraceTag;
 
... ...
... ...
 
if (logging != null) {
                logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
            }

可以发现，每个消息在分发开始和执行结束后，在logging.print()方法里有 >>>>>  和 <<<<<< 的特殊字符，那么我们可以根据这个特殊字符来作为这个消息执行的开始和结束标志，进而依此来打印主线程中的消息执行时间，具体代码如下：

/**
     * 方案一：只能打印耗时消息，无法知道具体是哪个消息耗时
     */
    private void methodOne() {
        outputMainLooper();
    }
 
    private void outputMainLooper() {
        Looper.getMainLooper().setMessageLogging(new Printer() {
            @Override
            public void println(String x) {
                if (x.startsWith(">>>>>")) {
                    startTime = System.currentTimeMillis();
                } else if (x.startsWith("<<<<<")) {
                    long end = System.currentTimeMillis();
                    //时间阈值可以自己定义，这里是10
                    if ((end - startTime) > 10) {
                        Log.i("buder mainLoop ------ ：", (end - startTime)+ " ");
                    }
                }
            }
        });
    }

这种方案能简单快速打印出主线程中消息的具体执行时间，但是我们的目的是要找出具体哪个方法耗时，需要打印出耗时方法的堆栈信息才能帮助我们快速定位到卡顿点。因此方案一仅打印message的耗时时间而无法定位到具体函数，局限性较大，没有多大意义。

方案二：利用Handler.java的sendMessageAtTime()、dispatchMessage()方法，找出耗时函数并打印耗时时间：

我们知道主线程中发送消息，最终会调用sendMessageAtTime方法入消息队列，然后通过dispatchMessage进行消息分发执行。那么我们分别利用这两个方法就可以监控到消息是谁发的，以及这个消息的执行时间。为了能够做到这些，我们利用epic框架对这两个函数进行hook，具体做法如下：

步骤一：gradle中添加库依赖：

implementation 'me.weishu:epic:0.6.0'

步骤二：hook sendMessageAtTime 和 dispatchMessage

/**
     * 方案二：可以打印耗时消息以及耗时时间
     */
    private void methodTwo() {
        final long[] startTime = {0};
        //hook sendMessageAtTime，具体msg消息是谁
        DexposedBridge.findAndHookMethod(Handler.class, "sendMessageAtTime", Message.class, long.class, new XC_MethodHook() {
            @Override
            protected void beforeHookedMethod(MethodHookParam param) throws Throwable {
                super.beforeHookedMethod(param);
                sMsgDetail.put((Message) param.args[0], Log.getStackTraceString(new Throwable()).replace("java.lang.Throwable", ""));
            }
 
            @Override
            protected void afterHookedMethod(MethodHookParam param) throws Throwable {
                super.afterHookedMethod(param);
            }
        });
 
        //hook dispatchMessage，打印耗时时间
        DexposedBridge.findAndHookMethod(Handler.class, "dispatchMessage", Message.class, new XC_MethodHook() {
            @Override
            protected void beforeHookedMethod(MethodHookParam param) throws Throwable {
                startTime[0] = System.currentTimeMillis();
                super.beforeHookedMethod(param);
            }
 
            @Override
            protected void afterHookedMethod(MethodHookParam param) throws Throwable {
                super.afterHookedMethod(param);
                long costTime = System.currentTimeMillis() - startTime[0];
                String stackMessage = null;
                //时间阈值可以自己定义，这里是10
                if (costTime > 10) {
                    stackMessage = sMsgDetail.get(param.args[0]);
                    Log.i("buder", costTime + "***********");
                    Log.e("buder", stackMessage);
                }
            }
        });
    }

执行方法后，可以清楚看到程序中具体是哪里执行了耗时操作：

这里即打印出了两个方案的耗时时间，又看到了MainActivity的第24和36行含有耗时操作。

完整代码：

• MainActivity.java，点击事件模拟耗时任务：

public class MainActivity extends AppCompatActivity {
 
    private Button mButton;
 
    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
 
        mButton  = findViewById(R.id.btn);
        mButton.setOnClickListener(new View.OnClickListener() {
            @Override
            public void onClick(View v) {
                //耗时操作任务一
                new Handler().postDelayed(new Runnable() {
                    @Override
                    public void run() {
                        for(int i = 0; i < 100000; i++) {
                            System.out.println("test 1");
                        }
                        Toast toast = Toast.makeText(getApplicationContext(),"点击完成", Toast.LENGTH_LONG);
                        toast.show();
                    }
                }, 1000);
 
                //耗时操作任务二
                new Handler().post(new Runnable() {
                    @Override
                    public void run() {
                        for(int i = 0; i < 200000; i++) {
                            System.out.println("test 1");
                        }
                    }
                });
 
            }
        });
    }
}

• DemoApplication.java 包含上述两种统计方案：
• 记得在Manifest中添加android:name=".DemoApplication"

public class DemoApplication extends Application {
 
    private long startTime = 0;
    private static ConcurrentHashMap<Message, String> sMsgDetail = new ConcurrentHashMap<>();
 
    @Override
    protected void attachBaseContext(Context base) {
        super.attachBaseContext(base);
        //获取耗时方案一
        methodOne();
        //获取耗时方案二
        methodTwo();
    }
 
    /**
     * 方案二：可以打印耗时消息以及耗时时间
     */
    private void methodTwo() {
        final long[] startTime = {0};
        //hook sendMessageAtTime，具体msg消息是谁
        DexposedBridge.findAndHookMethod(Handler.class, "sendMessageAtTime", Message.class, long.class, new XC_MethodHook() {
            @Override
            protected void beforeHookedMethod(MethodHookParam param) throws Throwable {
                super.beforeHookedMethod(param);
                sMsgDetail.put((Message) param.args[0], Log.getStackTraceString(new Throwable()).replace("java.lang.Throwable", ""));
            }
 
            @Override
            protected void afterHookedMethod(MethodHookParam param) throws Throwable {
                super.afterHookedMethod(param);
            }
        });
 
        //hook dispatchMessage，打印耗时时间
        DexposedBridge.findAndHookMethod(Handler.class, "dispatchMessage", Message.class, new XC_MethodHook() {
            @Override
            protected void beforeHookedMethod(MethodHookParam param) throws Throwable {
                startTime[0] = System.currentTimeMillis();
                super.beforeHookedMethod(param);
            }
 
            @Override
            protected void afterHookedMethod(MethodHookParam param) throws Throwable {
                super.afterHookedMethod(param);
                long costTime = System.currentTimeMillis() - startTime[0];
                String stackMessage = null;
                //时间阈值可以自己定义，这里是100
                if (costTime > 100) {
                    stackMessage = sMsgDetail.get(param.args[0]);
                    Log.i("buder", costTime + "***********");
                    Log.e("buder", stackMessage);
                }
            }
        });
    }
 
    /**
     * 方案一：只能打印耗时消息，无法知道具体是哪个消息耗时
     */
    private void methodOne() {
        outputMainLooper();
    }
 
    private void outputMainLooper() {
        Looper.getMainLooper().setMessageLogging(new Printer() {
            @Override
            public void println(String x) {
                if (x.startsWith(">>>>>")) {
                    startTime = System.currentTimeMillis();
                } else if (x.startsWith("<<<<<")) {
                    long end = System.currentTimeMillis();
                    //时间阈值可以自己定义，这里是100
                    if ((end - startTime) > 100) {
                        Log.i("buder mainLoop ------ ：", (end - startTime)+ " ");
                    }
                }
            }
        });
    }
 
    @Override
    public void onCreate() {
        super.onCreate();
    }
}

完整地址：base_component_learn/timeConsumingPrinter at master · buder-cp/base_component_learn · GitHub

参考博客：深入探索Android卡顿优化（下）_JsonChao的博客-CSDN博客_android lancet

epic相关：Weishu's Notes - 为数不多的维术

android-hacker/epic ：android-hacker/epic - Gitter