Android ANR分析详解

2019年4月25日 310次阅读来源: youseewhat

traces文件分析

简单了解ANR
各个应用进程和系统进程的函数堆栈信息都输出到了/data/anr/traces.txt的文件中，

 获取traces 文件：adb pull /data/anr

pull目录的原因是有些手机会对不同的应用输出专属的traces文件，所以/data/anr目录下会有一堆traces文件。一般三方app开发只关心自己的应用，而且没有root权限。所以只能分析traces文件定位anr，根据问题复现的模块、页面再结合traces文件三大常见的anr问题都能解决。打开traces文件搜索自己的应用包名就能在前后的位置上找到引发anr的类和方法。如下：

1.主线程被阻塞，输入事件5s没有响应，如onClick事件。这是anr问题的主要类型,一般开发者不会犯这样的错，凡是耗时的操作都另开线程处理，如果疏忽了看看自己的代码就知道怎么处理

《Android ANR分析详解》 image.png

BroadcastReceiver是在程序主线程运行,而且默认情况下BroadcastReceiver的运行时间为10s，所以不能有耗时操作，如果耗时超过10s就会导致anr，从traces文件log就可以看出onReceive不能进行耗时任务。
image.png
BroadcastReceiver是Android的消息组件，用来组件之间、应用之间的消息传递，生命周期太短也不能开子线程处理耗时任务，耗时任务一般转交给IntentService或者JobIntentService去做。

3.Service是计算型组件，虽然在后台运行，但是本质上它也跑在主线程，如果你的服务要做任何CPU密集型（如MP3播放）或阻塞（如网络）操作，都要放在子线程中，否则耗时超过20s就会导致anr。注意anr方法是我自己写的方法。onStartCommand()方法中有耗时任务将其放到子线程中去就可以了，例如：将下面的anr（）方法放到子线程

《Android ANR分析详解》 image.png

traces文件信息解析

//开头显示进程号、ANR发生的时间点和进程名称

    ----- pid 9183 at 2012-09-28 22:20:42 ----
 Cmd line: com.example.anrdemo

DALVIK THREADS: //以下是各个线程的函数堆栈信息
//依次是：线程名、线程优先级、线程号、线程当前状态（TIMED_WAIT或SUSPENDED在anr时很常见）
//线程名称后面标识有daemon，说明这是个守护线程

"main" prio=5 tid=1 TIMED_WAIT
//依次是：线程组名称、suspendCount个数、debugSuspendCount个数、线程的Java对象地址、线程的Native对象地址
| group="main" sCount=1 dsCount=0 obj=0x4025b1b8 self=0xce68

//sysTid是线程号，主线程的线程号和进程号相同
| sysTid=9183 nice=0 sched=0/0 cgrp=default     
handle=-1345002368| schedstat=( 140838632 210998525 213 )
at java.lang.VMThread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:1213)
.......


//Binder线程是进程的线程池中用来处理binder请求的线程

"Binder Thread #2" prio=5 tid=8 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x40750b90 self=0x1440b8
| sysTid=9190 nice=0 sched=0/0 cgrp=default handle=1476256
| schedstat=( 915528 18463135 4 )
at dalvik.system.NativeStart.run(Native Method)



//JDWP线程是支持虚拟机调试的线程，不需要关心

"JDWP" daemon prio=5 tid=5 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x4074b878 self=0x16c958
| sysTid=9187 nice=0 sched=0/0 cgrp=default handle=1510224
| schedstat=( 366211 2807617 7 )
t dalvik.system.NativeStart.run(Native Method)
//“Signal Catcher”负责接收和处理kernel发送的各种信号，例如SIGNAL_QUIT、SIGNAL_USR1等就是被该线程
//接收到，这个文件的内容就是由该线程负责输出的，可以看到它的状态是RUNNABLE，不过此线程也不需要关心

"Signal Catcher" daemon prio=5 tid=4 RUNNABLE
| group="system" sCount=0 dsCount=0 obj=0x4074b7b8 self=0x150008
| sysTid=9186 nice=0 sched=0/0 cgrp=default handle=1501664
| schedstat=( 1708985 6286621 9 )

三方应用开发如何避免ANR

三方应用开发常见的anr三种情况前文已经详细呈现，避免anr思路已经清晰，简单总结下：

绝对不要在主线程上进行复杂耗时的操作，比如说发送接收网络数据、进行大量计算、操作数据库、读写文件等，统统采用异步操作

2.broadCastReceiver 要进行复杂操作的的时候，可以在onReceive()方法中启动一个IntentService或者JobIntentService去做。

Service中的耗时操作最好也是采用异步任务

4.在设计及代码编写阶段避免出现出现同步/死锁、死循环等不恰当情况

Android系统开发中的ANR

对系统开发者来说只有/data/anr/traces.txt文件是远远不够的。因为虽然anr了但是traces文件没有anr的log或者traces文件有log,但是并不能定位到导致anr问题的原因。
ANR对系统的稳定性影响是比较大的，测试中心会将ANR作为系统稳定性的重要case。系统开发者一般就要依赖工具和系统log来分析，anr报在你负责的模块，但是导致anr的原因很可能在别的模块，尤其在跑稳定性测试的时候一些个别ANR问题很难调查清楚，毕竟脚本跟手动操作还是有些区别，而且像内存碎片，硬件故障等等的问题基本应用层是无从查起的，至少依靠个人是很难找出来，可能需要个团队一起关注（比如内核，BSP），甚至是反馈给厂商去解决。

根据我的经验以下几种情况都会导致ANR：

CPU密集，导致主线程没法抢占cpu时间片,要注意cpu占用高的进程
高IO，如不当访问数据库导致数据库负载过重时(log中cpu的使用iowait占比高)
低内存（low memory），如内存不足导致block在创建bitmap上
死锁引发ANR,非主线程持有主线程需要的锁对象,导致主线程等待超时,通常log中会有以下字段 Blocked | – locked | waiting to lock | held by thread,这个时候cpu多数是空闲，使用占比很低
当前应用进程进行进程间通信请求其他进程，其他进程的操作长时间没有反馈,例如操作硬件Camera
Service binder数量达到上限
在system_server中触发WatchDog ANR

当然前面app中的ANR问题也会出现，系统开发比较庞杂，也没法整理出通用的情况案例，只能说ANR之后去如何分析。
我个人是MTK平台做的比较多，平台都有自己的工具，也会提供文档，看看文档摸索一下基本就能干活了

使用GAT工具

GAT是MTK在DDMS基础上进行二次开发封装的一个集多种debug功能为一体的工具，除了包含原有DDMS的功能以外还支持kernel抓取，获取native进程列表，backtrace decode，提取手机端debug信息等功能。当MTKLogger出现异常时，经常会需要使用GAT工具来抓取log。

mtklog里面都有意个aee_exp文件，里面有两个文件一个是ZZ_INTERNAL，只有一句话，说出报的是什么错误，发生错误的进程号，发生错误的程序，报错时间等信息。

《Android ANR分析详解》 image.png

另外一个文件叫db.01.JE，这个文件里面放的报错的具体信息以及报错时候机器各种状态的保存，但是这个文件只能用mtk特制的gat软件打开。

点击菜单上window–openlogView，点击file-OpenAeeDB,选择要打开的dbg格式的文件，左边的一列目录是各种报错时候的信息，最主要的是第一项exp_main.txt，在同级目录下会输出所有文件。

《Android ANR分析详解》 image.png

点开能发现最主要的报错信息,信息描述的很直接，对应自己的程序就明白这些信息

Build Info:          //编译信息
Flavor Info: 'None'
Exception Log Time:  //anr记录时间

Exception Class: ANR
Exception Type: system_app_anr 
Current Executing Process:
com.android.settings
com.android.settings v19 (4.4.4-eng.scm.1428072972)

Backtrace:
Process: com.android.settings
Flags: 0x40c8be45
Package: com.android.settings v19 (4.4.4-eng.scm.1428072972)
Subject: Broadcast of Intent { act=[android.net]    (http://android.net/).conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.android.settings/.ales.NetworkReceiver (has extras) }
//如果是在某个页面的话，会将页面类名也输出
Build: alps**************/1428069651:user/test-keys

Android time :[2017-12-14 20:07:52.45] [5284.377]
CPU usage from 3399ms to 151ms ago:
  100% 2281/com.***.app: 90% user + 10% kernel / faults: 20828 minor 4 major
  22% 1717/system_server: 13% user + 9.1% kernel / faults: 821 minor 7 major
  21% 192/logd: 3.6% user + 17% kernel / faults: 6 minor
  20% 237/mediaserver: 7.3% user + 13% kernel / faults: 1301 minor
  8.2% 243/mobile_log_d: 2.4% user + 5.7% kernel / faults: 66 minor
  3.3% 2442/tx_thread: 0% user + 3.3% kernel
  3.3% 6208/logcat: 0.3% user + 3% kernel
  2.7% 212/surfaceflinger: 0.3% user + 2.4% kernel
  2.4% 2138/com.android.systemui: 1.8% user + 0.6% kernel / faults: 40 minor
  1.2% 2128/sdcard: 0% user + 1.2% kernel
  0.9% 7/rcu_preempt: 0% user + 0.9% kernel
  ............
56% TOTAL: 37% user + 18% kernel + 0% iowait + 0.6% softirq

Android time :[2017-12-14 20:08:14.42] [5306.347]
CPU usage from 35171ms to 0ms ago:
  76% 2281/com.****.app: 61% user + 14% kernel / faults: 120156 minor
  52% 237/mediaserver: 21% user + 31% kernel / faults: 13346 minor
  43% 192/logd: 6.8% user + 36% kernel / faults: 116 minor
  20% 1717/system_server: 12% user + 7.6% kernel / faults: 1734 minor 6 major
  18% 212/surfaceflinger: 3.3% user + 14% kernel / faults: 30 minor
  16% 243/mobile_log_d: 5.7% user + 10% kernel / faults: 1236 minor
  7.5% 6208/logcat: 0.7% user + 6.7% kernel
  2.4% 2138/com.android.systemui: 1.5% user + 0.9% kernel / faults: 307 minor
  2.2% 2442/tx_thread: 0% user + 2.2% kernel
  ......
70% TOTAL: 33% user + 36% kernel + 0% iowait + 0.3% softirq

ANR发生之前和之后一段时间的CPU使用率

CPU使用率可以理解为一段时间（记作T）内除CPU空闲时间（记作I）之外的时间与这段时间T的比值，用公式表示可以写为：
CPU使用率= (T – I) / T
而时间段T是两个采样时间点的时间差值。之所以可以这样计算，是因为Linux内核会把从系统启动开始到当前时刻CPU活动的所有时间信息都记录下来，我们可以通过查看“/proc/stat”文件获取这些信息。主要包括以下几种时间，这些时间都是从系统启动开始计算的，单位都是0.01秒：
user： CPU在用户态的运行时间，不包括nice值为负数的进程运行的时间
nice： CPU在用户态并且nice值为负数的进程运行的时间
system：CPU在内核态运行的时间
idle： CPU空闲时间，不包括iowait时间
iowait： CPU等待I/O操作的时间
irq： CPU硬中断的时间
softirq：CPU软中断的时间

进程的CPU使用率最后输出的“faults: xxx minor/major”部分表示的是页错误次数，当次数为0时不显示。major是指Major Page Fault（主要页错误，简称MPF），内核在读取数据时会先后查找CPU的高速缓存和物理内存，如果找不到会发出一个MPF信息，请求将数据加载到内存。Minor是指Minor Page Fault（次要页错误，简称MnPF），磁盘数据被加载到内存后，内核再次读取时，会发出一个MnPF信息。一个文件第一次被读写时会有很多的MPF，被缓存到内存后再次访问MPF就会很少，MnPF反而变多，这是内核为减少效率低下的磁盘I/O操作采用的缓存技术的结果。

如果ANR发生时发现CPU使用率中iowait占比很高，可以通过查看进程的major次数来推断是哪个进程在进行磁盘I/O操作。

LOG怎么分析

首先了解一下主要的log文件

__exp_main.txt：异常类型，调用栈等关键信息。
SYS_ANDROID_LOG：android main log
SYS_KERNEL_LOG：kernel log
SYS_VERSION_INFO：kernel版本，用于和vmlinux对比，只有匹    配的vmlinux才能用于分析这个异常。
SYS_ANDROID_EVENT_LOG：系统事件信息
DUMPSYS_ACTIVITY:AMS日志
DUMPSYS_DBINFO ：数据库操作记录
DUMPSYS_WINDOW :窗口记录，记录anr发生的窗口页面
PROCESS_STATE: 发生ANR程序的进程信息，虚拟机信息？
SWT_JBT_TRACES:不知道怎么描述，自认为堆栈调用相关的记录吧
SYS_ANDROID_EVENT_LOG:事件log，如ActivityManager、powerManager相关的活动记录
SYS_ANDROID_LOG:  上层app以及framework相关活动的log
SYS_ANDROID_RADIO_LOG: 联网相关
//binder相关
SYS_BINDER_INFO: 
SYS_BINDER_MEM_USED:
//parser解析文件夹，基本解析了anr相关的信息，CPU、内存的诊断,binder分析    
parser

log很多没有列举全，常用的基本就这些，主要的log文件大概了解一下。首先ZZ_INTERNAL、__exp_main.txt文件中找到ANR的应用进程号、进程名， SYS_ANDROID_EVENT_LOG中记录的事件log中过滤am_anr，并且要对应上进程号，这个事件log基本就指出当前在哪个类或者是什么操作，你就可以看看自己的代码了

《Android ANR分析详解》 image.png

SWT_JBT_TRACES同样找到对应的进程号，看看Heap是否不够用了、线程是否被Blocked。一般线程被Blocked了，通常cpu的占用比较低。

《Android ANR分析详解》 image.png

Blocked就一定有被持有的对象，这个有时候是发生在binder，就需要分析binder相关的log

《Android ANR分析详解》 image.png

binder分配使用情况、诊断分析报告

《Android ANR分析详解》 image.png
image.png

ANR发生之后log中记录的关键字段

am_anr：描述了anr发生时的事件，原因，进程。如果是自己的代码导致的，这里会输出你代码具体的调用类
image.png
image.png
image.png

ANR in：main_log 或 Sys_log ，描述anr发生的应用模块
Reason:原因
Android time ：时间，有些时候需要根据时间到其他模块追踪问题
上面这三个字段都会同时出现
image.png
Blocked | – locked | waiting to lock | held by thread
//发生在死锁的情况下就会出现这三个关键字段

根据官网论述，死锁现象会作为ANR的一种表现方式出现，也会把日志记录到/data/anr目录下，但是如果死锁发生在system server进程中，则看门狗(watchdog)会杀掉system server进程，并且在main log中会看到关键字”WATCHDOG KILLING SYSTEM PROCESS”，系统运行时将会重启，system server也会重启，此时用户会看到开机动画会再次播放。

WATCHDOG KILLING SYSTEM PROCESS

综上所属总结了一条快速过滤命令，一般稳定性测试结束上传的log非常大，解压后几个G的log文件是很正常，不可能打开搜索，即便时间多的用不完，打开的速度正常人也没法忍受，所以直接linux命令过滤，之后再打开那个已经过滤输出的文件，命令如下：

grep -rn "ANR in\|ANRManager: Reason:\|ANRManager: Android time\|am_anr\|WATCHDOG KILLING SYSTEM PROCESS\| iowait\| Blocked\| held by thread\| waiting to lock"
高效的过滤命令，虽然grep很好用，文件超大的时候还是ag速度快
ag "ANR in|ANRManager: Reason:|ANRManager: Android time|am_anr|WATCHDOG KILLING SYSTEM PROCESS| iowait| Blocked| held by thread| waiting to lock"

ag的安装

可以用过滤mobilelog文件夹进行分析,不同的厂商系统日志输出的地方不一样。

ANR的一点源码

ANR出现时调用的函数(源码)

// 记录ANR event log
  
        EventLog.writeEvent(EventLogTags.AM_ANR, app.userId, app.pid,app.processName, app.info.flags, annotation);

// 记录ANR 到 main log

   StringBuilder info = new StringBuilder();
    info.setLength(0);
    info.append("ANR in ").append(app.processName); //关键字"ANR in"
    if (activity != null && activity.shortComponentName != null) {
        info.append(" (").append(activity.shortComponentName).append(")");
    }
    info.append("\n");
    info.append("PID: ").append(app.pid).append("\n");
    if (annotation != null) {
        info.append("Reason: ").append(annotation).append("\n");
    }
    if (parent != null && parent != activity) {
        info.append("Parent: ").append(parent.shortComponentName).append("\n");
    }

    final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);

    // dump堆栈log
    File tracesFile = dumpStackTraces(true, firstPids, processCpuTracker, lastPids,
            NATIVE_STACKS_OF_INTEREST);

    原文作者：youseewhat
    原文地址: https://www.jianshu.com/p/d19c34e7e9bd
    本文转自网络文章，转载此文章仅为分享知识，如有侵权，请联系博主进行删除。