Android性能问题分析之bugreport

Android手机性能问题一直是用户关注的重点，分析性能问题则成为工程师日常工作的一部分。根据问题的类型通常有适合的工具可供使用，比如systrace ,traceview,simpleperf等可视化工具，然而这些工具对用户而言操作相对复杂，比较鸡肋但容易生成的bugreport就成为了解决用户反馈问题时仅有的“黑匣子”（通常还有一段文字描述或者现场视频）。这篇文章就来介绍如何用bugreport分析性能问题。

初学者分析bugreport时往往不得要领，原因有三个。第一，bugreport内容非常庞大繁杂，比如我现在手上这份有63M，73万行；第二，要修车必须得先懂车，要解决bug必须先懂系统；第三，性能问题的原因很多，常见的比如等锁，死锁，cpu抢占，cpu频率（boost或限频），拔核，编译问题导致的代码执行效率低，IO抢占，物理内存不足，虚拟空间耗尽，内存碎片，binder调用耗时，优先级反转，系统中各种cache异常，主线程忙，vsync异常，input事件异常，窗口失去焦点，绘图buffer异常，GPU合成慢，kernel配置选项异常等等等等等。。。。。。有些原因隐藏的比较深且关系链长，进一步加大了分析的难度。

尽管如此，bugreport的分析还是有一些通用的套路。既然阁下骨骼惊奇，想必也是练武奇才，这份秘籍送给你，还望好好练习，他日若遂凌云志，江湖血雨腥风时。

1) 明确目标

一个即将被围殴的剑客，最重要的是快速对敌人一剑封喉，而不仅仅是研究对方几个人啥阵型，毕竟还要留点时间耍酷。一个快要脱发的码农，拿到一份bugreport最重要是快速解决问题，而不仅仅是找出根因，毕竟还要留时间解下一个bug。

一剑封喉和研究阵型是目标与手段的关系，找出原因和解决问题同样如此。常犯的错误是把手段当成了目标多走了弯路。这是因为，思路不同：查清一个问题的原因和判断这个问题属于哪个领域是两个不同的问题，自然也有着不同的解法；代价不同：让我发现万有引力定律需要向天再借5000年，而请牛顿帮忙的话这事最多不超过23年。手机系统是由众多的模块组成的，不同的模块由不同的工程师负责，而专业的事要找专业的人，这才是效率最大化的方式。区分目标和手段听起来简单，但工作中我的确见过很多人犯这个错误，尤其是陷入到一个复杂问题的时候。当然，时间允许的情况下，一定要刨根问底，毕竟剑客的耍酷是建立在耍剑基础上的。

2) 定位问题。

用户反馈时都会有对应的问题描述，觉悟高的用户还会传卡顿现场的视频。一定要多读几遍描述，仔细看几遍视频，里面包含的信息量其实是很多的，却很容易被忽视，这些蛛丝马迹对解决问题至关重要，我们把它记为信息集I。在整个分析过程中I中的信息是不断增加的，并且每一条都很重要。

private static final int SKIPPED_FRAME_WARNING_LIMIT = SystemProperties.getInt(
            "debug.choreographer.skipwarning", 30);

if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) {
    Log.i(TAG, "Skipped " + skippedFrames + " frames!  "
        + "The application may be doing too much work on its main thread.");
}

通过以上代码可以看到，当掉帧数超过SKIPPED_FRAME_WARNING_LIMIT（默认30帧）时会打印Skipped....的log。我们就以它作为切入点进行问题定位。bugreport中搜索这条log，得到两种结果：

a) 搜到：通常搜索到不止1条，需要根据信息集I中的信息进行过滤，比如根据发生的时间，根据问题app，卡顿的严重程度或者问题前后的行为等。如果无法过滤出特定消息，返回上一步，完善信息集I或者沟通用户补充信息。

举个例子，通过微博17:52卡顿的描述可以定位下面的log:

02-17 17:52:30.443 10208 28958 28958 I Choreographer: Skipped 1150 frames!  
The application may be doing too much work on its main thread.

----- pid 28958 at 2020-02-17 17:53:56 -----
Cmd line: com.sina.weibo

log解释：微博在02-17 17:52:30.443掉了1150帧，也就是19166ms（正常情况1s 60帧，动态调频除外）。到这里信息集I中的信息增加了，这里面的信息就是刷子，时刻知道自己有几把刷子对解决问题是极其重要的。

b) 没搜到：没有信息本身就是信息。事实上没搜到比搜到了包含的信息更多。这里至少包含了以下几种可能。1. 掉帧但是主线程卡死，没机会打log 2. 没掉帧 3. 掉帧数没达到阈值 4. 没接收vsync。没接收vsync包括 4.1 主线程卡死，4.2 没有请求vsync。以上信息加入信息集I中（其中有些是互斥关系，当一个确定后，与之互斥的就要删掉）。这种情况需要借助用户在卡顿前后的行为进行定位，通常会锁定到一个很小的时间段内。

3) 分析原因

通过上面的步骤，我们明确了目标，定位到了一条log或者锁定了一个时间段，手里有了几把刷子。这就是起点，接下来条条大路通罗马，我分享我认为重要的几点经验。

问题分类。对问题进行分类一方面便于归纳总结，另一方面便于借鉴同类问题的解法。比如，卡死问题。常见原因无外乎主线程忙，窗口失去焦点，SurfaceFlinger合成出问题导致界面没有绘制等。这种常见原因不多的问题适合逐一排除，crash、黑屏白屏问题也属于此类。

对于其他很多问题，可能原因就太多了，文章开头列出的还只是我遇到的一部分。这种问题显然不能逐一排查。怎么办呢，毕竟此时手上没几把刷子，但有时少即是多，这使我们可以充分利用仅有的信息。

以上面微博卡顿为例，我们只知道微博在02-17 17:52:30.443的时候卡了19166ms。信息很少，但可以肯定log是在卡顿结束后打出的（没结束的话就不知道总共卡了多久），而且问题的原因肯定发生在02-17 17:52:30.443之前，大概率发生在离两个端点（02-17 17:52:30.443和02-17 17:52:30.443-19166ms）不远的地方。接下来我们同时扫描一下相应时间段的main log和event log，结果在event log中有如下发现:

02-17 17:52:30.433 10208 28958 28958 I binder_sample: [android.app.IActivityTaskManager,1,19175,
com.sina.weibo,100]

可见微博通过binder call IPC调用了IActivityTaskManager的接口1，并且耗时19175ms，(19175ms > 19166ms, 17:52:30.433在17:52:30.443前面，看似矛盾，但19166ms是跳过的帧，总时间还应加上正常帧的16.6ms)。这是一个跨进程的调用，对端是system_server进程，到这里，我们的信息集I中的元素进一步增加了，并且可以知道卡顿的原因转移到了system_server进程。就这样，一直分析下去。简单贴一下system_server端的log，可见是在等锁，持锁方在执行dumpActivity:

02-17 17:52:30.377  1000  1639  8339 I dvm_lock_sample: [system_server,1,Binder:1639_1B,19119,
WindowProcessUtils.java,400,java.lang.String com.android.server.wm.WindowProcessUtils
.getCallerPackageName(...),
ActivityTaskManagerService.java,7253,boolean com.android.server.wm
.ActivityTaskManagerService$LocalService.dumpActivity(...),100]

全局观察，用点想象力。通过逻辑推理从A到B可能需要n步，但通过想象只需要一步。这属于只可意会不可言传的骚操作领域，但还是有一点点技巧的，技巧就是从细节中跳出来，全局考虑，找规律。举个例子，对于图形化分析工具，比如systrace，如果有两个操作的图像能较好的拼在一起（板块构造学说是不是这么来的？），或者一批操作的图像的一端都严格对齐等等，这些反常的信号都在暗示它们之间可能存在很强的联系或者它们受一个共同因素的影响。再比如bugreport中，如果一段时间内所有的app都卡，放心绝对不是有什么东方的神秘力量，而是系统在抽风，比如内存碎片化比较严重或者CPU降频等影响全局的因素。

举个例子：打开相机卡

定位Log:

07-27 18:37:56.222 1000 1586 1642 I am_activity_launch_time:[0,225986022,
com.android.camera/.Camera,19823]

的确是卡的不轻，19823ms相当严重了已经。根据上面说的方法，继续找到下面的log：

07-27 18:37:55.799 10091  2248  2248 I binder_sample: [android.app.IActivityTaskManager,1,19439,
com.miui.home,100]
07-27 18:37:55.801 10091  2248  2248 I am_on_paused_called: [0,com.miui.home.launcher.Launcher,
performPause]

因为启动相机的过程首先要pause桌面，然而这里pause桌面花了19439ms。常规操作应该向前找为什么这里binder调用花了这么久，但不好意思，不是找不到，前面是真的没有直接相关的有效log了。需要发挥点想象力了，扫了一眼发现下面的log

07-27 18:37:55.802  1000  1586  2179 I dvm_lock_sample: [system_server,1,ClientModeImpl,18041,
..........................,int com.android.server.am.ActivityManagerService.broadcastIntent(),
-,1524,void com.android.server.am.ActivityManagerService$AppDeathRecipient.
binderDied(),100]
07-27 18:37:55.803  1000  1586  4970 I dvm_lock_sample: [system_server,1,Binder:1586_18,16790,
..........................int com.android.server.am.ActivityManagerService.broadcastIntent(),
-,1524,void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied(),100]
07-27 18:37:55.803  1000  1586  2174 I dvm_lock_sample: [system_server,0,NetworkStats,16783,
.........................,int com.android.server.am.ActivityManagerService.broadcastIntent(),
-,1524,void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied(),100]

这里的等锁单从时间上看就跟桌面pause扯不上关系，但是有一个binderDied，app进程被杀了？lowmemorykiller（LMK）杀的？看了一下果然这段时间有大量杀进程的日志，取其中一个如下：

07-27 18:37:55.975  I lowmemorykiller: Killing ':accountservice' (15215) (tgid 15215), adj 965,
07-27 18:37:55.975  I         : to free 121500kB on behalf of 'kswapd0' (90) because
07-27 18:37:55.975  I         : cache 1925820kB is below limit 347440kB for oom score 606
07-27 18:37:55.975  I         : Free memory is -28000kB above reserved.
07-27 18:37:55.975  I         : Free CMA is 17836kB
07-27 18:37:55.975  I         : Total reserve is 133660kB
07-27 18:37:55.975  I         : Total free pages is 150736kB
07-27 18:37:55.975  I         : Total file cache is 2844160kB
07-27 18:37:55.975  I         : GFP mask is 0x14000c0

信息量不小，解释一下，Total free pages is 150736kB，剩余内存仅有约150M。cache 1925820kB is below limit 347440kB，1925820kB < 347440kB，显然矛盾。for oom score 606与adj 965也不一致。理解这些矛盾需要对kernel LMK机制有所掌握，我直接给出答案。由于kswapd无法回收文件页，导致LMK机制无法发挥作用（因为LMK需要同时判断文件页和剩余内存小于阈值minfree才会起作用，minfree通常几百M，这里文件cache接近2G,显然太大），进而导致缓存进程无法被杀，内存得不到释放。内存得不到释放带来的后果就是内存压力逐渐变大，当内存压力超过一定的阈值后，kernel强制使能LMK，这时候log中就会出现上面的矛盾。（kernel这种双反馈思想还是值得学习的；另外，为什么LMK的判断条件里还要加一个文件页<minfree的判断？这是因为正常情况下文件页是容易被kswapd回收的，释放出来的内存可以供App使用，所以不需要杀掉后台缓存进程这种影响性能的方式）。到这里最大的疑问就是kernel为什么没有回收掉文件页，有一些可能的原因，不过不在本文讨论范围内了。

所以由于文件页回收不掉，加上空闲内存只有150M左右（这是一个极低的值，一般当空闲内存低到300M左右，手机就会出现明显卡顿），导致相机启动时间长的可能是非常大的。

检查确认。google原生log是比较有限的，为了更好的定位问题，各大手机厂商都有自己的log系统，但即使这样仍然有很多问题是无法100%确定原因的，就像上面的例子，我们也只能说大概率是内存原因。另外多数情况下信息集I中的信息是非常多的，每一条信息都可能会把我们引到不同的解决路径上，而这条路通向的是否是罗马也是值得商榷的。所以，比较好的习惯是得出结论后，回头看看它与我们信息集中的信息是否有冲突，一个正确的结论与条件应该是和谐的。

4)解决问题

通过前面的步骤，我们现在已经调查清楚了原因，这会引导我们解决现有的bug或者做出新的优化，也是工作的重点。这一部分需要注意的也挺多的，但不打算写了，因为对大多数人来说意义不大，再者我们的宗旨就是废话少说，尽管已经说了不少废话。

收工前总结一下，这篇文章说明了bugreport分析的必要性，描述了初学者分析困难的原因，其中重点提到了常见的导致性能问题的因素，接着主要分享了更好的分析bugreport的经验，包括明确目标来规划思路和提高效率，从Skipped frames入手定位问题，对问题进行分类来确定解题思路，发挥想象另辟蹊径，用信息集来检查结论，最后解决问题。正如文章开头说的，bugreport只是性能问题的诊断工具之一，工具没有好坏之分只有适不适合，都几把工具总是有好处的，后面有机会再介绍simpleperf,systrace等核武器。