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

转载请注明文章出处LooperJing！

一、FPS评测应用流畅度不准确

说到应用的流畅度，都会想到FPS，系统获取FPS的原理是：手机屏幕显示的内容是通过Android系统的SurfaceFLinger类，把当前系统里所有进程需要显示的信息合成一帧，然后提交到屏幕上进行显示，FPS就是1秒内SurfaceFLinger提交到屏幕的帧数。用FPS来评测一个应用是否真的卡顿存在两个问题。

有的时候FPS很低，APP看起来却很流畅；
APP停止操作之后，FPS还是在一直变化，这种情况是否会影响到FPS的准确度？
有的时候FPS很低，APP看起来却很流畅，是因为当前界面在1秒内只需要10帧的显示需求，当然不会卡顿，此时FPS只要高于10就可以了，如果屏幕根本没有绘制需求，那FPS的值就是0。

Android性能优化第（四）篇---Android渲染机制说过，Android系统每隔16ms发出VSYNC信号，触发对UI的渲染，16ms没完成绘制就会卡顿。VSync机制就像是一台转速固定的发动机(60转/s)。每一转会带动着去做一些UI相关的事情，但不是每一转都会有工作去做(就像有时在空挡，有时在D档)。有时候因为各种阻力某一圈工作量比较重超过了16.6ms，那么这台发动机这秒内就不是60转了，当然也有可能被其他因素影响，比如给油不足(主线程里干的活太多)等等，就会出现转速降低的状况。我们把这个转速叫做流畅度。当流畅度越小的时候说明当前程序越卡顿。

二、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中（英[ˌkɒrɪ'ɒɡrəfə(r)] 美[ˌkɒrɪ'ɒɡrəfə(r)]）。

void doFrame(long frameTimeNanos, int frame) {
        final long startNanos;
        synchronized (mLock) {
            if (!mFrameScheduled) {
                return; // no work to do
            }

            if (DEBUG_JANK && mDebugPrintNextFrameTimeDelta) {
                mDebugPrintNextFrameTimeDelta = false;
                Log.d(TAG, "Frame time delta: "
                        + ((frameTimeNanos - mLastFrameTimeNanos) * 0.000001f) + " ms");
            }

            long intendedFrameTimeNanos = frameTimeNanos;
            startNanos = System.nanoTime();
            final long jitterNanos = startNanos - frameTimeNanos;
            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.");
                }
                final long lastFrameOffset = jitterNanos % mFrameIntervalNanos;
                if (DEBUG_JANK) {
                    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;
            }
        }

    }

其中SKIPPED_FRAME_WARNING_LIMIT是Choreographer的成员变量。

  // Set a limit to warn about skipped frames.
  // Skipped frames imply jank.
  private static final int SKIPPED_FRAME_WARNING_LIMIT =SystemProperties.getInt( "debug.choreographer.skipwarning", 30);

也就是当跳帧数大于设置的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();
        }
    }

注意，这个方案是 API 16 以上才支持。Choreographer就是一个消息处理器，根据vsync 信号来计算frame，而计算frame的方式就是处理三种回调，包括事件回调、动画回调、绘制回调。这三种事件在消息输入、加入动画、准备绘图layout 等动作时均会发给Choreographer。一句话，我们只要捕获这个log提取出skippedFrames 就可以知道界面是否卡顿。

三、如何检测

采用上面的方式就可以在App内部观测当前App的流畅度了。并且在丢帧的地方打印，就可以知道丢帧的大概原因，大概位置，定位代码问题。

在Choreographer中有个回调接口，FrameCallback。

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

根据上面的代码，重写doFrame方法，所以照葫芦画瓢，自定义FrameCallback。我们可以在每一帧被渲染的时候记录下它开始渲染的时间，这样在下一帧被处理时，判断上一帧在渲染过程中是否出现掉帧。

public class SMFrameCallback implements Choreographer.FrameCallback {

    public static  SMFrameCallback sInstance;

    private String TAG="SMFrameCallback";

    public static final float deviceRefreshRateMs=16.6f;

    public static  long lastFrameTimeNanos=0;//纳秒为单位

    public static  long currentFrameTimeNanos=0;

    public void start() {
        Choreographer.getInstance().postFrameCallback(SMFrameCallback.getInstance());
    }

    public static SMFrameCallback getInstance() {
        if (sInstance == null) {
            sInstance = new SMFrameCallback();
        }
        return sInstance;
    }

    @Override
    public void doFrame(long frameTimeNanos) {
        if(lastFrameTimeNanos==0){
            lastFrameTimeNanos=frameTimeNanos;
            Choreographer.getInstance().postFrameCallback(this);
            return;
        }
        currentFrameTimeNanos=frameTimeNanos;
        float value=(currentFrameTimeNanos-lastFrameTimeNanos)/1000000.0f;

        final int skipFrameCount = skipFrameCount(lastFrameTimeNanos, currentFrameTimeNanos, deviceRefreshRateMs);
        Log.e(TAG,"两次绘制时间间隔value="+value+"  frameTimeNanos="+frameTimeNanos+"  currentFrameTimeNanos="+currentFrameTimeNanos+"  skipFrameCount="+skipFrameCount+"");
        lastFrameTimeNanos=currentFrameTimeNanos;
        Choreographer.getInstance().postFrameCallback(this);
    }


    /**
     *
     *计算跳过多少帧
     * @param start
     * @param end
     * @param devicefreshRate
     * @return
     */
    private  int skipFrameCount(long start,long end,float devicefreshRate){
        int count =0;
        long diffNs=end-start;
        long diffMs = Math.round(diffNs / 1000000.0f);
        long dev=Math.round(devicefreshRate);
        if(diffMs>dev){
            long skipCount=diffMs/dev;
            count=(int)skipCount;
        }
        return  count;
    }
}

在需要检测的Activity中调用 SMFrameCallback.getInstance().start()即可。一般优化一下，可以在BaseActivity去调用或者Activitylifecyclecallbacks中去调用.
正常情况下输出的日志是：

02-07 20:18:52.605 6683-6683/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=6996166386820  currentFrameTimeNanos=6996166386820  skipFrameCount=0
02-07 20:18:52.621 6683-6683/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=6996183053486  currentFrameTimeNanos=6996183053486  skipFrameCount=0
02-07 20:18:52.637 6683-6683/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=6996199720152  currentFrameTimeNanos=6996199720152  skipFrameCount=0
02-07 20:18:52.657 6683-6683/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=6996216386818  currentFrameTimeNanos=6996216386818  skipFrameCount=0
02-07 20:18:52.673 6683-6683/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=6996233053484  currentFrameTimeNanos=6996233053484  skipFrameCount=0
02-07 20:18:52.689 6683-6683/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=6996249720150  currentFrameTimeNanos=6996249720150  skipFrameCount=0

有跳帧的时候输出的日志是

02-07 20:21:53.909 9530-9530/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=7177466379568  currentFrameTimeNanos=7177466379568  skipFrameCount=0
02-07 20:21:53.925 9530-9530/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=7177483046234  currentFrameTimeNanos=7177483046234  skipFrameCount=0
02-07 20:21:54.133 9530-9530/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=200.0  frameTimeNanos=7177683046226  currentFrameTimeNanos=7177683046226  skipFrameCount=11
02-07 20:21:54.745 9530-9530/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=616.6666  frameTimeNanos=7178299712868  currentFrameTimeNanos=7178299712868  skipFrameCount=36
02-07 20:21:54.757 9530-9530/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=7178316379534  currentFrameTimeNanos=7178316379534  skipFrameCount=0
02-07 20:21:54.773 9530-9530/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=7178333046200  currentFrameTimeNanos=7178333046200  skipFrameCount=0
02-07 20:21:54.789 9530-9530/zhangwan.wj.com.choreographertest E/SMFrameCallback: 两次绘制时间间隔value=16.666666  frameTimeNanos=7178349712866  currentFrameTimeNanos=7178349712866  skipFrameCount=0

看到两次绘制的时间间隔相差616.6666毫秒，跳过了36帧，这个卡顿用户是能够明显感知的。

Please accept mybest wishes for your happiness and success ！

最后编辑于：2017.12.05 13:43:46

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

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

一、FPS评测应用流畅度不准确

二、Choreographer帧率检测原理

三、如何检测

推荐阅读更多精彩内容

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