ANR的分析

一 ANR是什么？

1.1 ANR的定义：

简单说，通常就是App运行的时候，duang~卡住了，怎么搞都动不了。当卡住超过一定时间，Android系统认为这就是一次“ANR（Application Not Responding）”。

具体说，在以下情况发生时，会发生ANR（可能在不同ROM 中时间有所更改）：

用户的输入在5s内没被App响应；
BroadcastReceiver的onReceiver()超过10s；
Service中各生命周期函数执行超过20s。

一般来说，界面相对越不“流畅”的App（说明UI线程耗时操作多）越容易发生ANR（一个输入事件在某个设备A上4秒有了反馈，并不意味着它在其他设备B上是安全的）。ANR其实就是界面卡顿的极端情况。反过来，只要通过合理的方案消灭了App出现的ANR，往往也同时会使App展示界面表现会更加顺滑流畅。

1.2 一些典型的ANR 问题场景

这里举几个容易发生ANR的场景：

1）最常见的错误，UI线程等待其它线程释放某个锁，导致UI线程无法处理用户输入；

2）游戏中每帧动画都进行了比较耗时的大量计算，导致CPU忙不过来；

3）Web应用中，网络状态不稳定，而界面在等待网络数据；

4）UI线程中进行了一些磁盘IO（包括数据库、SD卡等等）的操作，在个别设备上因为硬件损坏等原因阻塞住了；

5）手机被其他App占用着CPU，自己获取不到足够的CPU 时间片，纯属误伤。

二 ANR分析之trace

2.1 trace文件

Trace文件是个什么鬼？

App的进程发生ANR时，系统让活跃的Top进程都进行了一下dump，进程中的各种Thread就都dump到这个trace文件里了，所以trace文件中包含了每一条线程的运行时状态，通常位于手机的/data/anr/目录下

主要从以下几方面分析：

1）基本信息，包括进程名、进程号、包名、系统build号、ANR 类型等等；

2）CPU使用信息，包括活跃进程的CPU 平均占用率、IO情况等等；

3）线程堆栈信息，所属进程包括发生ANR的进程、其父进程、最近有活动的3个进程等等。

2.2 Thread Dump分析

首先介绍一下Thread Dump信息的各个部分

线程info信息块：

"Timer-0" daemon prio=10tid=0xac190c00 nid=0xaef in Object.wait() [0xae77d000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

atjava.lang.Object.wait(Native Method)

-waiting on <0xb3885f60> (a java.util.TaskQueue) ###继续wait

atjava.util.TimerThread.mainLoop(Timer.java:509)

-locked <0xb3885f60> (a java.util.TaskQueue) ###已经locked

atjava.util.TimerThread.run(Timer.java:462)

线程名称：Timer-0
线程类型：daemon
优先级：10，默认是5
jvm线程id：tid=0xac190c00，jvm内部线程的唯一标识（一般通过java.lang.Thread.getId()获取，通常用自增方式实现。）
对应系统线程id（Native Thread ID）：nid=0xaef，和top命令查看的线程pid对应，不过一个是10进制，一个是16进制。（可以通过命令：top -H -p pid，查看该进程的所有线程信息）
线程状态：in Object.wait().
起始栈地址：[0xae77d000]
Java thread statck trace：上面2~7行的信息。到目前为止这是最重要的数据，java stack trace提供了大部分信息来精确定位问题根源。

对于thread dump信息，主要关注的是线程的状态和其执行堆栈。现在针对这两个重点部分进行讲解

2.2.1 Java thread statck trace详解

堆栈信息应该逆向解读：程序先执行的是第7行，然后是第6行，依次类推。

- locked <0xb3885f60> (a java.util.ArrayList)

- waiting on <0xb3885f60> (a java.util.ArrayList)

也就是说对象先上锁，锁住对象0xb3885f60，然后释放该对象锁，进入waiting状态。为啥会出现这样的情况呢？看看下面的java代码示例，就会明白：

synchronized(obj) {

.........

obj.wait();

.........

}

在堆栈的第一行信息中，进一步标明了线程在代码级的状态，例如：

java.lang.Thread.State: TIMED_WAITING (parking)

解释如下：

|blocked|

This thread tried to enter asynchronized block, but the lock was taken by another thread. This thread isblocked until the lock gets released.

|blocked (on thin lock)|

This is the same state asblocked, but the lock in question is a thin lock.

|waiting|

This thread calledObject.wait() on an object. The thread will remain there until some otherthread sends a notification to that object.

|sleeping|

This thread calledjava.lang.Thread.sleep().

|parked|

This thread calledjava.util.concurrent.locks.LockSupport.park().

|suspended|

The thread's execution wassuspended by java.lang.Thread.suspend() or a JVMTI agent call.

2.2.2 线程状态详解

Runnable

_The thread is either running or ready to run when it gets its CPU turn._

Wait on condition

_The thread is either sleeping or waiting to be notified by another thread.

该状态出现在线程等待某个条件的发生或者sleep。具体是什么原因，可以结合 stacktrace来分析。

最常见的情况是线程在等待网络的读写，比如当网络数据没有准备好读时，线程处于这种等待状态，而一旦有数据准备好读之后，线程会重新激活，读取并处理数据。在Java引入New IO之前，对于每个网络连接，都有一个对应的线程来处理网络的读写操作，即使没有可读写的数据，线程仍然阻塞在读写操作上，这样有可能造成资源浪费，而且给操作系统的线程调度也带来压力。在New IO里采用了新的机制，编写的服务器程序的性能和可扩展性都得到提高。

如果发现有大量的线程都处在Wait on condition，从线程 stack看，正等待网络读写，这可能是一个网络瓶颈的征兆。因为网络阻塞导致线程无法执行。

一种情况是网络非常忙，几乎消耗了所有的带宽，仍然有大量数据等待网络读写；另一种情况也可能是网络空闲，但由于路由等问题，导致包无法正常的到达。

所以要结合系统的一些性能观察工具来综合分析，比如netstat统计单位时间的发送包的数目，看是否很明显超过了所在网络带宽的限制；观察CPU的利用率，看系统态的CPU时间是否明显大于用户态的CPU时间；这些都指向由于网络带宽所限导致的网络瓶颈。另外一种出现 Wait on condition的常见情况是该线程在 sleep，等待 sleep的时间到了，将被唤醒。

Waiting for Monitor Entry and in Object.wait()

_The thread is waiting to getthe lock for an object (some other thread may be holding the lock). Thishappens if two or more threads try to execute synchronized code. Note that thelock is always for an object and not for individual methods._

在多线程的 JAVA程序中，实现线程之间的同步，就要说说Monitor。 Monitor是Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者 Class的锁。每一个对象都有，也仅有一个monitor。每个Monitor在某个时刻，只能被一个线程拥有，该线程就是 “ActiveThread”，而其它线程都是“Waiting Thread”，分别在两个队列“ Entry Set”和“Wait Set”里面等候。在“Entry Set”中等待的线程状态是“Waiting for monitorentry”，而在“Wait Set”中等待的线程状态是“in Object.wait()”。

先看 “Entry Set”里面的线程。我们称被synchronized保护起来的代码段为临界区。当一个线程申请进入临界区时，它就进入了 “Entry Set”队列。对应的 code就像：

synchronized(obj) {

.........

}

这时有两种可能性：

1）该 monitor不被其它线程拥有， Entry Set里面也没有其它等待线程。本线程即成为相应类或者对象的 Monitor的 Owner，执行临界区的代码。
2）该 monitor被其它线程拥有，本线程在 Entry Set队列中等待。在第一种情况下，线程将处于 “Runnable”的状态，而第二种情况下，线程 DUMP会显示处于 “waiting for monitor entry”。

临界区的设置，是为了保证其内部的代码执行的原子性和完整性。但是因为临界区在任何时间只允许线程串行通过，这和我们多线程的程序的初衷是相反的。如果在多线程的程序中，大量使用 synchronized，或者不适当的使用了它，会造成大量线程在临界区的入口等待，造成系统的性能大幅下降。如果在线程 DUMP中发现了这个情况，应该审查源码，改进程序。

再看“Wait Set”里面的线程。当线程获得了Monitor，进入了临界区之后，如果发现线程继续运行的条件没有满足，它则调用对象（一般就是被synchronized的对象）的wait() 方法，放弃Monitor，进入“Wait Set”队列。只有当别的线程在该对象上调用了notify() 或者notifyAll()，“Wait Set”队列中线程才得到机会去竞争，但是只有一个线程获得对象的Monitor，恢复到运行态。在“Wait Set”中的线程， DUMP中表现为：in Object.wait()。

一般，CPU很忙时，则关注runnable的线程，CPU很闲时，则关注waiting for monitor entry的线程

参考：http://blog.csdn.net/Tencent_Bugly/article/details/46737697

三 ANR分析实例

3.1 一个简单ANR分析

这里举个简单的例子（实际上因为各App所处环境各异，可能出现各种各样复杂的ANR情况）当App运行卡住，弹出ANR对话框，查看Logcat输出：

ActivityManager: ANR in com.tencent.bugly.demo (com.tencent.bugly.demo/.MainActivity)
ActivityManager: PID: 18617
ActivityManager: Reason: Input dispatching timed out (Waiting because the touched window has not finished processing the input events that were previously delivered to it.)
ActivityManager: Load: 18.42 / 18.09 / 18.29
ActivityManager: CPU usage from 5924ms to 475ms ago:
ActivityManager: 93% 18617/com.tencent.bugly.demo: 93% user + 0% kernel / faults: 75 minor
……
ActivityManager: CPU usage from 2906ms to 3429ms later:
ActivityManager: 96% 18617/com.tencent.bugly.demo: 96% user + 0% kernel
……
ActivityManager: 55% TOTAL: 51% user + 3.8% kernel

分析一下，从Logcat可以得到以下信息：

com.tencent.bugly.demo这个App的MainActivity发生了ANR，进程号18617；
ANR原因：用户输入超时；
ANR发生前、后一段时间分别附在情况：在ANR发生前后，CPU有90+%耗费在这个demo上，说明很可能是这个demo自身性能引起的。

接下来再看traces文件确认：

----- pid 18617 at xxxx -----
Cmd line: com.tencent.bugly.demo
JNI: CheckJNI is off; workarounds are off; pins=0; globals=272 (plus 2 weak)
DALVIK THREADS:
"main" prio=5 tid=1 SUSPENDED
| group="main" sCount=1 dsCount=0 obj=0x415e4e58 self=0x415d3028
| sysTid=18617 nice=0 sched=0/0 cgrp=apps handle=1074372948
| state=S schedstat=( 38588000572 591063492 5767 ) utm=3846 stm=12 core=0
at com.tencent.bugly.demo.MainActivity$3.doCalc(MainActivity.java:~38)
at com.tencent.bugly.demo.MainActivity$3.onClick(MainActivity.java:33)
……

分析一下，traces文件中包含以下信息：

进程号：18617；包名：com.tencent.bugly.demo；
发生ANR时，main线程被挂起（也可能是其他等待状态，比如TIMED_WAIT）；
线程的几个重要参数：

group：线程组名称“main”；

sCount：Suspended个数“1”；

obj：线程的Java对象地址；

self：线程的Native对象地址；

sysTid：线程号（这里主线程的线程号=进程号）“18617”；
具体堆栈：从堆栈可以很清晰看出是doCalc()方法出的问题，由onClick触发。

综合以上分析，问题还原为：com.tencent.bugly.demo这个App的MainActivity中有个耗时的doCalc方法在跑，无法响应用户的触摸或按键输入。OK，接下来在代码里找问题就好了。

参考：http://blog.csdn.net/tencent_bugly/article/details/46650675

3.2 通过Android trace文件分析死锁ANR

对于从事Android开发的人来说，遇到ANR(Application Not Responding)是比较常见的问题。一般情况下，如果有ANR发生，系统都会在/data/anr/目录下生成trace文件，通过分析trace文件，可以定位产生ANR的原因。产生ANR的原因有很多，比如CPU使用过高、事件没有得到及时的响应、死锁等，下面将通过一次因为死锁导致的ANR问题，来说明如何通过trace文件分析ANR问题。对应的部分trace文件内容如下：

"PowerManagerService" prio=5 tid=24 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x41dd0eb0 self=0x5241b218
  | sysTid=567 nice=0 sched=0/0 cgrp=apps handle=1380038664
  | state=S schedstat=( 6682116007 11324451214 33313 ) utm=450 stm=219 core=1
  at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.Java:~13045)
  - waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
  at android.app.ContextImpl.sendBroadcast(ContextImpl.java:1144)
  at com.android.server.power.PowerManagerService$DisplayBlankerImpl.unblankAllDisplays(PowerManagerService.java:3442)
  at com.android.server.power.DisplayPowerState$PhotonicModulator$1.run(DisplayPowerState.java:456)
  at android.os.Handler.handleCallback(Handler.java:800)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loop(Looper.java:194)
  at android.os.HandlerThread.run(HandlerThread.java:60)
  
  "Binder_B" prio=5 tid=85 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x42744770 self=0x58329e88
  | sysTid=3700 nice=-20 sched=0/0 cgrp=apps handle=1471424616
  | state=S schedstat=( 1663727513 2044643318 6806 ) utm=132 stm=34 core=1
  at com.android.server.power.PowerManagerService$DisplayBlankerImpl.toString(PowerManagerService.java:~3449)
  - waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)
  at java.lang.StringBuilder.append(StringBuilder.java:202)
  at com.android.server.power.PowerManagerService.dump(PowerManagerService.java:3052)
  at android.os.Binder.dump(Binder.java:264)
  at android.os.Binder.onTransact(Binder.java:236)
  at android.os.IPowerManager$Stub.onTransact(IPowerManager.java:373)
  at android.os.Binder.execTransact(Binder.java:351)
  at dalvik.system.NativeStart.run(Native Method)
  
"android.server.ServerThread" prio=5 tid=12 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x41a76178 self=0x507837a8
  | sysTid=545 nice=-2 sched=0/0 cgrp=apps handle=1349936616
  | state=S schedstat=( 15368096286 21707846934 69485 ) utm=1226 stm=310 core=0
  at com.android.server.power.PowerManagerService.isScreenOnInternal(PowerManagerService.java:~2529)
  - waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
  at com.android.server.power.PowerManagerService.isScreenOn(PowerManagerService.java:2522)
  at com.android.server.wm.WindowManagerService.sendScreenStatusToClientsLocked(WindowManagerService.java:7749)
  at com.android.server.wm.WindowManagerService.setEventDispatching(WindowManagerService.java:7628)
  at com.android.server.am.ActivityManagerService.updateEventDispatchingLocked(ActivityManagerService.java:8083)
  at com.android.server.am.ActivityManagerService.wakingUp(ActivityManagerService.java:8077)
  at com.android.server.power.Notifier.sendWakeUpBroadcast(Notifier.java:474)
  at com.android.server.power.Notifier.sendNextBroadcast(Notifier.java:455)
  at com.android.server.power.Notifier.access$700(Notifier.java:62)
  at com.android.server.power.Notifier$NotifierHandler.handleMessage(Notifier.java:600)
  at android.os.Handler.dispatchMessage(Handler.java:107)
  at android.os.Looper.loop(Looper.java:194)
  at com.android.server.ServerThread.run(SystemServer.java:1328)

从trace文件看，是因为TID为24的线程等待一个TID为12的线程持有的锁，TID为12的线程等待一个TID为85的线程持有的锁，而TID为85的线程确等待一个TID为24的线程持有的锁，导致了循环等待的现象，对应的trace文件的语句如下：

TID 24：- waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
TID 12： - waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
TID 85：- waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)

既然是死锁，那么先看各线程都有那些锁。先看TID=24的线程的栈顶，ActivityManagerService的broadcastIntent函数代码如下:

 public final int broadcastIntent(IApplicationThread caller,
            Intent intent, String resolvedType, IIntentReceiver resultTo,
            int resultCode, String resultData, Bundle map,
            String requiredPermission, boolean serialized, boolean sticky, int userId) {
        enforceNotIsolatedCaller("broadcastIntent");
        synchronized(this) {
            intent = verifyBroadcastLocked(intent);
            
            final ProcessRecord callerApp = getRecordForAppLocked(caller);
            final int callingPid = Binder.getCallingPid();
            final int callingUid = Binder.getCallingUid();
            final long origId = Binder.clearCallingIdentity();
            int res = broadcastIntentLocked(callerApp,
                    callerApp != null ? callerApp.info.packageName : null,
                    intent, resolvedType, resultTo,
                    resultCode, resultData, map, requiredPermission, serialized, sticky,
                    callingPid, callingUid, userId);
            Binder.restoreCallingIdentity(origId);
            return res;
        }

可以看到TID=24需要ActivityManagerService这个锁。再看TID=12线程的栈顶，PowerManagerService的isScreenOnInternal函数代码如下：

private boolean isScreenOnInternal() {
        synchronized (mLock) {
            return !mSystemReady
                    || mDisplayPowerRequest.screenState != DisplayPowerRequest.SCREEN_STATE_OFF;
           }
    }

可以看到需要PowerManagerService的mlock这个锁。最后看TID=85线程的栈顶，同样在PowerManagerService里面，内部类DisplayBlankerImpl的toString函数：

public String toString() {
            synchronized (this) {
                return "blanked=" + mBlanked;
            }
        }

这是在内部类DisplayBlankerImpl里面实现的，所以需要DisplayBlankerImpl这个锁。对应的表格如下：

从表一来看，没有出现死锁现象，似乎并不是我们所想的那样。难道不是死锁？开始有点小怀疑自己了，难道别的原因导致的。也许只看调用堆栈的顶端可能不行，栈顶只能看出各线程需要的锁，不能仅看自己要什么吧！一味索取可不好！人不是这样做的！看一下整个的堆栈调用流程，看看自己拥有了那些锁。

跟踪TID=24线程的堆栈，在PowerManagerService内部类DisplayBlankerImpl的unblankAllDisplays函数中持有锁:

public void unblankAllDisplays() {
            synchronized (this) {
                nativeSetAutoSuspend(false);
                nativeSetInteractive(true);
                mDisplayManagerService.unblankAllDisplaysFromPowerManager();
                mBlanked = false;
                ///M: add for tvout and hdmi
                mTvOut.tvoutPowerEnable(true); 
                mHDMI.hdmiPowerEnable(true); 
                ///@}
                if (DEBUG) {
                    Slog.d(TAG_P, "unblankAllDisplays out ...");
                }
          if (mBootCompleted) {
               Intent intent = new Intent(ACTION_LOCK_SCREEN_SHOW);
               mContext.sendBroadcast(intent);
       } 
            }
        }

最后发送广播的代码，是我们自己添加的。根据unblankAllDisplays函数和broadcastIntent函数，可以看到TID=24的线程此时持有了DisplayBlankerImpl锁(unblankAllDisplays)，等待ActivityManagerService锁(broadcastIntent)释放。同样，跟踪TID=12线程的堆栈，在ActivityManagerService的wake_up函数中持有锁：

public void wakingUp() {
        if (checkCallingPermission(android.Manifest.permission.DEVICE_POWER)
                != PackageManager.PERMISSION_GRANTED) {
            throw new SecurityException("Requires permission "
                    + android.Manifest.permission.DEVICE_POWER);
        }


        synchronized(this) {
            Slog.i(TAG, "wakingUp");
            mWentToSleep = false;
            updateEventDispatchingLocked();
            comeOutOfSleepIfNeededLocked();
        }
    }

根据wakingUp函数和isScreenOnInternal函数，可以看到TID=12的线程持有ActivityManagerService锁(wakingUp)，等待PowerManagerService.mLock锁(isScreenOnInternal)。到这，似乎看到了希望，迷雾要拨开了，有点小自信是死锁导致的，但还不能最终下结论。一鼓作气，跟踪TID=85线程的堆栈，在PowerManagerService的dump有持有锁的操作：

protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
....
        synchronized (mLock) {
...
}

根据toString函数和dump函数，可以看到TID=85线程此时持有PowerManagerService.mLock锁(dump)，需要DisplayBlankerImpl(toString)。

似乎谜底已经揭晓了，如果你还没有看出来（其实我也没看出来），来个表看看吧！

参考：http://blog.csdn.net/gabbzang/article/details/22980797

四 ANR的解决方案

Android官方文档建议：

1）使用AsyncTask类，可以很方便地实现子线程耗时操作与UI更新；

2）对于BroadcastReceiver的耗时操作，建议放到Service中执行；

3）对于自建的Thread，可以通过Handler使之与UI 线程通信（这里需要注意的是，Thread默认优先级和UI线程是一样的，建议设置一般线程优先级为Process.THREAD_PRIORITY_BACKGROUND）。

这些方案大家应该都知道，不过仍难免有大量的ANR是写代码时忽略了，在测试时没发生，最终在用户的手机上出现的。回想一下是不是都经历过用户会反馈“App卡死没反应了”，但开发GG客服MM们却又因为缺少日志或无法复现而束手无策？因此要修复ANR，首先是要能发现用户ANR了，并且能知道是哪段代码导致ANR了，这样才能谈修复。