ANR问题一般解决思路

本文将基于MTK平台讨论ANR的一般解决思路以及例举常见的案例，这里的案例很多都是Monkey跑出来的，主要来源于平时项目上所遇到的。旨在通过了解本文后能够对ANR问题能够快速定位，减少排查的时间。同时在遇到棘手问题需要求助MTK时，能够更加从容。

先说下三种常见类型，这个想必各位都知道
1：KeyDispatchTimeout(谷歌default 5s，MTK平台上是8s) --主要类型
按键或触摸事件在特定时间内无响应
2：BroadcastTimeout(10s)
BroadcastReceiver在特定时间内无法处理完成
3：ServiceTimeout(20s) --小概率类型
Service在特定的时间内无法处理完成

Part1:日志获取&注意事项
对于ANR问题，鉴于测试同事上报时抓取的日志一般都是user版本获取的，而对于user版本获取的日志除了ANR时间点，看不到其它有效信息（predump无）。

这种情况下如果提交给MTK分析的话，MTK往往会要求在userdebug或者eng版本复现问题，因为userdebug或者ENG版本可以抓到predump、message、callstack等信息。

所以一旦有ANR问题需要给MTK分析的话，首先先确认是否是eng或者userdebug版本获取的，再一个check日志信息是否完整。平时处理的ANR问题又不少都是跑Monkey跑出来的，其中有不少还是低概率的，所以一次就把日志获取完整很重要。

这里顺便说一下，如果条件允许，最好使用userdebug版本测试，因为ENG版本测试的话本身会加重CPU loading
获取日志还有一点需要注意，发生ANR后，不要选择结束进程，因为这样AMS会kill掉该进程，有些信息会打印不出来，最好是ANR发生后等两三分钟左右，再将mtklog提交上来（db.XX.ANR写入到aee_exp文件夹下需要时间）

这里顺便说一下pre dump 机制
pre dump机制会分几个时间点打印 callstack
比如anr的触发时间是8秒无响应
则predump它会在4秒的时候预先dump一下callstack
6秒的时候再dump一下，anr发生后（8s后），本身会dump一次
则由这几次callstack综合分析，就会锁定大概是什么操作花了较长时间

所需日志
分析ANR问题一般需要如下日志信息：
1.aee_exp文件夹(MTK日志目录下，发生ANR会生成)
2.MTK目录下的mobilelog文件夹

这里的aee_exp文件夹一般都是需要的, 对DB进行dump解析，得到ANR发生时场景信息，比如主线程callstack，CPU，memory等，在分析问题根因时很关键。有些公司会有自己的抓取日志工具，比如当发生ANR时获取日志存放在工具指定路径，不过有些时候并不会抓取这个aee_exp文件，导致很多时候提交case给MTK分析时，MTK又索要这份文件，前后比较耽误时间
Tip:有时候会出现ANR复现了，却没有db文件生成，因为DB文件往往比较大，产生不了db文件最大的可能就是手机存储空间不足，所以复现时需要注意这一点

Part2:日志分析一般步骤
Step1:
查看mobilelog文件夹下的events_log,搜索关键字"am_anr",这一步用于确认ANR时间点，可以搜索到类似如下信息
04-29 10:00:57.240 1267 1341 I am_anr : [0,6073,com.android.dialer,952745541,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]
这个例子中的ANR类型为Input dispatching timed out, 这种anr的原因的是在viewrootimpl分发事件时，并没有找到focuswindow导致的。 时间点：10:00:57,进程号:6073
注意这里的进程号比较重要，后面要去trace.txt或者db文件中去看这个process(6073)对应的backtrace

Step2:
查看mobilelog文件夹下的main_log,搜索关键字"Application is not responding",发生ANR的时间点如下：
04-29 10:00:57.113 1267 1488 I InputDispatcher: Application is not responding: AppWindowToken{953236e token=Token{1b1a770 ActivityRecord{c3285b3 u0 com.android.dialer/.DialtactsActivity t2002}}}. It has been 8005.2ms since event, 8003.3ms since wait started. Reason: Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.
这里可以看出卡在com.android.dialer这个应用的DialtactsActivity这支文件
这个anr的直接原因是com.android.dialer/.DialtactsActivity已经成为 focused application 但是其window暂时未成为focuswindow，因此输入事件暂时不能分发，
inputdispatcher线程中的输入事件在8s内未得到处理完成的回复则会出现此类anr。

接着搜索关键字"ANR in",时间上应该是接着上面这一段，下面可以看到如下类似信息(如下片段仅仅举例，和上面的event日志不是一套)

main.png

可以看到ANR发生在com.android.dialer进程
ANR的类型，比如这个例子中是Input dispatching timed out
发生ANR时的CPU使用情况，CPU是否吃紧，列出的进程中是否有非常消耗CPU资源的，重点看下75% TOTAL: 30% user + 42% kernel + 1.3% iowait + 0.1% softirq这行，这个例子中发生ANR的Dialer进程CPU消耗为零，也就是压根没有拿到CPU资源，而总的CPU资源使用虽然蛮高的，却也没有达到百分百，很可能是依赖的某个进程挂住了，原因下面会继续分析
另外，很多时候需要注意iowait的占有率，如果占比比较高，则排查的方向要倾向与读取文件操作有关的信息，可以看trace日志中有没有一些读取文件或者操作SD卡的动作
还有注意观察一下在出现“Application is not responding”信息往上看，注意主线程是不是有耗时的动作，可以搜索关键字"ActivityThread"且搜索到的片段含有ANR的进程名

如果发现ANR时CPU loading并不高，再去检查memory的情况，以排查是否存在竞争memory的情况。aee_exp文件下的db文件解析后会有一个SYS_MEMORY_INFO文件，这个文件会列出问题发生时的MemTotal,MemFree,MemAvailable等信息

Step3:
trace.txt，这份trace务必要与moile日志匹配，可以看这份trace日志的最开头，比如这个例子trace最开头信息如下;
----- pid 6073 at 04-29 10:00:57 -----
Cmd line: com.android.dialer
这里可以看到pid 6073，和events_log搜索关键字"am_anr"得到的片段中的进程信息匹配

查看主线程的CallStack, 注意这里的sysTid号需要同events_log中含有“am_anr”片段中的6073一致，类似如下信息

trace.png

Step2中可以看到发生ANR的线程CPU使用为零，没有得到执行
再结合这一段的callstack，可以知道是由于com.android.dialer.dialpad.DialpadFragment的onStart方法没有得到执行
再往上看
at android.media.ToneGenerator.native_setup(Native method)
at android.media.ToneGenerator.<init>(ToneGenerator.java:756)
初步猜测是dialer进行拨号的时候，去播放拨号音，ToneGenerator被卡住了。 而卡住的原因是什么，这个时候再去看main.log看看能不能得到一些线索
在ANR时间点即关键字"ANR in"向上查看，发现有一段信息如下：
04-29 09:56:31.178 1267 2146 I ActivityManager: Process android.process.media (pid 1228) has died
至此ToneGenerator被卡住的原因清晰了，至于android.process.media这个进程为什么died.则不在本文讨论范围内

Part3:常见ANR案例分析

案例一：等待binder调用返回
比较常见的情况是在Binder通信时，对端没有回复导致，比如下面这个trace例子

binder通信卡住.png

这里说明对端没有回复，这就需要看当前这个线程6132在和谁通信，当前线程号在这段trace前面部分或者搜索"sysTid"
这个时候需要看SYS_BINDER_INFO这个文件了，aee_exp文件下的db文件(dbg结尾)通过MTK工具GAT解析后会有很多文件，其中就有SYS_BINDER_INFO这个文件
查找到有如下信息：
4897163: call from 6132:6132 to 1278:0 node 898 handle 6 size 96:0
4897164: reply from 1278:2035 to 6132:6132 node 0 handle -1 size 180:0

4897175: call from 6132:6132 to 1278:0 node 898 handle 6 size 96:0
4897176: reply from 1278:2034 to 6132:6132 node 0 handle -1 size 180:0

4897188: call from 6132:6132 to 1278:0 node 898 handle 6 size 96:0
4897189: reply from 1278:10225 to 6132:6132 node 0 handle -1 size 180:0

或者可以搜索关键字"outgoing transaction"，搜索到的片段中需含有"6132",这样可以顺着找到对端的进程号是1278
这个时候再去查看pid为1278即server端的trace dump信息，同时结合main.log，看看当时pid为1278的进程在做什么
这种就需要具体问题具体分析了，之前遇到过一个问题是对端的process在ANR之前一直在做网络通信，最终鉴定是网络异常导致

案例二：主线程等待锁
比如下面这个主线程的CallStack例子，可以看到如下信息：

死锁.png

这个例子中gallery的main thread在执行UploaderChimeraService的onDestroy方法时，需要lock 0x23f65d8b，但这个lock有被upload_periodic GCM Task 拿住，这个thread当前是在做连接网络的动作。所以如果仅仅从这段信息来看，很有可能是测试时手机连接的网络，无法连接gms的相关server有关

案例三：卡在IO上
这种情况一般是和文件操作相关，判断是否是这种情况，可以看mainlog中搜索关键字"ANR in",查看当时的CPU具体使用情况，比如下面这种
ANRManager: 100% TOTAL: 2% user + 2.1% kernel + 95% iowait + 0.1% softirq
很明显，IO占比很高，这个时候就需要查看trace日志看当时的callstack，着重看有没有file相关的动作，这个场景没有示例

案例四：主线程作耗时的动作
比如网络访问，访问数据库之类的，都很容易造成主线程堵塞，所以这种问题的解决，一般需要另起thread做耗时的操作
这里以访问数据库来说，这类型引起的ANR，一般来讲看当时的CPU使用情况会发现user占比较高，看trace中主线程当时的信息会发现会有一些比如query像ContentProvider这种数据库的动作。
这种情况下，还可以去看eventlog或者mainlog，在ANR发生前后打印出来的信息，比如访问数据库这种，在eventlog中搜索"am_anr",然后看前后片段，会发现发生ANR的这个进程有很多数据库相关的信息，说明在发生ANR前后主线程一直在忙于访问数据库，这类型的问题常见于图库，联系人，彩短信应用。

案例五：binder线程被占满
系统对每个process最多分配15个binder线程，这个是谷歌的设计（/frameworks/native/libs/binder/ProcessState.cpp)
如果另一个process发送太多重复binder请求，那么就会导致接收端binder线程被占满，从而处理不了其它的binder请求
这本身就是系统的一个限制，如果应用未按照系统的要求来实现对应逻辑，那么就会造成问题。
而系统端是不会（也不建议）通过修改系统行为来兼容应用逻辑，否则更容易造成其它根据系统需求正常编写的应用反而出现不可预料的问题。
判断Binder是否用完，可以在trace中搜索关键字"binder_f"，如果搜索到则表示已经用完，然后就要找log其他地方看是谁一直在消耗binder或者是有死锁发生，对于binder用完的前期思路大致如此。

案例六：JE或者NE导致ANR
比如如下这个例子com.xrom.intl.appcenter发生ANR,不过看log里有很多/system/bin/mediaserver的NE，且在ANR发生前也有一次。
一般NE dump trace等行为可能会导致ANR，所以建议把NE解掉后再看是否会发生ANR。
08-02 02:17:34.697 1133 1203 I am_anr : [0,28880,com.xrom.intl.appcenter,952680005,Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 2. Wait queue head age: 8507.7ms.)]
08-02 02:17:34.697 1133 1203 I ANRManager: startAsyncDump: AnrDumpRecord{ Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 2. Wait queue head age: 8507.7ms.) ProcessRecord{b678adb 28880:com.xrom.intl.appcenter/u0a32} IsCompleted:false IsCancelled:false }
而NE没有抓取到coredump，无法分析。

NE.png

main线程看起来是卡在hwui。
"main" prio=5 tid=1 Native
native: #02 pc 0001d0b9 /system/lib/libhwui.so (_ZN7android10uirenderer12renderthread11RenderProxy11postAndWaitEPNS1_22MethodInvokeRenderTaskE+108)
看起来是卡在renderthread
检查renderThread是在做binder通信:
"RenderThread" prio=5 tid=16 Native
| group="main" sCount=1 dsCount=0 obj=0x32dd90a0 self=0xee82a000
| sysTid=29618 nice=-4 cgrp=default sched=0/0 handle=0xe6bff930
native: #02 pc 0001a86f /system/lib/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+174)
进入SYS_BINDER_INFO(aee_exp下的db文件解析出来会包含此文件)检查它和谁在通信：
outgoing transaction 29169360: ffffffc02b41b680 from 28880:29618 to 363:15204 code 8 flags 10 pri -4 r1 node 34 size 80:8 data ffffff8004f800c8
那363又是谁：
system 363 1 27328 1204 0 20 0 0 0 fg binder_thr 7fad229b34 S 64 /system/bin/guiext-server
363又和谁在通信呢？
pending transaction 29168166: ffffffc0081f2100 from 363:363 to 28213:0 code 1 flags 10 pri -10 r1 node 15518486 size 13660:0 data ffffff8008b80408
28213：
----- pid 28213 at 2016-08-02 00:46:33 -----
Cmd line: /system/bin/mediaserver
所以是因为28213没有响应导致环环相扣最终引起com.xrom.intl.appcenter发生ANR。
28213没有响应正是因为/system/bin/mediaserver发生NE。

案例七：只存在于Monkey测试下
有些问题是只有在Monkey环境下才能跑出来，平时的user版本用户使用是不会出现的，这种问题的话就没有改动的意义。
比如下面这个例子：
ActivityManager: Not finishing activity because controller resumed
03-18 07:25:50.901 810 870 I am_anr : [0,25443,android.process.media,1086897733,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]
发生这个ANR的原因是Contoller将resume的操作给拦截了, 导致Focus不过去, 从而导致ANR，User版本不会有Contoller, 所以不会出现这个 ANR. 所以这个 ANR 可以忽略.

小结：
总的说来，拿到一份eng的完整日志，一般步骤如下：
1.find ANR time,PID,ANR type
2.check CPU usage and Memory
3.check trace.txt,mapping process ID and time stamp
4.find more information about main thread through main log and event log

这里的第四步需要根据问题来看，可以看看ANR时间点之前的日志信息找出怀疑点，这个时候需要结合trace来看，可以进一步确认怀疑点。举个例子，比如说如果ANR发生时间点之前有JE或者NE发生，则看下这些异常是否会阻碍某些事件的处理导致处理延时，如果不好判断是否会有影响，则可以先尝试去解决这些异常再去看ANR是否发生。

这里需要注意的是在分析ANR发生点之前的信息，时间点不能过早，ANR发生点之前太早的话也没有分析的意义，最好看发生ANR前0~4s的trace，这里的分析有时候很关键，往往会成为定位问题的关键。