[摘]Android ANR日志分析指南

Android 2019年5月30日 pm6:52发布6年前 (2019)更新 91es.com站长

79 0 0

定义

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

ANR类型

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

1、KeyDispatchTimeout（常见）

input事件在5S内没有处理完成发生了ANR。

logcat日志关键字：Input event dispatching timed out 或者 Input 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、多线程操作的死锁，主线程被block；

3、主线程被Binder 对端block；

4、System Server中WatchDog出现ANR；

5、service binder的连接达到上线无法和和System Server通信

6、系统资源已耗尽（管道、CPU、IO）

ANR案例分析过程

我们将一步一步分析ANR,这个过程更加理解如何找到问题、分析问题以及解决问题。

一、查看events_log

查看mobilelog文件夹下的events_log,从日志中搜索关键字：am_anr，找到出现ANR的时间点、进程PID、ANR类型。

如日志：

07-20 15:36:36.472  1000  1520  1597 I am_anr  : [0,1480,com.xxxx.moblie,952680005,
Input dispatching timed out (AppWindowToken{da8f666
token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}},
Waiting because no window has focus but there is a focused
application that may eventually add a window when it finishes starting up.)]

从上面的log我们可以看出：应用com.xxxx.moblie 在07-20 15:36:36.472时间，发生了一次KeyDispatchTimeout类型的ANR，它的进程号是1480. 把关键的信息整理一下：

ANR时间：07-20 15:36:36.472

进程pid：1480

进程名：com.xxxx.moblie

ANR类型：KeyDispatchTimeout

我们已经知道了发生KeyDispatchTimeout的ANR是因为 input事件在5秒内没有处理完成。那么在这个时间07-20 15:36:36.472 的前5秒，也就是（15:36:30 ~15:36:31）时间段左右程序到底做了什么事情？这个简单，因为我们已经知道pid了，再搜索一下pid = 1480的日志.这些日志表示该进程所运行的轨迹，关键的日志如下：

07-20 15:36:29.749 10102  1480  1737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE
07-20 15:36:30.136 10102  1480  1737 D moblie-Application: receiving an empty message, drop
07-20 15:36:35.791 10102  1480  1766 I Adreno  : QUALCOMM build                   : 9c9b012, I92eb381bc9
07-20 15:36:35.791 10102  1480  1766 I Adreno  : Build Date                       : 12/31/17
07-20 15:36:35.791 10102  1480  1766 I Adreno  : OpenGL ES Shader Compiler Version: EV031.22.00.01
07-20 15:36:35.791 10102  1480  1766 I Adreno  : Local Branch                     :
07-20 15:36:35.791 10102  1480  1766 I Adreno  : Remote Branch                    : refs/tags/AU_LINUX_ANDROID_LA.UM.6.4.R1.08.00.00.309.049
07-20 15:36:35.791 10102  1480  1766 I Adreno  : Remote Branch                    : NONE
07-20 15:36:35.791 10102  1480  1766 I Adreno  : Reconstruct Branch               : NOTHING
07-20 15:36:35.826 10102  1480  1766 I vndksupport: sphal namespace is not configured for this process.
Loading /vendor/lib64/hw/gralloc.msm8998.so from the current namespace instead.
07-20 15:36:36.682 10102  1480  1480 W ViewRootImpl[MainActivity]:
 Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_PERIOD,
scanCode=0, metaState=0, flags=0x28, repeatCount=0, eventTime=16099429, downTime=16099429, deviceId=-1, source=0x101 }

从上面我们可以知道，在时间 07-20 15:36:29.749 程序收到了一个action消息。

07-20 15:36:29.749 10102  1480  1737 D moblie-Application: [Thread:17329]
 receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE。

原来是应用com.xxxx.moblie 收到了一个推送消息（com.ttt.push.RECEIVE_MESSAGE）导致了阻塞，我们再串联一下目前所获取到的信息：在时间07-20 15:36:29.749 应用com.xxxx.moblie 收到了一下推送信息action=com.ttt.push.RECEIVE_MESSAGE发生阻塞，5秒后发生了KeyDispatchTimeout的ANR。

虽然知道了是怎么开始的，但是具体原因还没有找到，是不是当时CPU很紧张、各路APP再抢占资源？我们再看看CPU的信息,。搜索关键字关键字： ANR IN

07-20 15:36:58.711  1000  1520  1597 E ActivityManager: ANR in com.xxxx.moblie (com.xxxx.moblie/.ui.MainActivity) (进程名)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: PID: 1480 (进程pid)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: Reason: Input dispatching timed out (AppWindowToken{da8f666
token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window
has focus but there is a focused application that may eventually add a window when it finishes starting up.)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0 (Load表明是1分钟,5分钟,15分钟CPU的负载)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: CPU usage from 20ms to 20286ms later (2018-07-20 15:36:36.170 to 2018-07-20 15:36:56.436):
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   42% 6774/pressure: 41% user + 1.4% kernel / faults: 168 minor
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   34% 142/kswapd0: 0% user + 34% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   31% 1520/system_server: 13% user + 18% kernel / faults: 58724 minor 1585 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   13% 29901/com.ss.android.article.news: 7.7% user + 6% kernel / faults: 56007 minor 2446 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   13% 32638/com.android.quicksearchbox: 9.4% user + 3.8% kernel / faults: 48999 minor 1540 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   11% (CPU的使用率)1480/com.xxxx.moblie: 5.2%(用户态的使用率)
 user + (内核态的使用率) 6.3% kernel / faults: 76401 minor 2422 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   8.2% 21000/kworker/u16:12: 0% user + 8.2% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   0.8% 724/mtd: 0% user + 0.8% kernel / faults: 1561 minor 9 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   8% 29704/kworker/u16:8: 0% user + 8% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   7.9% 24391/kworker/u16:18: 0% user + 7.9% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   7.1% 30656/kworker/u16:14: 0% user + 7.1% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   7.1% 9998/kworker/u16:4: 0% user + 7.1% kernel

我已经在log 中标志了相关的含义。com.xxxx.moblie 占用了11%的CPU，其实这并不算多。现在的手机基本都是多核CPU。假如你的CPU是4核，那么上限是400%，以此类推。

既然不是CPU负载的原因，那么到底是什么原因呢？这时就要看我们的终极大杀器——traces.txt。

二、 traces.txt 日志分析

当APP不响应、响应慢了、或者WatchDog的监视没有得到回应时，系统就会dump出一个traces.txt文件，存放在文件目录:/data/anr/traces.txt，通过traces文件,我们可以拿到线程名、堆栈信息、线程当前状态、binder call等信息。

通过adb命令拿到该文件：adb pull /data/anr/traces.txt

trace: Cmd line:com.xxxx.moblie

"main" prio=5 tid=1 Runnable
  | group="main" sCount=0 dsCount=0 obj=0x73bcc7d0 self=0x7f20814c00
  | sysTid=20176 nice=-10 cgrp=default sched=0/0 handle=0x7f251349b0
  | state=R schedstat=( 0 0 0 ) utm=12 stm=3 core=5 HZ=100
  | stack=0x7fdb75e000-0x7fdb760000 stackSize=8MB
  | held mutexes= "mutator lock"(shared held)
  // java 堆栈调用信息,可以查看调用的关系，定位到具体位置
  at ttt.push.InterceptorProxy.addMiuiApplication(InterceptorProxy.java:77)
  at ttt.push.InterceptorProxy.create(InterceptorProxy.java:59)
  at android.app.Activity.onCreate(Activity.java:1041)
  at miui.app.Activity.onCreate(SourceFile:47)
  at com.xxxx.moblie.ui.b.onCreate(SourceFile:172)
  at com.xxxx.moblie.ui.MainActivity.onCreate(SourceFile:68)
  at android.app.Activity.performCreate(Activity.java:7050)
  at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1214)
  at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2807)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2929)
  at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1618)
  at android.os.Handler.dispatchMessage(Handler.java:105)
  at android.os.Looper.loop(Looper.java:171)
  at android.app.ActivityThread.main(ActivityThread.java:6699)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:246)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:783)

我详细解析一下traces.txt里面的一些字段，看看它到底能给我们提供什么信息.

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核的序号。

Java的堆栈信息是我们最关心的，它能够定位到具体位置。从上面的traces,我们可以判断ttt.push.InterceptorProxy.addMiuiApplicationInterceptorProxy.java:77 导致了com.xxxx.moblie发生了ANR。这时候可以对着源码查看，找到出问题，并且解决它。

总结一下这分析流程：首先我们搜索am_anr，找到出现ANR的时间点、进程PID、ANR类型、然后再找搜索PID，找前5秒左右的日志。过滤ANR IN 查看CPU信息，接着查看traces.txt，找到java的堆栈信息定位代码位置，最后查看源码，分析与解决问题。这个过程基本能找到发生ANR的来龙去脉。

本文摘抄于《Android ANR日志分析指南》，感谢作者贡献，写得很全。

历史上的今天

《2023: Android悬浮球(0条评论)》

# Android # am_anr # Android # ANR # ANR IN # Application Not Responding # traces.txt

版权声明 1、本站名称： 91易搜
2、本站网址： 91es.com 和 3xcn.com
3、本站内容：部分来源于网络，仅供学习和参考，若侵权请留言
3、本站申明：个人流水账日记，内容并不保证有效

暂无评论

暂无评论...

随机推荐

周国平：心静是一种境界

木心：至少，每天要看书

龙应台：幸福就是……

adb

Git

NDK

Web

顾城：远和近

你一会看我一会看云我觉得你看我时很远你看云时很近

诗歌

3年前 (2021)

sleep和wait的区别简介

前言记录一下sleep和wait的区别正文wait必须搭配synchronize一起使用，而sleep不需要；进入wait状态的线程能够被 notify 和 notifyAll 线程唤醒，而 sleep 状态的线程不能被 notify 方法唤醒；wait 通常有条件地执行，线程...

小知识

2年前 (2023)

Android音乐频谱显示

前言本文抄的，音乐频谱相关，想单独记录于此，方便自己查阅和回顾。具体可以看：https://github.com/wanliLiu/androidequalizerPS: 图片截图Github上的正文VisualizerWaveView2.java图中第一个public cla...

Android 小知识

1年前 (2023)

《MySQL基础教程》笔记6

前言主要是记录一下update和delete命令的使用。根据《MySQL基础教程-西泽梦路》学习，简单的做一下笔记。记录于此，方便自己回忆。正文我这以Window版的phpstudy软件验证。需要进入这个目录，才可以使用mysql命令D:\phpstudy_pro\Extensions...

Web

11个月前

朱自清：冬天

说起冬天，忽然想到豆腐。是一“小洋锅”（铝锅）白煮豆腐，热腾腾的。水滚着，像好些鱼眼睛，一小块一小块豆腐养在里面，嫩而滑，仿佛反穿的白狐大衣。锅在“洋炉子”（煤油不打气炉）上，和炉子都熏得乌黑乌黑，越显出豆腐的白。这是晚上，屋子老了，虽点着“洋灯”，也还是阴暗。围着桌子坐的是父亲跟我们哥儿三个。“洋...

散文

3年前 (2021)

Log工具类

抱歉，好久没更新了，主要是在折腾91易搜（直通车：https://www.91es.com/）。最近发现项目中很多都用重复的类，因此后续多整理一下常用的实用的工具类。或许以后直接复用即可。今天重新定义了一个Log工具类VLog。（这个网上一大把），直接上代码：public class...

Android Java

5年前 (2019)

[摘]Android ANR日志分析指南

目录

定义

ANR类型

1、KeyDispatchTimeout（常见）

2、BroadcastTimeout

3、ServiceTimeout

4：ContentProviderTimeout

ANR出现的原因

ANR案例分析过程

一、查看events_log

二、 traces.txt 日志分析

历史上的今天

相关文章

Android (/sys/路径)属性文件节点值的读写

[摘]Android ANR日志分析指南之实例解析

暂无评论

随机推荐

顾城：远和近

sleep和wait的区别简介

Android音乐频谱显示

《MySQL基础教程》笔记6

朱自清：冬天

Log工具类

目录

定义

ANR类型

1、KeyDispatchTimeout（常见）

2、BroadcastTimeout

3、ServiceTimeout

4：ContentProviderTimeout

ANR出现的原因

ANR案例分析过程

一、 查看events_log

二、 traces.txt 日志分析

历史上的今天

相关文章

Android (/sys/路径)属性文件节点值的读写

[摘]Android ANR日志分析指南之实例解析

随机推荐

一、查看events_log