Andriod-ANR总结及日志分析

文章目录

1. 1. ANR简述
2. 2. ANR产生原因
3. 3. 典型的ANR场景
4. 4. ANR日志分析

ANR简述

ANR（Application Not Responding）应用程序无响应。如果你应用程序在UI线程被阻塞太长时间，就会出现ANR，通常出现ANR，系统会弹出一个应用无响应对话框，同时会产生一个日志文件traces.txt，位于/data/anr/文件夹下面。

ANR产生原因

出现ANR一般有以下几种原因：

1. KeyDispatchTimeout(常见)
   input事件在5s内没有处理完成
   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

典型的ANR场景

1)主线程频繁进行IO操作，比如读写文件或者数据库；
2)硬件操作如进行调用照相机或者录音等操作；
3)多线程操作的死锁，导致主线程等待超时；
4)主线程操作调用join()方法、sleep()方法或者wait()方法；
5)耗时动画/耗资源行为导致CPU负载过重
6)system server中发生WatchDog ANR；
7)service binder的数量达到上限

ANR日志分析

ANR的Log信息保存在：/data/anr/traces.txt，每一次新的ANR发生，会把之前的ANR信息覆盖掉

获取trace文件：adb pull /data/anr/traces.txt

获取日志有一点需要注意，发生ANR后，不要选择结束进程，因为这样AMS会kill掉该进程，有些信息会打印不出来（比如MTK平台上会生成db.XX.ANR，写入到aee_exp文件夹下需要时间），最好是ANR发生后等两三分钟左右，再获取日志。

例如：

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

04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG:3---发生ANR的时间和生成trace.txt的时间
04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 3 ……
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): Reason:keyDispatchingTimedOut  -----ANR的类型
04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53 --CPU的负载情况
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago ----CPU在ANR发生前的使用情况；备注：这个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----注意这行：注意87%的iowait
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms later:-- ANR后CPU的使用量
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

从Logcat中可以得到以下信息：

1. 导致ANR的包名（com.android.emai），类名（com.android.email.activity.SplitScreenActivity），进程PID（21404）
2. 导致ANR的原因：keyDispatchingTimedOut
3. 系统中活跃进程的CPU占用率，关键的一句：100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait；表示CPU占用满负荷了，其中绝大数是被iowait即I/O操作占用了。我们就可以大致得出是io操作导致的ANR。

限于篇幅有限，不在分析别的ANR类型。同时需要注意：并不是所有的ANR类型都有章可循，很多偶发的ANR受限于当时发生的环境或者系统Bug；因此对ANR，更应该强调预防而不是分析。