android anr分析

转自：https://blog.csdn.net/fishmai/article/details/71077047

 

ANR简介

• ANR，是“Application Not Responding”的缩写，即“应用程序无响应”。在Android中，ActivityManagerService（简称AMS）和WindowManagerService（简称WMS）会监测应用程序的响应时间，如果应用程序主线程（即UI线程）在超时时间内对输入事件没有处理完毕，或者对特定操作没有执行完毕，就会出现ANR。对于输入事件没有处理完毕产生的ANR，Android会显示一个对话框，提示用户当前应用程序没有响应，用户可以选择继续等待或者关闭这个应用程序（也就是杀掉这个应用程序的进程）。

为什么会有ANR

ANR的产生需要同时满足三个条件：

• 主线程：只有应用程序进程的主线程响应超时才会产生ANR；

• 超时时间：产生ANR的上下文不同，超时时间也会不同，但只要在这个时间上限内没有响应就会ANR；

• 输入事件/特定操作：输入事件是指按键、触屏等设备输入事件，特定操作是指BroadcastReceiver和Service的生命周期中的各个函数，产生ANR的上下文不同，导致ANR的原因也会不同；

针对这三个条件，有以下三种情况会触发ANR，详细说明如下。

• 1、主线程对输入事件在5秒内没有处理完毕

Android的事件系统从2.3开始做了完全不同的实现，原先2.2中是在Java层实现的，但在2.3中整体转移到了C++层，本书基于2.3以后的版本进行说明。我们先简单了解一下产生这种ANR的整个流程。

当应用程序的Window处于Active状态并且能够接收输入事件（例如按键事件、触摸事件等）时，系统底层上报的事件就会被InputDispatcher分发给这个应用程序，应用程序的主线程通过InputChannel读取输入事件并交给界面视图处理，界面视图是一个树状结构，DecorView是视图树的根，事件从树根开始一层一层向端点（例如一个Button）传递。我们通常会注册一个监听器来接收并处理事件，或者创建自定义的视图控件来处理事件。

InputDispatcher运行在系统进程（进程名为system_server）的一个单独的线程中，应用程序的主线程在处理事件的过程中，InputDispatcher会不断的检测处理过程是否超时，一旦超时，会通过一系列的回调通知WMS的notifyANR函数，最终会调用到AMS中mHandler对象里的SHOW_NOT_RESPONDING_MSG这个case，此时界面上就显示系统提示对话框了，同时使用logcat命令查看log（日志信息）也可以看到关于ANR的信息。一下子出现了好几个重要的名词，要深入了解这种情况的ANR，需要熟悉Android的事件机制，本次不做解析，这里只需要记住他们的功能：

• Window：具体指的是PhoneWindow对象，表示一个能够显示的窗口，它能够接收系统分发的各种输入事件；

• InputDispatcher：将系统上报的输入事件分发给当前活动的窗口；

• InputChannel：InputDispatcher和应用程序分别运行在两个不同的进程中，InputDispatcher就是通过InputChannel将事件对象传递给应用进程的。

注意：产生这种ANR的前提是要有输入事件，如果用户没有触发任何输入事件，即便是主线程阻塞了，也不会产生ANR，因为InputDispatcher没有分发事件给应用程序，当然也不会检测处理超时和报告ANR了。

• 2、主线程在执行BroadcastReceiver的onReceive函数时10秒内没有执行完毕
  BroadcastReceiver（简称BR）的onReceive函数运行在主线程中，当这个函数超过10秒钟没有返回就会触发ANR。不过对这种情况的ANR系统不会显示对话框提示，仅是输出log而已。

• 3、主线程在执行Service的各个生命周期函数时20秒内没有执行完毕
  Service的各个生命周期函数也运行在主线程中，当这些函数超过20秒钟没有返回就会触发ANR。同样对这种情况的ANR系统也不会显示对话框提示，仅是输出log。

三种ANR中只有第1种会显示系统提示对话框，因为用户正在做界面交互操作，如果长时间没有任何响应，会让用户怀疑设备死机了，大多数人此时会开始乱按，甚至拔出电池重启，给用户的体验肯定是非常糟糕的。

三种ANR发生时都会在log中输出错误信息，你会发现各个应用进程和系统进程的函数堆栈信息都输出到了一个/data/anr/traces.txt的文件中，这个文件是分析ANR原因的关键文件，同时在日志中还会看到当时的CPU使用率，这也是重要信息，可以利用它们分析ANR问题。

这三种ANR不是孤立的，有可能会相互影响。例如一个应用程序进程中同时有一个正在显示的Activity和一个正在处理消息的BroadcastReceiver，它们都运行在这个进程的主线程中。如果BR的onReceive函数没有返回，此时用户点击屏幕，而onReceive超过5秒仍然没有返回，主线程无法处理用户输入事件，就会引起第1种ANR。如果继续超过10秒没有返回，又会引起第2种ANR。

 

如何分析

关于发生 ANR 截取的 log 和 trace 这里就不多说了

1、CPU 问题

• 在 Monkeylog.log 文件中定位到 "anr in" 位置，查看 cpu usage ,total 占用，如发现接近100%，暂时判断为 cpu 问题。
• 然后在 logcat.log 文件中定位到 "not responding" 发生时间，并截取
  cpuinfo.log 中时间点前后 5s 的 log，然后计算 CPU 占中，看哪个进程用的多，在酌情分析模块的 CPU 占中。

2、GC 问题

• 定位到 logcat.log 文件中 "not responding" 发生时间点；

• 去查看发生 ANR 时间点对应的 trace 文件，定位到应用报名，若Dalvik Thread主线程显示“SUSPENDED”,则为内存问题；

• 截取 ANR 发生时间点前 5s 的 log，分析 "dalvikvm" 打印的 Paused GC 耗时，如果过多则定位为 GC 问题，需要查看这 5s 件发生了哪些耗时的操作。

注意：发生 GC 的进程 id 需要和当前发生 ANR 的线程 id 的要一致

如何避免

• 合理使用 UI 主线程，耗时操作放入其他线程工作；
• 合理使用 Handler 来处理其他线程请求；
• 合理使用并遵循 Android 生命周期, 避免在 onCreate() and onResume() 做过多的事情；
• 使用一些架构形成规范来避免内存等问题,例如：MVP、RxJava；
• 经常使用工具来检查内存问题,例如:MAT、TraceView、AS 自带等工具；
• 避免加载大图片引起内存不足导致 ANR；
• 避免内存泄露引起的 ANR。

比如官方例子中：

 private class DownloadFilesTask extends AsyncTask<URL, Integer, Long> {
     // Do the long-running work in here
     // 耗时操作放这里
     protected Long doInBackground(URL... urls) {
         int count = urls.length;
         long totalSize = 0;
         for (int i = 0; i < count; i++) {
             totalSize += Downloader.downloadFile(urls[i]);
             publishProgress((int) ((i / (float) count) * 100));
             // Escape early if cancel() is called
             if (isCancelled()) break;
         }
         return totalSize;
     }

     // This is called each time you call publishProgress()
     protected void onProgressUpdate(Integer... progress) {
         setProgressPercent(progress[0]);
     }

     // This is called when doInBackground() is finished
      // 耗时操作完成后 Post 到 UI 主线程
     protected void onPostExecute(Long result) {
         showNotification("Downloaded " + result + " bytes");
     }
 }

友好处理

一般情况下， 超过100至200毫秒用户会感知程序有些缓慢。因此，可以做一些比较友好的 UI 提示页面，比如：ProgressBar，来表明当前正在处理，使得用户不会去一直点击页面，减少输入即可能减少 ANR 出现几率，因为按键5s不响应是会出现 ANR 的。

可以使用性能工具来优化我们的 App，如 Systrace 和 Traceview 。

关于内存泄露分析可以查看之前总结的 Android 内存泄漏工具使用分析

Basic investigate steps

1. Find "waiting to lock"

   • you can find monitor state "Binder Thread #15" prio=5 tid=75 MONITOR

   • you are lucky if find "waiting to lock"

   • example : waiting to lock <0xblahblah> (a com.foo.A) held by threadid=74

2. You can notice that "tid=74" hold a task now. So go to tid=74

3. tid=74 maybe SUSPENDED state! find main reason! trace does not always contain "waiting to lock". in this case it is hard to find main reason.

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日志不是一套)

图片.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一致，类似如下信息

图片.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例子

图片.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，无法分析。

图片.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，这里的分析有时候很关键，往往会成为定位问题的关键。