舞影凌风

Android ANR日志分析

  android、anr

ANR介绍和类型

当Android应用程序的UI线程被阻塞太久时，会触发一个“应用程序没有响应”(ANR)错误。如果app在前台，系统会向用户显示一个对话框，如图1所示。ANR对话框为用户提供了强制退出应用程序的机会。 https://developer.android.com/topic/performance/vitals/anr

出现ANR的一般有以下几种类型：搜索ANR in 可以查看抛出ANR日志线程

1: KeyDispatchTimeout
  • input事件在5S内没有处理完成发生了ANR。
  • logcat日志关键字：Reason: Input dispatching timed out (Waiting because the focused window has not finished processing the input events that were previously delivered to it.)
2: BroadcastTimeout
  • 前台Broadcast：onReceiver在10S内没有处理完成发生ANR。
  • 后台Broadcast：onReceiver在60s内没有处理完成发生ANR。
  • logcat日志关键字：Reason: Broadcast of Intent
3: ServiceTimeout
  • 前台Service：onCreate，onStart，onBind等生命周期在20s内没有处理完成发生ANR。
  • 后台Service：onCreate，onStart，onBind等生命周期在200s内没有处理完成发生ANR
  • logcat日志关键字：Reason: Executing service
4: ContentProviderTimeout
  • ContentProvider 在10S内没有处理完成发生ANR。
  • logcat日志关键字：Reason: timeout publishing content providers

诊断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

当遇到ANR时，Android会存储跟踪信息。 在较旧的OS版本上，设备上只有一个/data/anr/traces.txt文件。 在较新的OS发行版中，存在多个/ data / anr / anr_ *文件。可以通过adb 获取: 

adb root  
adb shell ls /data/anr  
adb pull /data/anr/<filename>

traces日志参数介绍

AsyncTask #2" prio=5 tid=18 Runnable  
  | group="main" sCount=0 dsCount=0 obj=0x12c333a0 self=0x94c87100
  | sysTid=25287 nice=10 cgrp=default sched=0/0 handle=0x94b80920
  | state=R schedstat=( 0 0 0 ) utm=757 stm=0 core=3 HZ=100
  | stack=0x94a7e000-0x94a80000 stackSize=1038KB
  | held mutexes= "mutator lock"(shared held)
  at com.android.developer.anrsample.BubbleSort.sort(BubbleSort.java:8)
  at com.android.developer.anrsample.MainActivity$LockTask.doInBackground(MainActivity.java:147)
  - locked <0x083105ee> (a java.lang.Boolean)
  at com.android.developer.anrsample.MainActivity$LockTask.doInBackground(MainActivity.java:135)
  at android.os.AsyncTask$2.call(AsyncTask.java:305)
  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:243)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
  at java.lang.Thread.run(Thread.java:761)
  • main：main标识是主线程，如果是线程，那么命名成“Thread-X”的格式,x表示线程id,逐步递增。
  • prio：线程优先级,默认是5
  • tid：tid不是线程的id，是线程唯一标识ID
  • group：是线程组名称
  • sCount：该线程被挂起的次数
  • dsCount：是线程被调试器挂起的次数
  • obj：对象地址
  • self：该线程Native的地址
  • sysTid：是线程号(主线程的线程号和进程号相同)
  • nice：是线程的调度优先级
  • sched：分别标志了线程的调度策略和优先级
  • cgrp：调度归属组
  • handle：线程处理函数的地址。
  • state：是调度状态
  • schedstat：从 /proc/[pid]/task/[tid]/schedstat读出，三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度，不支持这项信息的三个值都是0；
  • utm：是线程用户态下使用的时间值(单位是jiffies）
  • stm：是内核态下的调度时间值
  • core：是最后执行这个线程的cpu核的序号。

线程状态

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

  • am_anr： 描述了anr发生时的事件，原因，进程。如果是自己的代码导致的，这里会输出你代码具体的调用类
  • ANR in：mainlog 或 Syslog ，描述anr发生的应用模块
  • Reason:原因
  • Blocked | - locked | waiting to lock | held by thread 发生在死锁的情况下就会出现这三个关键字段
  • WATCHDOG KILLING SYSTEM PROCESS 
grep -rn "ANR in\|ANRManager: Reason:\|ANRManager: Android time\|am_anr\|WATCHDOG KILLING SYSTEM PROCESS\| iowait\| Blocked\| held by thread\| waiting to lock"

# sublime
ANR in|Reason:|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"

参考文档