Janky frames 是如何计算出来的

本文出自:【张旭童的简书】 (http://www.jianshu.com/users/8e91ff99b072/latest_articles)
想来gayhub和我gaygayup:【mcxtzhang的Github主页】https://github.com/mcxtzhang

背景

最近在做一些性能监控的工作,其中线下监控fps这一项,经过调研,最终采用dumpsys gfxinfo的方式。

在6.0+的手机中执行如下命令,

adb shell dumpsys gfxinfo 包名 

可以得到一些log:

Applications Graphics Acceleration Info:
Uptime: 3820706382 Realtime: 3903615964

** Graphics info for pid 427 [包名] **

Stats since: 3820661771494092ns
Total frames rendered: 201
//重点关注对象
Janky frames: 76 (37.81%)
50th percentile: 6ms
90th percentile: 19ms
95th percentile: 61ms
99th percentile: 300ms
Number Missed Vsync: 14
Number High input latency: 0
Number Slow UI thread: 17
Number Slow bitmap uploads: 5
Number Slow issue draw commands: 60
........
//重点关注对象
    ActivityName/android.view.ViewRootImpl@d4c0f16 (visibility=0)
//每个Activity的每一帧的原始数据,包含每个阶段的时间戳
---PROFILEDATA---
Flags,IntendedVsync,Vsync,OldestInputEvent,NewestInputEvent,HandleInputStart,AnimationStart,PerformTraversalsStart,DrawStart,SyncQueued,SyncStart,IssueDrawCommandsStart,SwapBuffers,FrameCompleted,
0,3820697872348436,3820697872348436,9223372036854775807,0,3820697872662836,3820697872693045,3820697872814399,3820697872932628,3820697873194607,3820697873228461,3820697873328982,3820697873869086,3820697876514920,
0,3820697889204506,3820697889204506,9223372036854775807,0,3820697889517524,3820697889547211,3820697889672211,3820697889801899,3820697890120649,3820697890156586,3820697890267524,3820697890787836,3820697892957628,
0,3820697906060465,3820697906060465,9223372036854775807,0,3820697906622211,3820697906650857,3820697906761795,3820697906888357,3820697907180024,3820697907215961,3820697907325857,3820697907809190,3820697909209190,
0,3820697922916378,3820697922916378,9223372036854775807,0,3820697923237315,3820697923265440,3820697923397732,3820697923533149,3820697923806586,3820697923837315,3820697923936795,3820697924388878,3820697927055024,
0,3820697939772285,3820697939772285,9223372036854775807,0,3820697940389920,3820697940418565,3820697940532628,3820697940652420,3820697940915961,3820697940948774,3820697941046690,3820697941496170,3820697943844086,
0,3820697956628358,3820697956628358,9223372036854775807,0,3820697956922732,3820697956952940,3820697957073774,3820697957197732,3820697957457107,3820697957490961,3820697957583149,3820697958036795,3820697959429503,
............

其中有一项名为:Janky frames的数据引起了我们的兴趣。

Janky frames该如何理解呢?参考官方文档1 的说明,似乎就是掉帧的数量。

可如果按照掉帧的数量来理解,这份log显示的掉帧率高达37.81%,一个app如果近40%的帧都被skip,用户不可能毫无感知。

但在我们测试时,没有感觉到明显的卡顿。(且根据原始数据,用另外一套计算方式,算出的帧率fps值也与掉帧率的百分比矛盾)

但这Janky frames毕竟是官方adb命令给出的值,具有一定的权威性,于是我们开始自我怀疑,

  • 是我们的眼睛没有看出卡顿?
  • 是我们计算帧率fps的方式出现了问题?
  • ...

由于官方在log中并未给出实际fps的值,于是为了探究问题出在哪里,也为了参考官方的计算标准,即如何判定一帧出现了janky,我便把黑手伸向了无辜的源码,毕竟源码之下,了无秘密。

遂,现在的目标是:

  • 找到adb shell dumpsys gfxinfo的源码
  • 找到源码里关于Janky frame的计算方法

找到gfxinfo源码

经过搜索,在Android dumpsys工具分析文中中得知,当我们执行adb shell dumpsys后,根据后面不同的参数,例如meminfogfxinfo,实际上是通过ServiceManager->checkService(services[i])方法,从ServiceManager中取出对应服务的Binder对象,并最终通过service->dump(STDOUT_FILENO, args)调用对应服务Binder对象的dump()方法执行具体命令。

这些系统服务的注册,是在AMS(ActivityManagerService.java)里的setSystemProcess()里完成的,

    public void setSystemProcess() {
        try {
            //在ServiceManager中注册服务
            //"activity";
            ServiceManager.addService(Context.ACTIVITY_SERVICE, this, true);
            ServiceManager.addService(ProcessStats.SERVICE_NAME, mProcessStats);
            ServiceManager.addService("meminfo", new MemBinder(this));
            ServiceManager.addService("gfxinfo", new GraphicsBinder(this));
            ServiceManager.addService("dbinfo", new DbBinder(this));
            ...
        } catch (PackageManager.NameNotFoundException e) {
            throw new RuntimeException(
                    "Unable to find android system package", e);
        }
    }

可以看到,我们熟悉的 "activity"、"meminfo"以及本文的主角"gfxinfo"都在其中注册。

java层源码

顺藤摸瓜,我们看看GraphicsBinder这个类以及它的dump()方法:

    static class GraphicsBinder extends Binder {
        ActivityManagerService mActivityManagerService;
        GraphicsBinder(ActivityManagerService activityManagerService) {
            mActivityManagerService = activityManagerService;
        }

        @Override
        protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
            if (!DumpUtils.checkDumpAndUsageStatsPermission(mActivityManagerService.mContext,
                    "gfxinfo", pw)) return;
            //调用ams的dumpGraphicsHardwareUsage()方法
            mActivityManagerService.dumpGraphicsHardwareUsage(fd, pw, args);
        }
    }

dump()方法很简单,仅仅验证权限后调用ams的dumpGraphicsHardwareUsage()方法,继续跟进:

    final void dumpGraphicsHardwareUsage(FileDescriptor fd,
            PrintWriter pw, String[] args) {
        //根据args参数,参数里包含进程名 或者进程id,得到指定进程。 如果args参数里不包含进程名,则得到所有进程
        ArrayList<ProcessRecord> procs = collectProcesses(pw, 0, false, args);
        //没有符合条件的进程时的输出
        if (procs == null) {
            pw.println("No process found for: " + args[0]);
            return;
        }
        //执行命令时的时间
        long uptime = SystemClock.uptimeMillis();
        long realtime = SystemClock.elapsedRealtime();
        pw.println("Applications Graphics Acceleration Info:");
        pw.println("Uptime: " + uptime + " Realtime: " + realtime);
        //循环进程列表
        for (int i = procs.size() - 1 ; i >= 0 ; i--) {
            ProcessRecord r = procs.get(i);
            if (r.thread != null) {
                pw.println("\n** Graphics info for pid " + r.pid + " [" + r.processName + "] **");
                pw.flush();
                try {
                    TransferPipe tp = new TransferPipe();
                    try {
                        //重点,执行每个进程的ApplicationThread的dumpGfxInfo()方法
                        r.thread.dumpGfxInfo(tp.getWriteFd(), args);
                        tp.go(fd);
                    } finally {
                        tp.kill();
                    }
                } catch (IOException e) {
                    pw.println("Failure while dumping the app: " + r);
                    pw.flush();
                } catch (RemoteException e) {
                    pw.println("Got a RemoteException while dumping the app " + r);
                    pw.flush();
                }
            }
        }
    }

可以看到,我们关心的核心输出(Janky frames部分)以进程区分,并在ApplicationThread.dumpGfxInfo()方法中输出。
ApplicationThreadActivityThread.java中,继续跟进:

        @Override
        public void dumpGfxInfo(ParcelFileDescriptor pfd, String[] args) {
            //jni  ,janky frames输出就在其中
            dumpGraphicsInfo(pfd.getFileDescriptor());
            // java方法,输出 Profile data in ms: 后面的部分
            WindowManagerGlobal.getInstance().dumpGfxInfo(pfd.getFileDescriptor(), args);
            IoUtils.closeQuietly(pfd);
        }
        
    // ------------------ Regular JNI ------------------------
    private native void dumpGraphicsInfo(FileDescriptor fd);

查看WindowManagerGlobal.dumpGfxInfo()方法:

    public void dumpGfxInfo(FileDescriptor fd, String[] args) {
        FileOutputStream fout = new FileOutputStream(fd);
        PrintWriter pw = new FastPrintWriter(fout);
        try {
            synchronized (mLock) {
                final int count = mViews.size();

                pw.println("Profile data in ms:");

                for (int i = 0; i < count; i++) {
                    ViewRootImpl root = mRoots.get(i);
                    String name = getWindowName(root);
                    pw.printf("\n\t%s (visibility=%d)", name, root.getHostVisibility());

                    ThreadedRenderer renderer =
                            root.getView().mAttachInfo.mThreadedRenderer;
                    if (renderer != null) {
                        renderer.dumpGfxInfo(pw, fd, args);
                    }
                }

                pw.println("\nView hierarchy:\n");

                int viewsCount = 0;
                int displayListsSize = 0;
                int[] info = new int[2];

                for (int i = 0; i < count; i++) {
                    ViewRootImpl root = mRoots.get(i);
                    root.dumpGfxInfo(info);

                    String name = getWindowName(root);
                    pw.printf("  %s\n  %d views, %.2f kB of display lists",
                            name, info[0], info[1] / 1024.0f);
                    pw.printf("\n\n");

                    viewsCount += info[0];
                    displayListsSize += info[1];
                }

                pw.printf("\nTotal ViewRootImpl: %d\n", count);
                pw.printf("Total Views:        %d\n", viewsCount);
                pw.printf("Total DisplayList:  %.2f kB\n\n", displayListsSize / 1024.0f);
            }
        } finally {
            pw.flush();
        }
    }

可知,其中输出的是"Profile data in ms:"后面部分的log,所以,我们关心的部分就在JNI里了。

C层源码

看到JNI我是抗拒的,本科时学的那些C、C++早已记不太清,一想到要看C层的源码,就觉得头大。原本想溜,但是转念一想,我只需要关注它对于"Janky frame"的计算方式,无外乎那些数学运算。只要重点关注函数调用处,搜索关键字,说不定可以找到答案。于是,继续跟进。

由于涉及C层的源码在AndroidStudio中查看不了,下面的分析使用查看framework源码网站进行。我全局搜索了关键字dumpGraphicsInfo,找到函数定义处:

[图片上传失败...(image-c02780-1517466253400)]
进入android_view_DisplayListCanvas.cpp查看():

[图片上传失败...(image-1ac76-1517466253400)]
搜索dumpGraphicsMemory

[图片上传失败...(image-3561dc-1517466253400)]
进入RenderProxy.cpp后,
[图片上传失败...(image-9d5c50-1517466253400)]
由于对c++不是很懂,这一块的代码不是很懂,但是从全局搜索只有三处调用,而且从jankTracker的字样上可以看出(这一步有一些连蒙带猜),这里应该是正确的方向,继续跟进:
JankTracker.h文件中:
[图片上传失败...(image-5f14bc-1517466253400)]
于是我们进入JankTracker.cpp中查看dumpData()方法的具体实现:

[图片上传失败...(image-93dee3-1517466253400)]
看到这里我是既兴奋又痛苦。兴奋的是我找到了最终log对应的输出之处,痛苦的是,这里仅仅是将ProfileData->jankFrameCount字段输出,看来革命之路还长,还要找到赋值的地方。

jankFrameCount 赋值之处

全局搜索->jankFrameCount调用之处,:

[图片上传失败...(image-d7ee56-1517466253400)]
发现仅在JankTracker.cpp中使用到,在addFrame()函数中会递增:

[图片上传失败...(image-1577db-1517466253400)]
可以看出,如果一帧的时间如果小于mFrameInterval,则return,那么jankFrameCount不会递增即 每一帧的时间大于等于mFrameInterval,就是Janky frame

看来我们离答案已经很接近了,那么mFrameInterval是多少呢?
搜索mFrameInterval是在setFrameInterval()中赋值的:

[图片上传失败...(image-fc007e-1517466253401)]
setFrameInterval()在JankTracker初始化时调用:
[图片上传失败...(image-ab8fb4-1517466253401)]
根据官方文档1以及官方视频why60fps,刷新频率fps是60。所以可得frameIntervalNanos约等于16.67ms.

结论

至此我们可以得出结论,官方衡量Janky frames的标准:一帧的时间超过16.67ms。

想法

注:以下想法目前还没有源码撑腰,并不一定正确,如有错误以及知情大佬,烦请指正,谢谢

有上述结论可以看出 Janky frames确实代表了这一帧的完整绘制时间太久,出现了问题,

那么回到我们文首的问题,某些页面的Janky frames高达近37.81%,为何我们没有感到卡顿?以及为何算出来的fps并没有低于37.2= 60*(1-0.38)?

关于这个问题,经过讨论,有以下暂时的想法:

  • Android 5.0以后,加入了RenderThread,用于分担UI Thread的部分绘制工作。即一帧的完整绘制时间 是由UIThread和RenderThread上的耗时相加得到的。
  • UI Thread在处理完input animation以及部分draw的工作后,将剩余绘制工作交于RenderThread,UI Thread此时可以继续处理下一个VSYNC到来时的工作。
  • RenderThread 以及三缓冲机制

[图片上传失败...(image-2f72c8-1517466253401)]

可以看出B先导致了一次视觉上的jank,C理论上也是jank的(相加时间超过了16.67ms),但是由于此时屏幕上显示的是B,C虽然delay了一帧,但是由于C之前的B已经delay了一帧,所以C看起来仍然是紧跟着B显示在屏幕上,而且A顺利的在16.67ms完成了任务,紧跟着C继续绘制了,则用户在视觉上只少看到了一帧。

所以我们的想法是:

在Android5.0+,Janky frames 并不代表用户视觉上的,显示在屏幕上的丢帧率,但是它可以代表有问题的帧率

即这些帧有问题,但最终由于三缓冲机制的背锅,部分帧没有最终影响到用户,

所以实际上的fps值会高于 60(1-掉帧率).*

这个问题后面也会继续跟进,做到理据服。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 148,827评论 1 317
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 63,511评论 1 266
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 99,318评论 0 218
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 42,108评论 0 189
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 50,112评论 1 266
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 39,387评论 1 185
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 30,905评论 2 283
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 29,657评论 0 177
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 33,144评论 0 223
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 29,744评论 2 225
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,100评论 1 236
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 27,565评论 2 222
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,041评论 3 216
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 25,769评论 0 9
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,301评论 0 178
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 34,173评论 2 239
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 34,313评论 2 242

推荐阅读更多精彩内容

  • Android 自定义View的各种姿势1 Activity的显示之ViewRootImpl详解 Activity...
    passiontim阅读 170,450评论 25 707
  • 发现 关注 消息 iOS 第三方库、插件、知名博客总结 作者大灰狼的小绵羊哥哥关注 2017.06.26 09:4...
    肇东周阅读 11,528评论 4 58
  • 深阅读,有以下几点要记住: 1、边问边读。问自己,读书想要解决什么问题?书能给自己提供什么?以提升对书的关注和兴趣...
    An_An阅读 663评论 0 1
  • 初中的时候,我喜欢一个叫翼的男生,他高大帅气阳光,满足了我对白马王子所有的幻想。 他周围总是环绕着女孩子,所以我只...
    文雅的风阅读 252评论 0 1
  • 接到面试通知辗转反侧,一直在默念明天改如何介绍自己的项目经验等。早早的起床,洗漱,把自己的总结的问题自问自答了一些...
    刘恒_893f阅读 153评论 0 0