Android 系统 ANR 分析详解

android  基础 专栏收录该内容
15 篇文章 2 订阅
  • 什么是 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 层内存使用情况
    • 结合系统给每个应用分配的最大内存来分析
  • 0
    点赞
  • 2
    评论
  • 10
    收藏
  • 一键三连
    一键三连
  • 扫一扫,分享海报

©️2021 CSDN 皮肤主题: 大白 设计师:CSDN官方博客 返回首页
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、C币套餐、付费专栏及课程。

余额充值