ANR问题分析

2019年4月25日 295次阅读 来源: ZHTo0

本文站在系统角度来简单总结下ANR分析的一般套路。

一、ANR简介

1.1 ANR定义

ANR（Application Not Responding）：即应用无响应。主线程在超时时间内没有做完特定的事情，就会发生ANR。

1.2 ANR类型

1）KeyDispatchTimeout-主要类型按键或触摸事件,input事件在5S内没有处理完成发生ANR
日志关键字：Reason: Input dispatching timed out xxxx

2）ServiceTimeout-bind，create，start，unbind等在主线程处理耗时，前台Service在20s内，后台Service在200s内没有处理完成发生ANR
日志关键字：Timeout executing service:/executing service XXX

3）BroadcastTimeout- BroadcastReceiver onReceiver处理事务时前台广播在10S内，后台广播在60s内没有处理完成发生ANR
日志关键字：Timeout of broadcast XXX/Receiver during timeout:XXX/Broadcast of XXX

4）ProcessContentProviderPublishTimedOutLocked-ContentProvider publish在10s内没有处理完成发生ANR
日志关键字：timeout publishing content providers

1.3 造成ANR的常见原因

  • 主线程耗时操作，如复杂的layout，庞大的for循环，IO等。
  • 主线程被子线程同步锁block
  • 主线程被Binder 对端block
  • Binder被占满导致主线程无法和SystemServer通信
  • 得不到系统资源（CPU/Memory/IO）
二、ANR分析

本文描述的ANR分析是针对bugreport进行的分析

首先抓取bugreport:

adb bugreport > bugreport.txt

分析ANR大致分为以下几个步骤:

1.确定ANR发生时间,关键字:am_anr,ANR in
2.查看ANR发生时打印的trace,文件目录:/data/anr/traces.txt,以及系统附加信息关键字:MIUI-BLOCK-MONITOR
3.查看系统耗时关键字:binder_sample,dvm_lock_sample,am_lifecycle_sample,binder thread
4.结合源码和以上的信息进行分析

2.1 am_anr

12-17 06:02:14.463 1566 1583 I am_anr : [0,8769,com.android.updater,952680005,Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }]

发生anr的时间点 am_anr: 进程pid：8769、进程名：com.android.updater、发生ANR的类型是：BroadcastTimeout、的具体类或者原因：{ act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }

2.2 ANR in

12-17 06:02:19.286 1566 1583 E ActivityManager: ANR in com.android.updater(进程名)
 12-17 06:02:19.286 1566 1583 E ActivityManager: PID: 8769(进程pid)
 12-17 06:02:19.286 1566 1583 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }(原因)
 12-17 06:02:19.286 1566 1583 E ActivityManager: Load: 0.0 / 0.0 / 0.0(Load表明是1分钟,5分钟,15分钟CPU的负载)
 12-17 06:02:19.286 1566 1583 E ActivityManager: CPU usage from 0ms to 18846ms later (2017-12-17 06:02:00.379 to 2017-12-17 06:02:19.224):
 12-17 06:02:19.286 1566 1583 E ActivityManager: 95%(CPU的使用率)6142/com.immomo.momo: 95% (用户态的使用率)user + 0% (内核态的使用率)kernel
 12-17 06:02:19.286 1566 1583 E ActivityManager: 2.3% 8170/[com.tencent.mm](http://com.tencent.mm/): 2.3% user + 0% kernel / faults: 448 minor
12-17 06:02:19.286 1566 1583 E ActivityManager: 0.7% 1566/system_server: 0.4% user + 0.3% kernel / faults: 150 minor (高速缓存的缺页次数)1 major(内存的缺页次数)

通过am_anr 和 ANR in 确定ANR发生的时间、对应的进程、原因描述等、CPU占用和iowait时间有特别异常的也可以关注下。

2.3 trace

发生ANR时,各个应用进程和系统进程的函数堆栈信息都输出到了一个/data/anr/traces.txt的文件.我们往往比较关注的是发生ANR的应用进程主线程具体执行堆栈,我们可以知道在发生ANR这个时间点主线程具体在做什么,为什么卡住了,是等锁,binder call调用还是主线程存在耗时的操作等等.

2.4 几个系统关键字

binder_sample： 监控每个进程的主线程的binder transaction的耗时情况, 当超过阈值（比如：500ms）时,则输出相应的目标调用信息.

2754 2754 I binder_sample: [android.app.IActivityManager,35,2900,android.process.media,5]

说明:

1.主线程2754,
2.执行android.app.IActivityManager接口,
3.所对应方法code =35(即STOP_SERVICE_TRANSACTION),
4.所花费时间为2900ms,
5.该block所在package为 android.process.media.
最后一个参数是sample比例(没有太大价值)

dvm_lock_sample:当某个线程等待lock的时间blocked超过阈值（比如：500ms）,则输出当前的持锁状态.

 dvm_lock_sample: [system_server,1,Binder_9,1500,ActivityManagerService.java,6403,-,1448,0]

说明：system_server: Binder_9,执行到ActivityManagerService.java的6403行代码,一直在等待AMS锁, “-“代表持锁的是同一个文件，

即该锁被同一文件的1448行代码所持有, 从而导致Binder_9线程被阻塞1500ms.

am_lifecycle_sample： 当app在主线程的生命周期回调方法执行时间超过阈值（比如：3000ms）,则输出相应信息.

02-23 11:02:35.876 8203 8203 I am_lifecycle_sample: [0,com.android.systemui,114,3837]

说明： pid=8203, processName=com.android.systemui, MessageCode=114(CREATE_SERVICE), 耗时3.827s

注意: MessageCode=200 (并行广播onReceive耗时), 其他Code见 ActivityThread.H类

binder thread：当system_server等进程的线程池使用完, 无空闲线程时, 则binder通信都处于饥饿状态, 则饥饿状态超过一定阈值则输出信息.

1232 1232 "binder thread pool (16 threads) starved for 100 ms"

说明: system_server进程的 线程池已满的持续长达100ms

以上的binder call 信息,我们查找日志中的持锁信息

   12-17 02:08:44.559 1999 4899 I dvm_lock_sample: [system_server,1,Binder:1999_16,68916,PackageManagerService.java,3537,UserManagerService.java,3380,0]

   12-17 02:08:44.696 1999 4131 I dvm_lock_sample: [system_server,1,Binder:1999_14,61042,PackageManagerService.java,3537,UserManagerService.java,3380,0]

PackageManagerService.java第3537需要的锁被UserManagerService.java中的3380行持有,我们再结合源码查看UserManagerService.java中的3380行是因为什么原因导致持锁耗时

注意:binder call出现耗时,有binder在通信过程中因为繁忙造成,也有可能因为对端持锁或者执行一些耗时的操作耗时,日志中打印binder call信息表明binder call与远程端通信已经结束,出现binder call信息也不不代表framework出现问题,需要根据日志分析准确定位.

总结下基本分析流程：

  1. 根据log确认发生ANR的进程、发生时间、大概在做什么操作，同时关注此时CPU、内存、IO的情况。
  2. 分析trace，先看时间是否能对的上，判断是不是案发现场，然后关注主线程是否存在耗时、死锁、等锁等问题，可以基本看出是APP问题还是系统问题。
  3. 如果是系统问题导致的，再结合binder_sample、dvm_lock_sample来分别定位下binder call耗时 和 系统持锁耗时的问题。
  4. 结合代码或源码来具体分析有问题的点。
    原文作者：ZHTo0
    原文地址: https://www.jianshu.com/p/082045769443
    本文转自网络文章，转载此文章仅为分享知识，如有侵权，请联系博主进行删除。
点赞