Android性能监测：Looper机制监测卡顿和丢帧（二）

浅浅的花香味﹌ 2023-10-17 22:44 54阅读 0赞

**Android性能监测：Looper机制监测卡顿和丢帧（二）**

附录1使用Android的Choreographer监测App发生的UI卡顿丢帧问题。Choreographer本身依赖于Android主线程的Looper消息机制。  
发生在Android主线程的每16ms重绘操作依赖于Main Looper中消息的发送和获取。如果App一切运行正常，无卡顿无丢帧现象发生，那么开发者的代码在主线程Looper消息队列中发送和接收消息的时间会很短，理想情况是16ms，这是也是Android系统规定的时间。但是，如果一些发生在主线程的代码写的太重，执行任务花费时间太久，就会在主线程延迟Main Looper的消息在16ms尺度范围内的读和写。

先看下Android官方实现的Looper中loop（）函数代码官方实现：

/**
         * Run the message queue in this thread. Be sure to call
         * {@link #quit()} to end the 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
                final Printer logging = me.mLogging;
                if (logging != null) {
                    logging.println(">>>>> Dispatching to " + msg.target + " " +
                            msg.callback + ": " + msg.what);
                }
    
                final long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
    
                final long traceTag = me.mTraceTag;
                if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
                    Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
                }
                final long start = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
                final long end;
                try {
                    msg.target.dispatchMessage(msg);
                    end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
                } finally {
                    if (traceTag != 0) {
                        Trace.traceEnd(traceTag);
                    }
                }
                if (slowDispatchThresholdMs > 0) {
                    final long time = end - start;
                    if (time > slowDispatchThresholdMs) {
                        Slog.w(TAG, "Dispatch took " + time + "ms on "
                                + Thread.currentThread().getName() + ", h=" +
                                msg.target + " cb=" + msg.callback + " msg=" + msg.what);
                    }
                }
    
                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.recycleUnchecked();
            }
        }

在loop()函数中，Android完成了Looper消息队列的分发，在分发消息开始，会打印一串log日志：

logging.println(">>>>> Dispatching to " + msg.target + " " +
                            msg.callback + ": " + msg.what);

同时在消息处理结束后也会打印一串消息日志：

logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);

正常的情况下，分发消息开始到消息结束，理想的情况下应该在16ms以内。但是分发处理的消息到上层，由开发者代码接管并处理，如果耗时太久，就很可能超出16ms，也即发生了丢帧，超时太多，由于Android系统依赖主线程Looper重绘UI的消息迟迟得不到处理，那么就导致绘图动作停滞，用户视觉上就会感受到卡顿。  
利用这一特性和情景，可以使用主线程的Looper监测系统发生的卡顿和丢帧。具体是这样的：首先给App的主线程Looper注册一个自己的消息日志输出打印器，正常情况下，该日志打印器将输出全部的Android Looper上的日志，但是在这里，技巧性的过滤两个特殊日志：

>>>>> Dispatching to

表示Looper开始分发主线程上的消息。

<<<<< Finished to

表示Looper分发主线程上的消失结束。

从>>>>> Dispatching to 到 <<<<< Finished to 之间这段操作，就是留给开发者所写的代码发生在上层主线程操作的动作，通常所说的卡顿也就发生这一段。  
正确情况下，从消息分发（>>>>> Dispatching to）开始，到消息处理结束（<<<<< Finished to），这段操作理想情况应在16ms以内完成，如果超过这一时间，也即意味着卡顿和丢帧。  
现在设计一种技巧性的编程方案：在（>>>>> Dispatching to）开始时候，延时一定时间（THREAD\_HOLD）执行一个线程，延时时间为THREAD\_HOLD，该线程只完成打印当前Android堆栈的信息。THREAD\_HOLD即为开发者意图捕捉到的超时时间。如果没什么意外，该线程在THREAD\_HOLD后，就打印出当前Android的堆栈信息。巧就巧妙在利用这一点儿，因为延时THREAD\_HOLD执行的线程和主线程Looper中的线程是并行执行的，当在>>>>> Dispatching to时刻把延时线程任务构建完抛出去等待THREAD\_HOLD后执行，而当前的Looper线程中的消息分发也在执行，这两个是并发执行的不同线程。  
设想如果Looper线程中的操作代码很快就执行完毕，不到16ms就到了<<<<< Finished to，那么毫无疑问当前的主线程无卡顿和丢帧发生。如果特意把THREAD\_HOLD设置成大于16ms的延时时间，比如1000ms，如果线程运行顺畅不卡顿无丢帧，那么从>>>>> Dispatching to到达<<<<< Finished to后，把延时THREAD\_HOLD执行的线程删除掉，那么线程就不会输出任何堆栈信息。若不行主线程发生阻塞，当从>>>>> Dispatching to到达<<<<< Finished to花费1000ms甚至更长时间后，而由于到达<<<<< Finished to的时候没来得及把堆栈打印线程删除掉，因此就输出了当前堆栈信息，此堆栈信息刚好即为发生卡顿和丢帧的代码堆栈，正好就是所需的卡顿和丢帧检测代码。

如代码：

package zhangphil.test;
    
    import android.os.Bundle;
    import android.os.Handler;
    import android.os.HandlerThread;
    import android.os.Looper;
    import android.support.annotation.Nullable;
    import android.support.v7.app.AppCompatActivity;
    import android.util.Log;
    import android.util.Printer;
    import android.view.View;
    
    public class ANRActivity extends AppCompatActivity {
    
        private final String TAG = "卡顿性能检测";
        private CheckTask mCheckTask = new CheckTask();
    
        @Override
        protected void onCreate(@Nullable Bundle savedInstanceState) {
            super.onCreate(savedInstanceState);
    
            check();
    
            setContentView(R.layout.activity_anr);
            findViewById(R.id.button).setOnClickListener(new View.OnClickListener() {
                @Override
                public void onClick(View v) {
                    uiLongTimeWork();
                }
            });
        }
    
        private void check() {
            Looper.getMainLooper().setMessageLogging(new Printer() {
                private final String START = ">>>>> Dispatching to";
                private final String END = "<<<<< Finished to";
    
                @Override
                public void println(String s) {
                    if (s.startsWith(START)) {
                        mCheckTask.start();
                    } else if (s.startsWith(END)) {
                        mCheckTask.end();
                    }
                }
            });
        }
    
        private class CheckTask {
            private HandlerThread mHandlerThread = new HandlerThread("卡顿检测");
            private Handler mHandler;
    
            private final int THREAD_HOLD = 1000;
    
            public CheckTask() {
                mHandlerThread.start();
                mHandler = new Handler(mHandlerThread.getLooper());
            }
    
            private Runnable mRunnable = new Runnable() {
                @Override
                public void run() {
                    log();
                }
            };
    
            public void start() {
                mHandler.postDelayed(mRunnable, THREAD_HOLD);
            }
    
            public void end() {
                mHandler.removeCallbacks(mRunnable);
            }
        }
    
        private void uiLongTimeWork() {
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    
        /**
         * 输出当前异常或及错误堆栈信息。
         */
        private void log() {
            StringBuilder sb = new StringBuilder();
            StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
            for (StackTraceElement s : stackTrace) {
                sb.append(s + "\n");
            }
    
            Log.w(TAG, sb.toString());
        }
    }

运行输出：

07-24 10:12:08.476 17064-17110/zhangphil.test W/卡顿性能检测: java.lang.Thread.sleep(Native Method)
        java.lang.Thread.sleep(Thread.java:386)
        java.lang.Thread.sleep(Thread.java:327)
        zhangphil.test.ANRActivity.uiLongTimeWork(ANRActivity.java:78)
        zhangphil.test.ANRActivity.access$000(ANRActivity.java:13)
        zhangphil.test.ANRActivity$1.onClick(ANRActivity.java:28)
        android.view.View.performClick(View.java:6291)
        android.view.View$PerformClick.run(View.java:24931)
        android.os.Handler.handleCallback(Handler.java:808)
        android.os.Handler.dispatchMessage(Handler.java:101)
        android.os.Looper.loop(Looper.java:166)
        android.app.ActivityThread.main(ActivityThread.java:7425)
        java.lang.reflect.Method.invoke(Native Method)
        com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:245)
        com.android.internal.os.ZygoteInit.main(ZygoteInit.java:921)

可以看到当点击按钮故意制造一个卡顿后，卡顿被检测到，并且输出和定位到了卡顿的具体代码位置。  
总结起来，利用主线程的Looper检测卡顿和丢帧，从成对的消息分发（>>>>> Dispatching to），到消息处理结束（<<<<< Finished to），正常的理想时间应该在16ms以内，若当前代码耗时太多，这一段时间就会超过16ms。假设现在要检测耗时超过1秒（1000ms）的耗时操作，那就在>>>>> Dispatching to时刻，抛出一个延时执行的线程，该线程打印当前堆栈的信息，延时的时间特意设置成阈值1000。此种情况下，正常顺畅执行无卡顿无丢帧的代码从>>>>> Dispatching to到<<<<< Finished to之间不会超过设置的阈值1000ms，因此当Looper中的代码到达<<<<< Finished to就把之前抛出来延时执行的线程删除掉，也就不会输出任何堆栈信息。但是只有当耗时代码从>>>>> Dispatching to到<<<<< Finished to超过了1000ms，由于Looper中由于耗时操作很晚（超过我们设定的阈值）才到达<<<<< Finished to，没赶上删掉堆栈打印线程，于是堆栈线程得以有机会打印当前堆栈信息，这就是卡顿和丢帧的发生场景检测机制。  
事实上可以灵活设置延时阈值THREAD\_HOLD，从而检测到任何大于或等于该时间的耗时操作。

附录：  
1，《Android性能：通过Choreographer检测UI丢帧和卡顿》链接：https://blog.csdn.net/zhangphil/article/details/81129246