Android 应用程序 ANR 问题分析总结

ANR (Application Not Responding) 应用程序无响应。如果应用程序在UI线程被阻塞太长时间，就会出现ANR，通常出现ANR，系统会弹出一个提示提示框，让用户知道，该程序正在被阻塞，是否继续等待还是关闭。

1、ANR出现的原因

• 主线程频繁进行耗时的IO操作：如数据库读写（UI线程等待其它线程释放某个锁，导致UI线程无法处理用户输入）；
• 多线程操作的死锁，主线程被block；
• 主线程被Binder 对端block；
• System Server中WatchDog出现ANR；
• service binder的连接达到上线无法和SystemServer通信
• 系统资源已耗尽（管道、CPU、IO）

2、ANR类型

出现ANR的一般有以下几种类型：

(1) KeyDispatchTimeout（常见）

input事件在5S内没有处理完成发生了ANR。
logcat日志关键字：Input event dispatching timed out

(2) BroadcastTimeout

前台Broadcast：onReceiver在10S内没有处理完成发生ANR。
后台Broadcast：onReceiver在60s内没有处理完成发生ANR。
logcat日志关键字：Timeout of broadcast BroadcastRecord

(3) ServiceTimeout

前台Service：onCreate，onStart，onBind等生命周期在20s内没有处理完成发生ANR。
后台Service：onCreate，onStart，onBind等生命周期在200s内没有处理完成发生ANR
logcat日志关键字：Timeout executing service

(4) ContentProviderTimeout

ContentProvider 在10S内没有处理完成发生ANR。 logcat日志关键字：timeout publishing content providers

3、分析过程

(1) 直接打印系统log

使用命令 adb logcat 获取系统打印的部分 log，通过搜索关键字：ANR in

就可以找到报告CPU相关的ANR信息位置，例如:

02-16 14:46:22.550   466  2850 E ActivityManager: PID: 2743
02-16 14:46:22.550   466  2850 E ActivityManager: Reason: Input dispatching timed out (f56e537 com.android.documentsui/com.android.documentsui.picker.PickActivity (server) is not responding. Waited 5004ms for MotionEvent(deviceId=5, source=0x00002002, displayId=0, action=UNKNOWN, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, classification=NONE, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, xCursorPosition=44.8, yCursorPosition=60.4, pointers=[0: (44.8, 60.4)]), policyFlags=0x62000000)
02-16 14:46:22.550   466  2850 E ActivityManager: Parent: com.android.documentsui/.picker.PickActivity
02-16 14:46:22.550   466  2850 E ActivityManager: Load: 6.29 / 1.83 / 0.76
02-16 14:46:22.550   466  2850 E ActivityManager: ----- Output from /proc/pressure/memory -----
02-16 14:46:22.550   466  2850 E ActivityManager: some avg10=0.04 avg60=0.12 avg300=0.06 total=430350
02-16 14:46:22.550   466  2850 E ActivityManager: full avg10=0.01 avg60=0.02 avg300=0.00 total=161798
02-16 14:46:22.550   466  2850 E ActivityManager: ----- End output from /proc/pressure/memory -----
02-16 14:46:22.550   466  2850 E ActivityManager: 
02-16 14:46:22.550   466  2850 E ActivityManager: CPU usage from 0ms to 6470ms later (2023-02-16 14:46:16.047 to 2023-02-16 14:46:22.517):
02-16 14:46:22.550   466  2850 E ActivityManager:   102% 1592/android.process.media: 45% user + 57% kernel / faults: 5321 minor
02-16 14:46:22.550   466  2850 E ActivityManager:   82% 2743/com.android.documentsui: 74% user + 8.5% kernel / faults: 5859 minor 6 major
02-16 14:46:22.550   466  2850 E ActivityManager:   53% 1436/com.android.providers.media.module: 39% user + 14% kernel / faults: 9076 minor 1 major
02-16 14:46:22.550   466  2850 E ActivityManager:   35% 466/system_server: 22% user + 13% kernel / faults: 13088 minor 4 major
02-16 14:46:22.550   466  2850 E ActivityManager:   12% 146/logd: 4.1% user + 8% kernel / faults: 7 minor
02-16 14:46:22.550   466  2850 E ActivityManager:   10% 1260/adbd: 3.3% user + 7.4% kernel
……
02-16 14:46:22.550   466  2850 E ActivityManager: 96% TOTAL: 54% user + 35% kernel + 0.3% iowait + 5.1% irq + 1% softirq
02-16 14:46:22.550   466  2850 E ActivityManager: CPU usage from 44ms to 633ms later (2023-02-16 14:46:16.091 to 2023-02-16 14:46:16.679):
02-16 14:46:22.550   466  2850 E ActivityManager:   100% 1592/android.process.media: 42% user + 
……
02-16 14:46:22.551   466  2850 E ActivityManager:   94% 2743/com.android.documentsui: 86% user + 
……
02-16 14:46:22.551   466  2850 E ActivityManager: 95% TOTAL: 51% user + 37% kernel + 5.1% irq + 0.8% softirq
02-16 14:46:22.568   466  2850 D ActivityManager: Completed ANR of com.android.documentsui in 6521ms, latency 28ms

通过上述log可知

进程PID：2743

进程名：com.android.documentsui

ANR类型：KeyDispatchTimeout

等等信息。通过搜索 PID 号找到如下log，确定ANR发生的位置：

02-16 14:46:21.265  2743  2743 W oid.documentsu: Long monitor contention with owner AsyncTask #31 (2852) at com.android.documentsui.DirectoryResult com.android.documentsui.MultiRootDocumentsLoader.loadInBackground()(MultiRootDocumentsLoader.java:130) waiters=0 in void com.android.documentsui.MultiRootDocumentsLoader.onReset() for 458ms

(2) 获取详细log

当上述步骤无法找到ANR发生的位置或者原因时，可以使用命令 adb bugreport 获取获取错误、异常等问题的报告文件，然后找到 bugreport_XXX.txt文件查看系统打印的详细log信息。

然后找到关键字：am_anr ，可以得知ANR的时间点、进程PID、ANR类型（最接近ANR触发时间点的就是EventLog中输出的 am_anr 信息）例如：

02-16 14:46:16.078  1000   466  2850 I am_anr  : [0,2743,com.android.documentsui,818527813,Input dispatching timed out (f56e537 com.android.documentsui/com.android.documentsui.picker.PickActivity (server) is not responding. Waited 5004ms for MotionEvent(deviceId=5, source=0x00002002, displayId=0, action=UNKNOWN, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, classification=NONE, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, xCursorPosition=44.8, yCursorPosition=60.4, pointers=[0: (44.8, 60.4)]), policyFlags=0x62000000)]

应用com.android.documentsui在02-16 14:46:16.078时间，发生了一次KeyDispatchTimeout类型的ANR，它的进程号是2743，即：

ANR时间：02-16 14:46:16.078

进程pid：2743

进程名：com.android.documentsui

ANR类型：KeyDispatchTimeout

通过上面关键信息，我们了解到，发生KeyDispatchTimeout的ANR是因为input事件在5秒内没有处理完成。那么在这个时间02-16 14:46:16.078的前5秒，也就是（14:46:11 ~14:46:12）时间段左右程序到底做了什么事情？我们已经知道pid了，再搜索一下pid = 2743的日志.这些日志表示该进程所运行的轨迹，关键的日志如下：

02-16 14:46:13.274  2743  2847 D MultiRootDocsLoader: Found 0 of 0 queries done

02-16 14:46:13.274  2743  2743 W oid.documentsu: Long monitor contention with owner AsyncTask #30 (2847) at com.android.documentsui.DirectoryResult com.android.documentsui.MultiRootDocumentsLoader.loadInBackground()(MultiRootDocumentsLoader.java:130) waiters=0 in void com.android.documentsui.MultiRootDocumentsLoader.onReset() for 477ms

02-16 14:46:13.275  2743  2743 D AbstractActionHandler: Creating new loader recents.

(3) 获取ANR报告

通过命令 adb pull data/anr/* 获取ANR报告文件(一般是anr_XXX)，通过所搜进程pid或发生anr的应用包名找到anr发生的代码位置，例如：

"main" prio=5 tid=1 Blocked| group="main" sCount=1 dsCount=0 flags=1 obj=0x7185f448 self=0xb400007c571d4be0| sysTid=2743 nice=-10 cgrp=default sched=0/0 handle=0x7d7db7c4f8| state=S schedstat=( 2582277546 378772611 1438 ) utm=225 stm=32 core=3 HZ=100| stack=0x7fff273000-0x7fff275000 stackSize=8192KB| held mutexes=at com.android.documentsui.MultiRootDocumentsLoader.onReset(MultiRootDocumentsLoader.java:332)- waiting to lock <0x0e9de0a8> (a java.util.HashMap) held by thread 52at androidx.loader.content.Loader.reset(Loader.java:447)at androidx.loader.app.LoaderManagerImpl$LoaderInfo.destroy(LoaderManagerImpl.java:167)at androidx.loader.app.LoaderManagerImpl.restartLoader(LoaderManagerImpl.java:457)at com.android.documentsui.AbstractActionHandler.loadDocumentsForCurrentStack(AbstractActionHandler.java:775)at com.android.documentsui.-$$Lambda$L5LNv5NSfnK-xtifNcLLKR6iIWM.run(lambda:-1)at com.android.documentsui.ContentLock.runWhenUnlocked(ContentLock.java:78)- locked <0x0d9c07c1> (a com.android.documentsui.ContentLock)at com.android.documentsui.LockingContentObserver.onChange(LockingContentObserver.java:51)at android.database.ContentObserver.onChange(ContentObserver.java:153)at android.database.ContentObserver.onChange(ContentObserver.java:169)at android.database.ContentObserver.onChange(ContentObserver.java:187)at android.database.ContentObserver.onChange(ContentObserver.java:202)at android.database.ContentObserver.lambda$dispatchChange$0$ContentObserver(ContentObserver.java:282)at android.database.-$$Lambda$ContentObserver$MgqiYb2qvgLhoXTioYXq9MvvpNk.run(lambda:-1)at android.os.Handler.handleCallback(Handler.java:938)at android.os.Handler.dispatchMessage(Handler.java:99)at android.os.Looper.loop(Looper.java:223)at android.app.ActivityThread.main(ActivityThread.java:7664)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)