性能优化-界面卡顿和丢帧(Choreographer 代码检测)

标签： Choreographer UI卡顿 UI丢帧

作者公众号：


本文将介绍3个知识点：

  1. 获取系统UI刷新频率
  2. 检测UI丢帧和卡顿
  3. 输出UI丢帧和卡顿堆栈信息
    Choreographer.jpg

系统UI刷新频率

Android系统每隔16ms重绘UI界面，16ms是因为Android系统规定UI绘图的刷新频率60FPS。Android系统每隔16ms，发送一个系统级别信号VSYNC唤起重绘操作。1秒内绘制UI界面60次。每16ms为一个UI界面绘制周期。
现在有些手机厂商的手机屏幕刷新频率已经是120FPS，每隔8.3毫秒重绘UI界面；
获取系统UI刷新频率

    private float getRefreshRate() { //获取屏幕主频频率
        Display display = getWindowManager().getDefaultDisplay();
        float refreshRate = display.getRefreshRate();
        Log.d(TAG, "屏幕主频频率 =" + refreshRate);
        return refreshRate;
    }

log打印如下：

D/MainActivity: 屏幕主频频率 =60.0

UI丢帧和卡顿检查-Choreographer

平常所说的“丢帧”情况，并不是真的把绘图的帧给“丢失”了，也而是UI绘图的操作没有和系统16ms的绘图更新频率步调一致，开发者代码在绘图中绘制操作太多，导致操作的时间超过16ms，在Android系统需要在16ms时需要重绘的时刻由于UI线程被阻塞而绘制失败。如果丢的帧数量是一两帧，用户在视觉上没有明显感觉，但是如果超过3帧，用户就有视觉上的感知。丢帧数如果再持续增多，在视觉上就是所谓的“卡顿”。

丢帧是引起卡顿的重要原因。在Android中可以通过Choreographer检测Android系统的丢帧情况。

public class MainActivity extends Activity {
    ...
    private MyFrameCallback mFrameCallback = new MyFrameCallback();
    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        Choreographer.getInstance().postFrameCallback(mFrameCallback);
        
        MYTest();
        button = findViewById(R.id.bottom);
        button.setOnClickListener(new View.OnClickListener() {
            @Override
            public void onClick(View v) {
                uiLongTimeWork();
                Log.d(MainActivity.class.getSimpleName(), "button click");
            }
        });
    }

    private void MYTest() {
        setContentView(R.layout.activity_main);
        Log.d(MainActivity.class.getSimpleName(), "MYTest");
    }

    private float getRefreshRate() { //获取屏幕主频频率
        Display display = getWindowManager().getDefaultDisplay();
        float refreshRate = display.getRefreshRate();
//        Log.d(TAG, "屏幕主频频率 =" + refreshRate);
        return refreshRate;
    }

    @RequiresApi(api = Build.VERSION_CODES.JELLY_BEAN)
    public class MyFrameCallback implements Choreographer.FrameCallback {
        private String TAG = "性能检测";
        private long lastTime = 0;
        
        @Override
        public void doFrame(long frameTimeNanos) {
            if (lastTime == 0) {
                //代码第一次初始化。不做检测统计。
                lastTime = frameTimeNanos;
            } else {
                long times = (frameTimeNanos - lastTime) / 1000000;
                int frames = (int) (times / (1000/getRefreshRate()));
                if (times > 16) {
                    Log.w(TAG, "UI线程超时(超过16ms):" + times + "ms" + " , 丢帧:" + frames);
                }
                lastTime = frameTimeNanos;
            }
            Choreographer.getInstance().postFrameCallback(mFrameCallback);
        }
    }

    private void uiLongTimeWork() {
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

Choreographer周期性的在UI重绘时候触发，在代码中记录上一次和下一次绘制的时间间隔，如果超过16ms，就意味着一次UI线程重绘的“丢帧”。丢帧的数量为间隔时间除以16，如果超过3，就开始有卡顿的感知。
Log如下

W/性能检测: UI线程超时(超过16ms):33ms , 丢帧:1
W/性能检测: UI线程超时(超过16ms):19ms , 丢帧:1
W/性能检测: UI线程超时(超过16ms):1016ms , 丢帧:60
W/性能检测: UI线程超时(超过16ms):24ms , 丢帧:1
W/性能检测: UI线程超时(超过16ms):21ms , 丢帧:1
W/性能检测: UI线程超时(超过16ms):1016ms , 丢帧:60
W/性能检测: UI线程超时(超过16ms):23ms , 丢帧:1
W/性能检测: UI线程超时(超过16ms):33ms , 丢帧:1

如果手动点击按钮故意阻塞1秒，丢弃的帧数更多。丢帧:60，就是点击button按钮，执行uiLongTimeWork产生的；

UI丢帧和卡顿堆栈信息输出

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

先看下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);

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

>>>>> Dispatching to

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

<<<<< Finished to

表示Looper分发主线程上的消失结束。
从>>>>> Dispatching to 到 <<<<< Finished to 之间这段操作，就是留给开发者所写的代码发生在上层主线程操作的动作，通常所说的卡顿也就发生这一段。

正确情况下，从消息分发（>>>>> Dispatching to）开始，到消息处理结束（<<<<< Finished to），这段操作理想情况应在（1000/UI刷新频率）ms以内完成，如果超过这一时间，也即意味着卡顿和丢帧。

现在设计一种技巧性的编程方案：在（>>>>> 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的时候没来得及把堆栈打印线程删除掉，因此就输出了当前堆栈信息，此堆栈信息刚好即为发生卡顿和丢帧的代码堆栈，正好就是所需的卡顿和丢帧检测代码。

public class MainActivity extends Activity {
    ...
    private CheckTask mCheckTask = new CheckTask();
    
        @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        check();
        ...
        button = findViewById(R.id.bottom);
        button.setOnClickListener(new View.OnClickListener() {
            @Override
            public void onClick(View v) {
                uiLongTimeWork();
                Log.d(MainActivity.class.getSimpleName(), "button click");
            }
        });
    }
    
    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 void uiLongTimeWork() {
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    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 log() {
        StringBuilder sb = new StringBuilder();
        StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
        for (StackTraceElement s : stackTrace) {
            sb.append(s + "\n");
        }

        Log.w(TAG, sb.toString());
    }

运行输出：

1970-02-14 17:35:06.367 11590-11590/com.yanbing.aop_project D/MainActivity: button click
1970-02-14 17:35:06.367 11590-11611/com.yanbing.aop_project W/MainActivity: java.lang.String.indexOf(String.java:1658)
    java.lang.String.indexOf(String.java:1638)
    java.lang.String.contains(String.java:2126)
    java.lang.Class.classNameImpliesTopLevel(Class.java:1169)
    java.lang.Class.getEnclosingConstructor(Class.java:1159)
    java.lang.Class.isLocalClass(Class.java:1312)
    java.lang.Class.getSimpleName(Class.java:1219)
    com.yanbing.aop_project.MainActivity$2.onClick(MainActivity.java:71)
    android.view.View.performClick(View.java:6294)
    android.view.View$PerformClick.run(View.java:24770)
    android.os.Handler.handleCallback(Handler.java:790)
    android.os.Handler.dispatchMessage(Handler.java:99)
    android.os.Looper.loop(Looper.java:164)
    android.app.ActivityThread.main(ActivityThread.java:6494)
    java.lang.reflect.Method.invoke(Native Method)
    com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
    com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)

可以看到当点击按钮故意制造一个卡顿后，卡顿被检测到，并且输出和定位到了卡顿的具体代码位置。
总结：利用主线程的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，从而检测到任何大于或等于该时间的耗时操作。

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 159,569评论 4赞 363
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 67,499评论 1赞 294
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 109,271评论 0赞 244
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 44,087评论 0赞 209
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 52,474评论 3赞 287
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 40,670评论 1赞 222
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 31,911评论 2赞 313
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 30,636评论 0赞 202
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 34,397评论 1赞 246
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,607评论 2赞 246
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,093评论 1赞 261
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 28,418评论 2赞 254
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 33,074评论 3赞 237
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,092评论 0赞 8
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,865评论 0赞 196
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 35,726评论 2赞 276
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 35,627评论 2赞 270