Android 系统 ANR 分析详解

今天药忘吃喽~ 2022-03-11 15:12 844阅读 0赞

*  什么是 ANR
 *  ANR 产生的原因
 *  ANR 出现流程分析
 *  发生 ANR 如何定位
 *  如何避免和解决 ANR

附 Google 官网说明链接：[Keeping your app responsive][]

### 1. 什么是 ANR ###

*  ANR：Application Not Responding，即应用无响应
 *  为用户在主线程长时间被阻塞
 *  Android 系统自身提供的一种检测机制

##### \-> ANR 的类型 #####

ANR 一般有三种类型：

1.  KeyDispatchTimeout（5秒超时） – 主要类型按键或触摸事件在特定时间内无响应
2.  BroadCastTimeout（10秒超时） – 一个广播接收者流程没有在 10 秒之内完成

##### 自定义修改按键响应超时时间 #####

在 frameworks/base/ 下的 ActivityManagerService.java 中定义了具体的超时时间，默认为 5 秒

// How long we wait until we timeout on key dispatching.
    static final int KEY_DISPATCHING_TIMEOUT = 5*1000;

### 2 ANR 产生的原因 ###

超时时间的计数一般是从按键分发给 APP 开始。超时的原因一般有两种：

1.  当前的事件没有机会得到处理（即 UI 线程正在处理前一个事件，没有及时的完成或者 looper 因为某种原因阻塞住了）
2.  当前的事件正在处理，但是没有及时完成

需要满足的条件：

1.  主线程：只有应用的主线程响应超时才会导致 ANR
2.  超时时间（Timeout）：导致 ANR 的原因不同，系统限定的时间也不同，但只要超过时间上限，系统就会发出 Signal 3，产生 ANR
3.  输入操作/特定操作：输入操作指的是按键、触屏等操作，特定操作指的是广播、服务中执行耗时操作等

下面总结了几点常见的引起 ANR 的情况：

1. 应用程序自身引起的
       例如，主线程阻塞（block）、挂起、死锁、死循环、执行耗时操作等
    2. 其他应用进程引起的
       例如，其他进程的 CPU 占用率过高、某一时刻系统 CPU 负载过高等，
       都会导致当前进程无法抢到 CPU 时间片
    3. IO wait
       文件读写耗时较久，占用 CPU 时间片较长，导致 ANR

> 小技巧：如果你在解决其他问题时也需要查看 Java 进程中各个线程的函数堆栈信息，就可以使用向目标进程发送 SIGNAL\_QUIT（3），它并不会让进程真正退出。

### 3. ANR 出现流程分析 ###

##### 1. 输入时间响应超时导致 ANR 流程 #####

在系统输入管理服务进程（InputManagerService）中有一个线程（InputDispathcerThread）专门管理输入事件的分发，在该线程处理输入事件的过程中，回调 InputDispatcher 对象方法不断的检测处理过程是否超时，一旦超时，则会回调调用 InputMethod 对象的 notifyANR 方法，其会最终出发 AMS 中 handler 对象的 SHOW\_NOT\_RESPONDING\_MSG 这个事件，显示 ANR 对话框。

##### 2. 广播过程发生 ANR 流程 #####

广播分为三类：普通、有序、异步。只有有序（ordered）的广播才会发生超时，而在 AndroidManifest 中注册的广播都会被当做有序广播来处理，会被放在广播的队列中串行处理。AMS 在处理广播队列时，会设置一个超时时间，当处理一个广播达到超时时间的限制时，就会触发 BroadcastQueue 类对象的 processNextBroadcast 方法来判断是否超时，如果超时，就会终止该广播，触发 ANR 对话框。

##### 3. UI 线程 #####

…

### 4. 发生 ANR 如何定位 ###

系统发生 ANR 的时候，一般会以以下三种方式记录

*  logcat 日志
 *  /data/anr/traces.txt
 *  dropBox 服务

#### 4.1 通过 logcat 文件分析 ####

\-> 举例说明：

04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.android.email/com.android.email.activity.SplitScreenActivitypaused=false}.
    5009.8ms since event, 5009.5ms since waitstarted
    04-0113:12:11.572 I/WindowManager( 220): Input event 
    dispatching timedout sending 
    tocom.android.email/com.android.email.activity.SplitScreenActivity
    
    // 1. 发生 ANR 的时间和生成 trace.txt 的时间
    04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 
    04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to 
    signal 3 
    // 2. ANR 发生的地点
    04-0113:12:15.872 E/ActivityManager( 220): ANR in 
    com.android.email(com.android.email/.activity.SplitScreenActivity)
    04-0113:12:15.872 E/ActivityManager( 220): 
    // 3. ANR 的类型
    Reason:keyDispatchingTimedOut
    // 4. ANR 发生前 CPU 的负载情况
    04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53
    04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago 
    04-0113:12:15.872 E/ActivityManager( 220): 5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults:
    10 minor
    04-0113:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11
    minor 2 major
    04-0113:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait
    // 5. ANR 发生后 CPU 的负载情况
    04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms 
    04-0113:12:15.872 E/ActivityManager( 220): 25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor
    04-0113:12:15.872 E/ActivityManager( 220): 16% 21603/__eas(par.hakan: 16% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
    04-0113:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel

从 LOG 上可以提取到的有效信息：

##### 1. ANR 发生的时间、地点以及类型 #####

类型为 keyDispatchingTimedOut，即按键事件输入响应超时，发生在 com.android.email 应用中

##### 2. CPU 负载情况 #####

*  如果 CPU 占用率接近 100%，说明当前设备很忙，有可能是 CPU 饥饿导致了ANR
 *  如果 IOWait 很高，说明主线程正在进行 IO 操作
 *  如果 CPU 占用率很低，则说明当前主线程被 BLOCK 了

从上面的 LOG 可以看出，total CPU 占用率达到 100%，并且 io wait 占用 87%，说明当前主线程正在进行 io 操作。

#### 4.2 通过 traces.xml 文件分析 ####

trace 文件中会标明 Thread 的状态，如：

DALVIK THREADS (12):
    // 当前线程名 - "main"
    // 线程优先级 - "prio=5"
    // 线程id - "tid=1"
    // 线程状态 - "Sleeping"
    "main" prio=5 tid=1 Runnable

其他常用的状态定义在 Thread.java 文件中：

ThreadState (defined at "dalvik/vm/thread.h")
    THREAD_UNDEFINED = -1, / makes enum compatible with int32_t /
    THREAD_ZOMBIE = 0, / 线程死亡，终止运行 /
    THREAD_RUNNING = 1, / 线程可运行或正在运行 /
    THREAD_TIMED_WAIT = 2, / 执行了带有超时参数的 wait、sleep 或 join 函数 /
    THREAD_MONITOR = 3, / 线程阻塞 /
    THREAD_WAIT = 4, / 执行了无超时参数的 wait 函数 /
    THREAD_INITIALIZING= 5, / 新建，正在初始化，为其分配资源 /
    THREAD_STARTING = 6, / 新建，正在启动 /
    THREAD_NATIVE = 7, / 正在执行 JNI 本地函数 /
    THREAD_VMWAIT = 8, / 正在等待 VM 资源 /
    THREAD_SUSPENDED = 9, / suspended, usually by GC or debugger /

举例分析：

----- pid 609 at 2019-02-16 05:00:10 -----
    Cmd line: com.android.systemui
    ...
    "main" prio=5 tid=1 Native
      | group="main" sCount=1 dsCount=0 flags=1 obj=0x748ef1f0 self=0xb0851000
      | sysTid=609 nice=0 cgrp=default sched=0/0 handle=0xb4a3f494
      | state=S schedstat=( 392030973719 182772499142 1025298 ) utm=33261 stm=5941 core=2 HZ=100
      | stack=0xbe5fa000-0xbe5fc000 stackSize=8MB
      | held mutexes=
      kernel: (couldn't read /proc/self/task/609/stack)
      native: #00 pc 00019d74  /system/lib/libc.so (syscall+28)
      native: #01 pc 0001d11d  /system/lib/libc.so (__futex_wait_ex(void volatile*, bool, int, bool, timespec const*)+88)
      native: #02 pc 00063a99  /system/lib/libc.so (pthread_cond_wait+32)
      native: #03 pc 0037cb2b  /system/lib/libhwui.so (android::uirenderer::renderthread::DrawFrameTask::postAndWait()+174)
      native: #04 pc 0037ca59  /system/lib/libhwui.so (android::uirenderer::renderthread::DrawFrameTask::drawFrame()+24)
      at android.view.ThreadedRenderer.nSyncAndDrawFrame(Native method)
      at android.view.ThreadedRenderer.draw(ThreadedRenderer.java:823)
      at android.view.ViewRootImpl.draw(ViewRootImpl.java:3316)
      at android.view.ViewRootImpl.performDraw(ViewRootImpl.java:3120)
      at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:2489)
      at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1465)
      at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:7188)
      at android.view.Choreographer$CallbackRecord.run(Choreographer.java:949)
      at android.view.Choreographer.doCallbacks(Choreographer.java:761)
      at android.view.Choreographer.doFrame(Choreographer.java:696)
      at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:935)
      at android.os.Handler.handleCallback(Handler.java:873)
      at android.os.Handler.dispatchMessage(Handler.java:99)
      at android.os.Looper.loop(Looper.java:193)
      at android.app.ActivityThread.main(ActivityThread.java:6718)
      at java.lang.reflect.Method.invoke(Native method)
      at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
      at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)

以上的 trace 文件来自 systemui ANR，可以看出在 main 线程执行 NATIVE 方法的过程中，nSyncAndDrawFrame GPU 渲染的过程发生超时。

### 5. 如何避免和解决 ANR ###

1.  UI 线程尽量只做跟 UI 相关的工作
2.  耗时的工作（比如数据库操作，I/O，连接网络或者别的有可能阻碍 UI 线程的操作）把它放入单独的线程处理
3.  尽量用 Handler 来处理 UIthread 和别的线程之间的交互
4.  实在绕不开主线程，可以尝试通过 Handler 延迟加载
5.  广播中如果有耗时操作，建议放在 service 中去执行，或者通过 handlerThread 分发执行。

##### 分析着重点 #####

*  cpu 占用率方面
    
     *  可以通过分析各进程的 CPU 时间占用率，来判断是否为某些进程长期占用 CPU 导致该进程无法获取到足够的 CPU 处理时间，而导致 ANR
     *  重点关注下 CPU 的负载，即 Logcat 中 Load1（Load: 0.42 / 0.27 / 0.25，即 cpu 平均负载），各个进程总的 CPU 时间占用率，用户 CPU 时间占用率，核心态 CPU 时间占用率，以及 iowait CPU 时间占用率。
 *  内存方面
    
     *  主要看当前应用 native 和 dalvik 层内存使用情况
     *  结合系统给每个应用分配的最大内存来分析

[Keeping your app responsive]: http://developer.android.com/intl/zh-cn/training/articles/perf-anr.html#anr