Android 教你如何发现 APP 卡顿

最近部门打算优化下 APP 在低端机上的卡顿状况，既然想优化，就必须获取卡顿状况，那么如何获取卡顿状况就是本文目的。

通常主线程过多的 UI 绘制、大量的 IO 操做或是大量的计算操做占用 CPU，致使 App 界面卡顿。只要咱们能在发生卡顿的时候，捕捉到主线程的堆栈信息和系统的资源使用信息，便可准确分析卡顿发生在什么函数，资源占用状况如何。那么问题就是如何有效检测 Android 主线程的卡顿发生？

用 adb 系统工具观察 App 的卡顿数据状况，试图重现场景来定位问题。

经常使用的方式是使用 adb SurfaceFlinger 服务和 adb gfxinfo 功能，在自动化操做 app 的过程当中，使用 adb 获取数据来监控 app 的流畅状况，发现出现出现卡顿的时间段，寻找出现卡顿的场景和操做。

方式1：adb shell dumpsysSurfaceFlinger

使用 ‘adb shell dumpsysSurfaceFlinger’ 命令便可获取最近 127 帧的数据，经过按期执行 adb 命令，获取帧数来计算出帧率 FPS。

方式2：adb shell dumpsys gfxinfo

使用 ‘adb shell dumpsys gfxinfo’ 命令便可获取最新 128 帧的绘制信息，详细包括每一帧绘制的 Draw，Process，Execute 三个过程的耗时，若是这三个时间总和超过 16.6ms 即认为是发生了卡顿。

已有的两种方案比较适合衡量回归卡顿问题的修复效果和判断某些特定场景下是否有卡顿状况，然而，这样的方式有几个明显的不足：

• 通常很难构造实际用户卡顿的环境来重现；

• 这种方式操做起来比较麻烦，需编写自动化用例，没法覆盖大量的可疑场景，测试重现耗时耗人力；

• 没法衡量静态页面的卡顿状况；

• 出现卡顿的时候app没法及时获取运行状态和信息，开发定位困难。

随着对Android 源码的深刻研究，也有了其余两种比较方便的方式，而且这两种方式侵入性小，占用内存低，可以更好的用在实际场景中：

1. 利用UI线程的Looper打印的日志匹配；

2. 使用Choreographer.FrameCallback

利用 UI 线程的 Looper 打印的日志匹配

Android 主线程更新 UI。若是界面1秒钟刷新少于 60 次，即 FPS 小于 60，用户就会产生卡顿感受。简单来讲，Android 使用消息机制进行 UI 更新，UI 线程有个 Looper，在其 loop方法中会不断取出 message，调用其绑定的 Handler 在 UI 线程执行。若是在 handler 的 dispatchMesaage 方法里有耗时操做，就会发生卡顿。

下面来看下 Looper.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();

        // Allow overriding a threshold with a system prop. e.g.
        // adb shell 'setprop log.looper.1000.main.slow 1 && stop && start'
        final int thresholdOverride =
                SystemProperties.getInt("log.looper."
                        + Process.myUid() + "."
                        + Thread.currentThread().getName()
                        + ".slow", 0);

        boolean slowDeliveryDetected = false;

        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);
            }
            // Make sure the observer won't change while processing a transaction.
            final Observer observer = sObserver;

            final long traceTag = me.mTraceTag;
            long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
            long slowDeliveryThresholdMs = me.mSlowDeliveryThresholdMs;
            if (thresholdOverride > 0) {
                slowDispatchThresholdMs = thresholdOverride;
                slowDeliveryThresholdMs = thresholdOverride;
            }
            final boolean logSlowDelivery = (slowDeliveryThresholdMs > 0) && (msg.when > 0);
            final boolean logSlowDispatch = (slowDispatchThresholdMs > 0);

            final boolean needStartTime = logSlowDelivery || logSlowDispatch;
            final boolean needEndTime = logSlowDispatch;

            if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
                Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
            }

            final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
            final long dispatchEnd;
            Object token = null;
            if (observer != null) {
                token = observer.messageDispatchStarting();
            }
            long origWorkSource = ThreadLocalWorkSource.setUid(msg.workSourceUid);
            try {
                msg.target.dispatchMessage(msg);
                if (observer != null) {
                    observer.messageDispatched(token, msg);
                }
                dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
            } catch (Exception exception) {
                if (observer != null) {
                    observer.dispatchingThrewException(token, msg, exception);
                }
                throw exception;
            } finally {
                ThreadLocalWorkSource.restore(origWorkSource);
                if (traceTag != 0) {
                    Trace.traceEnd(traceTag);
                }
            }
            if (logSlowDelivery) {
                if (slowDeliveryDetected) {
                    if ((dispatchStart - msg.when) <= 10) {
                        Slog.w(TAG, "Drained");
                        slowDeliveryDetected = false;
                    }
                } else {
                    if (showSlowLog(slowDeliveryThresholdMs, msg.when, dispatchStart, "delivery",
                            msg)) {
                        // Once we write a slow delivery log, suppress until the queue drains.
                        slowDeliveryDetected = true;
                    }
                }
            }
            if (logSlowDispatch) {
                showSlowLog(slowDispatchThresholdMs, dispatchStart, dispatchEnd, "dispatch", msg);
            }

            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();
        }
    }

代码中两处标红的地方，就是 msg.target.dispatchMessage(msg) 的执行先后索打印的 log。经过测量处理时间就能检测到部分UI线程是否有耗时的操做。注意到这行执行代码的先后，有两个 logging.println 函数，若是设置了logging，会分别打印出 ”>>>>> Dispatching to “ 和 ”<<<<< Finished to “ 这样的日志，这样咱们就能够经过两次log的时间差值，来计算 dispatchMessage 的执行时间，从而设置阈值判断是否发生了卡顿。

那么如何设置 logging 呢？

咱们看下面的代码：

/**
     * 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 final class Looper { private Printer mLogging; public void setMessageLogging(@Nullable Printer printer) { mLogging = printer; } } 

public interface Printer { void println(String x); }

Looper 的 mLogging 是私有的，而且提供了 setMessageLogging(@Nullable Printer printer) 方法，因此咱们能够本身实现一个 Printer，在经过 setMessageLogging() 方法传入便可，代码以下： 

public class BlockDetectByPrinter {
    
    public static void start() {
        Looper.getMainLooper().setMessageLogging(new Printer() {
            private static final String START = ">>>>> Dispatching";
            private static final String END = "<<<<< Finished";

            @Override
            public void println(String x) {
                if (x.startsWith(START)) {
                    LogMonitor.getInstance().startMonitor();
                }
                if (x.startsWith(END)) {
                    LogMonitor.getInstance().removeMonitor();
                }
            }
        });
    }
}

设置了logging后，loop方法会回调 logging.println 打印出每次消息执行的时间日志：”>>>>> Dispatching to “和”<<<<< Finished to “。BlockDetectByPrinter 的使用则在Application 的 onCreate 方法中调用 BlockDetectByPrinter.start() 便可。

咱们能够简单实现一个 LogMonitor 来记录卡顿时候主线程的堆栈信息。当匹配到 >>>>> Dispatching 时，执行 startMonitor，会在 200ms（设定的卡顿阈值）后执行任务，这个任务负责在子线程（非UI线程）打印UI线程的堆栈信息。若是消息低于 200ms 内执行完成，就能够匹配到 <<<<< Finished 日志，那么在打印堆栈任务启动前执行 removeMonitor 取消了这个任务，则认为没有卡顿的发生；若是消息超过 200ms 才执行完毕，此时认为发生了卡顿，并打印 UI 线程的堆栈信息。

LogMonitor如何实现？

public class LogMonitor {
    private static final String TAG = "LogMonitor";
    private static LogMonitor sInstance = new LogMonitor();
    private HandlerThread mLogThread = new HandlerThread("log");
    private Handler mIoHandler;
    private static final long TIME_BLOCK = 200L;

    private LogMonitor() {
        mLogThread.start();
        mIoHandler = new Handler(mLogThread.getLooper());
    }

    private static Runnable mLogRunnable = new Runnable() {
        @Override
        public void run() {
            StringBuilder sb = new StringBuilder();
            StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
            for (StackTraceElement s : stackTrace) {
                sb.append(s.toString() + "\n");
            }
            Log.e(TAG, sb.toString());
        }
    };

    public static LogMonitor getInstance() {
        return sInstance;
    }

    public boolean isMonitor() {
        return mIoHandler.hasCallbacks(mLogRunnable);
    }

    public void startMonitor() {
        mIoHandler.postDelayed(mLogRunnable, TIME_BLOCK);
    }

    public void removeMonitor() {
        mIoHandler.removeCallbacks(mLogRunnable);
    }
}

这里咱们使用 HandlerThread 来构造一个 Handler，HandlerThread 继承自 Thread，实际上就一个 Thread，只不过比普通的 Thread 多了一个 Looper，对外提供本身这个 Looper 对象的 getLooper 方法，而后建立 Handler 时将 HandlerThread 中的 looper 对象传入。这样咱们的 mIoHandler 对象就是与 HandlerThread 这个非 UI 线程绑定的了，它处理耗时操做将不会阻塞UI。若是UI线程阻塞超过 200ms，就会在子线程中执行 mLogRunnable，打印出 UI 线程当前的堆栈信息，若是处理消息没有超过 1000ms，则会实时的 remove 掉这个mLogRunnable 任务。

发生卡顿时打印出堆栈信息的大体内容以下，开发能够经过 log 定位耗时的地方。

2020-10-30 14:26:13.823 30359-30415/com.example.myproxyplugin E/LogMonitor: java.lang.Thread.sleep(Native Method)
    java.lang.Thread.sleep(Thread.java:443)
    java.lang.Thread.sleep(Thread.java:359)
    com.example.myproxyplugin.MainActivity$1.run(MainActivity.java:22)
    android.os.Handler.handleCallback(Handler.java:900)
    android.os.Handler.dispatchMessage(Handler.java:103)
    android.os.Looper.loop(Looper.java:219)
    android.app.ActivityThread.main(ActivityThread.java:8347)
    java.lang.reflect.Method.invoke(Native Method)
    com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513)
    com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1055)

优势：用户使用 app 或者测试过程当中都能从app层面来监控卡顿状况，一旦出现卡顿能记录 app 状态和信息， 只要dispatchMesaage执行耗时过大都会记录下来，再也不有前面两种adb方式面临的问题与不足。

缺点：需另开子线程获取堆栈信息，会消耗少许系统资源。

在实际实现中，不一样手机不一样 Android  系统甚至是不一样的 ROM 版本，Loop 函数不必定都能打印出 ”>>>>> Dispatching to “ 和 ”<<<<< Finished to “ 这样的日志，致使该方式没法进行。

优化的策略：咱们知道 Loop 函数开始和结束必会执行 println 打印日志，因此优化版本将卡顿的判断改成，Loop输出第一句 log 时看成 startMonitor，输出下一句log时看成end时刻来解决这个问题。

其实 Looper 中有个 Observer 接口能够很好的完成这个任务，只是由于被标记为 hide 了，因此咱们不能使用，不过能够知道下。

Observer 接口提供了三个方法，分别是监放任务开始，结束，发生错误的回调。

    /** {@hide} */
    public interface Observer {
        /**
         * Called right before a message is dispatched.
         *
         * <p> The token type is not specified to allow the implementation to specify its own type.
         *
         * @return a token used for collecting telemetry when dispatching a single message.
         *         The token token must be passed back exactly once to either
         *         {@link Observer#messageDispatched} or {@link Observer#dispatchingThrewException}
         *         and must not be reused again.
         *
         */
        Object messageDispatchStarting();

        /**
         * Called when a message was processed by a Handler.
         *
         * @param token Token obtained by previously calling
         *              {@link Observer#messageDispatchStarting} on the same Observer instance.
         * @param msg The message that was dispatched.
         */
        void messageDispatched(Object token, Message msg);

        /**
         * Called when an exception was thrown while processing a message.
         *
         * @param token Token obtained by previously calling
         *              {@link Observer#messageDispatchStarting} on the same Observer instance.
         * @param msg The message that was dispatched and caused an exception.
         * @param exception The exception that was thrown.
         */
        void dispatchingThrewException(Object token, Message msg, Exception exception);
    }

利用Choreographer.FrameCallback监控卡顿

Choreographer.FrameCallback 官方文档连接（https://developer.android.com/reference/android/view/Choreographer.FrameCallback.html）

咱们知道， Android 系统每隔 16ms 发出 VSYNC 信号，来通知界面进行重绘、渲染，每一次同步的周期为16.6ms，表明一帧的刷新频率。SDK 中包含了一个相关类，以及相关回调。理论上来讲两次回调的时间周期应该在 16ms，若是超过了 16ms 咱们则认为发生了卡顿，利用两次回调间的时间周期来判断是否发生卡顿（这个方案是 Android 4.1 API 16 以上才支持）。

这个方案的原理主要是经过 Choreographer 类设置它的 FrameCallback 函数，当每一帧被渲染时会触发回调 FrameCallback， FrameCallback 回调 void doFrame (long frameTimeNanos) 函数。一次界面渲染会回调 doFrame 方法，若是两次 doFrame 之间的间隔大于 16.6ms 说明发生了卡顿。 

public class FPSFrameCallback implements Choreographer.FrameCallback {

    private static final String TAG = "FPS_TEST";
    private long mLastFrameTimeNanos = 0;
    private long mFrameIntervalNanos;

    public FPSFrameCallback(long lastFrameTimeNanos) {
        mLastFrameTimeNanos = lastFrameTimeNanos;
        // 1s 60 帧
        mFrameIntervalNanos = (long) (1000000000 / 60.0);
    }

    @Override
    public void doFrame(long frameTimeNanos) {

        //初始化时间
        if (mLastFrameTimeNanos == 0) {
            mLastFrameTimeNanos = frameTimeNanos;
        }
        final long jitterNanos = frameTimeNanos - mLastFrameTimeNanos;
        if (jitterNanos >= mFrameIntervalNanos) {
            final long skippedFrames = jitterNanos / mFrameIntervalNanos;
            if (skippedFrames > 30) {
                Log.i(TAG, "Skipped " + skippedFrames + " frames!  "
                        + "The application may be doing too much work on its main thread.");
            }
        }
        mLastFrameTimeNanos = frameTimeNanos;
        //注册下一帧回调
        Choreographer.getInstance().postFrameCallback(this);
    }
}

本质和 log 没太多区别，可是这个更加通用些，不会由于机型系统缘由出现不可用的问题。 

示例

下面进入实战，看看代码层面是如何实现的。 

MainActivity 代码以下：

public class MainActivity extends AppCompatActivity {
    Handler handler = new Handler(Looper.getMainLooper());

    private final Runnable runnable = new Runnable() {
        @Override
        public void run() {
            try {
                Thread.sleep(600);
                handler.postDelayed(runnable, 500);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    };

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        Choreographer.getInstance().postFrameCallback(new FPSFrameCallback(System.nanoTime()));
        BlockDetectByPrinter.start();
    }

    @Override
    protected void onResume() {
        super.onResume();
        handler.postDelayed(runnable, 500);
    }

}

收集到的堆栈信息以下：

2020-10-30 14:26:13.823 30359-30415/com.example.myproxyplugin E/LogMonitor: java.lang.Thread.sleep(Native Method)
    java.lang.Thread.sleep(Thread.java:443)
    java.lang.Thread.sleep(Thread.java:359)
    com.example.myproxyplugin.MainActivity$1.run(MainActivity.java:22)
    android.os.Handler.handleCallback(Handler.java:900)
    android.os.Handler.dispatchMessage(Handler.java:103)
    android.os.Looper.loop(Looper.java:219)
    android.app.ActivityThread.main(ActivityThread.java:8347)
    java.lang.reflect.Method.invoke(Native Method)
    com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513)
    com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1055)

对于 FPS log 能够看到以下信息：

     I/Choreographer: Skipped 64 frames!  The application may be doing too much work on its main thread.
     I/FPS_TEST: Skipped 65 frames!  The application may be doing too much work on its main thread.

若是你要把上面的方法用到本身的APP 中，那么还须要不少操做，具体能够阅读参考文献的内容。

 

参考文章

广研Android卡顿监控系统