Android知识体系之异常处理-卡顿

Android知识体系

参考

自动化卡顿检测方案及优化
深入探索Android卡顿优化（上）
深入探索Android卡顿优化（下）

卡顿

关于什么是卡顿？可以参考什么是卡顿

原理

一个线程不管有多少Handler，它只会有一个Looper存在，主线程执行的任何代码都会通过Looper.loop()方法执行。而在Looper函数中，它有一个mLogging对象，这个对象在每个message处理前后都会被调用。主线程发生了卡顿，那一定是在dispatchMessage()方法中执行了耗时操作。那么，我们就可以通过这个mLogging对象对dispatchMessage()进行监控。

在线监测

利用loop()中打印的日志

大家都知道在Android UI线程中有个Looper，在其loop方法中会不断取出Message，调用其绑定的Handler在UI线程进行执行。

大致代码如下：

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

第15行代码，就是有可能发生卡顿的地方，注意这行代码的前后，有两个logging。如果设置了logging，会分别打印出“>>>>> Dispatching to”和“<<<<< Finished to”这样的Log。这样就给我们监视两次Log之间的时间差，来判断是否发生了卡顿。

public final class Looper {
    private Printer mLogging;
    public void setMessageLogging(@Nullable Printer printer) {
        mLogging = printer;
    }
}
public interface Printer {
    void println(String x);
}

所以，我们可以自己实现一个Printer，在通过setMessageLogging()方法传入即可。

public class MyApplication extends Application {
    @Override
    public void onCreate() {
        super.onCreate();
       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();
                }
            }
        });
    }
}

LogMonitor的代码如下：

public class LogMonitor {
    private static final long TIME_BLOCK = 1000L;
    private static LogMonitor sInstance = new LogMonitor();
    private HandlerThread mHandlerThread = new HandlerThread("log");
    private Handler mHandler;
    private LogMonitor() {
        mHandlerThread.start();
        mHandler = new Handler(mHandlerThread.getLooper());
    }
    private static Runnable mRunnable = 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 void startMonitor() {
        mHandler.postDelayed(mRunnable, TIME_BLOCK);
    }
    public boolean isMonitor() {
        return mHandler.hasCallbacks(mRunnable);
    }
    public void removeMonitor() {
        mHandler.removeCallbacks(mRunnable);
    }
}

我们假设阀值是1000ms，也就是说超过1000ms的都算卡顿。
当“>>>>> Dispatching to”打印了，我们就发送一个延迟1秒钟的任务，这个任务会打印出造成卡顿的UI线程里的堆栈信息。
如果在1秒钟之内我们检测到了“<<<<< Finished to”打印，就会移除这个延迟1秒的任务。
如果1秒内没有检测到“<<<<< Finished to”打印，

BlockCanary就是基于这个原理实现的。

利用Choreographer

Android性能优化第（十 一）篇---卡顿分析，正确评测流畅度

Choreographer就是一个消息处理器，根据vsync 信号 来计算frame，而计算frame的方式就是处理三种回调，包括事件回调、动画回调、绘制回调。这三种事件在消息输入、加入动画、准备绘图layout 等动作时均会发给Choreographer。

有的时候会看到这样的log，系统帮助我们打印出了跳帧数：

02-07 19:47:04.333 17601-17604/zhangwan.wj.com.choreographertest D/dalvikvm: GC_CONCURRENT freed 143K, 3% free 9105K/9384K, paused 2ms+0ms, total 6ms
02-07 19:47:04.337 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 60 frames!  The application may be doing too much work on its main thread.
02-07 19:47:11.685 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 85 frames!  The application may be doing too much work on its main thread.
02-07 19:47:12.545 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 37 frames!  The application may be doing too much work on its main thread.
02-07 19:47:14.893 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 37 frames!  The application may be doing too much work on its main thread.
02-07 19:47:23.049 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 36 frames!  The application may be doing too much work on its main thread.
02-07 19:47:23.929 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 37 frames!  The application may be doing too much work on its main thread.
02-07 19:47:24.961 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 61 frames!  The application may be doing too much work on its main thread.
02-07 19:47:25.817 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 36 frames!  The application may be doing too much work on its main thread.
02-07 19:47:26.433 17601-17601/zhangwan.wj.com.choreographertest I/Choreographer: Skipped 36 frames!  The application may be doing too much work on its main thread.

这个log就出自于Choreographer中

public final class Choreographer {
    void doFrame(long frameTimeNanos, int frame) {
        final long startNanos;
        synchronized (mLock) {
            if (!mFrameScheduled) {
                return; // no work to do
            }
            //当前时间
            startNanos = System.nanoTime();
            //抖动间隔
            final long jitterNanos = startNanos - frameTimeNanos;
            //抖动间隔大于屏幕刷新时间间隔（16ms）
            if (jitterNanos >= mFrameIntervalNanos) {
                final long skippedFrames = jitterNanos / mFrameIntervalNanos;
                //跳过了几帧！，也许当前应用在主线程做了太多的事情。
                if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) {
                    Log.i(TAG, "Skipped " + skippedFrames + " frames!  "
                            + "The application may be doing too much work on its main thread.");
                }
                //最后一次的屏幕刷是lastFrameOffset之前开始的
                final long lastFrameOffset = jitterNanos % mFrameIntervalNanos;
                if (DEBUG) {
                    Log.d(TAG, "Missed vsync by " + (jitterNanos * 0.000001f) + " ms "
                            + "which is more than the frame interval of "
                            + (mFrameIntervalNanos * 0.000001f) + " ms!  "
                            + "Skipping " + skippedFrames + " frames and setting frame "
                            + "time to " + (lastFrameOffset * 0.000001f) + " ms in the past.");
                }
                //最后一帧的刷新开始时间
                frameTimeNanos = startNanos - lastFrameOffset;
            }
            //由于跳帧可能造成了当前展现的是之前的帧，这样需要等待下一个vsync信号
            if (frameTimeNanos < mLastFrameTimeNanos) {
                if (DEBUG) {
                    Log.d(TAG, "Frame time appears to be going backwards.  May be due to a "
                            + "previously skipped frame.  Waiting for next vsync.");
                }
                scheduleVsyncLocked();
                return;
            }
            //当前画面刷新的状态置false
            mFrameScheduled = false;
            //更新最后一帧的刷新时间
            mLastFrameTimeNanos = frameTimeNanos;
        }
        //按照优先级策略进行画面刷新时间处理
        doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos);
        doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos);
        doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos);
        if (DEBUG) {
            final long endNanos = System.nanoTime();
            Log.d(TAG, "Frame " + frame + ": Finished, took "
                    + (endNanos - startNanos) * 0.000001f + " ms, latency "
                    + (startNanos - frameTimeNanos) * 0.000001f + " ms.");
        }
    }
}

当跳帧数大于设置的SKIPPED_FRAME_WARNING_LIMIT 值时会在当前进程输出这个log。由于 SKIPPED_FRAME_WARNING_LIMIT 的值默认为 30，所以上面的log并不是经常看到。

方法一

如果我们用反射的方法把SKIPPED_FRAME_WARNING_LIMIT的值设置成1，这样可以保证只要有丢帧，就会有上面的log输出来。

static {
    try {
        Field field = Choreographer.class.getDeclaredField("SKIPPED_FRAME_WARNING_LIMIT");
        field.setAccessible(true);
        field.set(Choreographer.class, 1);
    } catch (Throwable e) {
        e.printStackTrace();
    }
}

只要捕获这个log提取出skippedFrames 就可以知道界面是否卡顿。

方法二

上面的方法只能让我们知道丢帧了，却无法知道更详细定位问题的信息了。
在Choreographer中有个回调接口，FrameCallback。

public interface FrameCallback {  
  //当新的一帧被绘制的时候被调用。  
   public void doFrame(long frameTimeNanos);
}

public class BlockDetectByChoreographer {
    public static void start() {
        Choreographer.getInstance()
            .postFrameCallback(new Choreographer.FrameCallback() {
                @Override
                public void doFrame(long l) {
                    if (LogMonitor.getInstance().isMonitor()) {
                        LogMonitor.getInstance().removeMonitor();                    
                    } 
                    LogMonitor.getInstance().startMonitor();
                    Choreographer.getInstance().postFrameCallback(this);
                }
        });
    }
}

第一次的时候开始检测，如果大于阈值则输出相关堆栈信息，否则则移除。