Android 进阶——Framework 核心ANR（ Applicatipon No Response）机制设计思想详解

Posted CrazyMo_

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了Android 进阶——Framework 核心ANR（ Applicatipon No Response）机制设计思想详解相关的知识，希望对你有一定的参考价值。

文章大纲

引言

一、一些与ANR有关的计算机理论

在android 的开发性能优化领域常常会和trace.txt文件打交道，里面包含一些线程的堆栈信息：Blocked、TimedWaiting、mutexes等等关键字，那么这些信息是想要告诉我们什么呢？在本文中，我们将从简要介绍一下相关计算机知识。

1、互斥锁（Mutexes）概述

在计算机科学中，互斥是一种机制，通过互斥对象是在代码的关键部分期间，使得一次只允许一个线程访问共享资源，而在Java中被称为Lock。互斥机制通常依赖两类方法：获取和释放(有时称为lock和unlock)。操作系统内核保证，一旦一个线程成功地获得了锁，在第一个线程释放它之前，没有其他线程可以获得它，如果第二个线程尝试获取就会被阻塞住，直到这个锁再次可用。因此，如果所有线程都确保只在获取和释放调用之间使用共享资源，则保证它们会轮流使用该资源。

2、死锁（Deadlocks ）概述

虽然互斥对象在正确使用时非常强大，但它们确实有可能导致一个罕见的、难以捉摸的问题，即死锁。这通常发生在两个线程都试图获取另一个线程持有的互斥对象时，这将导致它们被永久阻塞。简而言之，如果两个线程之间都需要同时获取到两个或者多个共享资源才能正常工作，而当线程A持有了共享资源A正申请共享资源B，与此用时线程B持有共享资源B正申请共享资源A，但两个线程互不相让，最终就会进入死锁状态。在Android中线程对运行应用程序至关重要(如果其中一个线程是主线程)，它很可能导致ANR(应用程序不响应)和应用程序崩溃。

二、ANR 设计目的概述

Android 设计 ANR 的用意，是系统通过与之交互的组件(Activity，Service，Receiver，Provider、BroadcastReceiver)以及用户交互系统(InputEvent)进行超时监控，以判断应用进程(主线程)是否存在卡死或响应过慢的问题，就相当于是Android系统中的看门狗(watchdog)的设计思想。

三、Android 组件ANR超时机制

JVM Finalizer机制，当根可达性算法进行第一次检索完成后，并非所有不可达的对象都意味着即将消亡。因为当GC开始时会触发两次标记过程，第一次首先标记处没有必要执行finalize方法的对象，这部分对象被直接宣布“死刑”；而那些重写了finallize方法的对象则得到一次救赎的机会的，相当于是目前只是判了“死缓”，还有机会在finalize方法中重获新生（比如让他重新连上"GC"链），所以第二次标记才是真正执行“死刑”——真正开始回收不可达的对象。

1、Activity 切换处理超时

2、Broadcast 广播处理超时

com\\android\\server\\am\\ActivityManagerService.java

只有静态注册的广播和有序广播超时时才可能导致ANR，而动态注册的非有序广播并不会ANR 。因为广播发送时，会判断该进程是否存在，不存在则创建，创建进程的耗时也算在超时时间里。

只有当进程存在前台显示的Activity才会弹出ANR对话框，否则会直接杀掉当前进程 。

    // How long we allow a receiver to run before giving up on it.
    static final int BROADCAST_FG_TIMEOUT = 10*1000;
    static final int BROADCAST_BG_TIMEOUT = 60*1000;

  • 前台Broadcast：onReceiver在10S内没有处理完成发生ANR。

    发送时添加上前台广播标志 intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)即位前台广播

  • 后台Broadcast：onReceiver在60s内没有处理完成发生ANR。

logcat日志关键字：Timeout of broadcast BroadcastRecord

3、Service 服务处理超时

/base/services/core/java/com/android/server/am/ActiveServices.java

Service的onCreate()、onStartCommand()、onStart()、 onBind()、 onRebind(),、onTaskRemoved(),、onUnbind()、onDestroy()生命周期方法在主线程处理耗时任务超时可能导致ANR。

  // How long we wait for a service to finish executing.
    static final int SERVICE_TIMEOUT = 20*1000;

    // How long we wait for a service to finish executing.
    static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;

  • 前台Service在20s内没有处理完成发生ANR。

    即App处于用户态（即App中的某个Activity正处于前台、以Foreground Service 方式启动或者有前台广播正在执行）时正在运行的Service则为前台Service。

  • 后台Service在200s内没有处理完成发生ANR。

logcat日志关键字：Timeout executing service:/executing service XXX

4、ContentProvider 处理超时

ContentProvider publish在10S内没有处理完成发生ANR。

logcat日志关键字：timeout publishing content providers

5、Input 输入系统处理超时

KeyDispatchTimeout，InputDispatcher 分发keyEvent 到对应进程的Focused Window，当对应的Window 不存在、处于暂停态或者Input Chanel 占满、Input Chanel 未注册、渠道异常或5s内没有处理完这个keyEvent 就会导致ANR。简而言之，input事件在5S内没有处理完成导致ANR。

日志关键字：Input event dispatching timed out

6、Finalizer 处理超时

四、ANR的定位和排查

ANR的定位和排查是需要具体问题具体分析的，

1、 查看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 (AppWindowTokenda8f666 token=Token5501f51 ActivityRecord15c5c78 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 (AppWindowTokenda8f666 token=Token5501f51 ActivityRecord15c5c78 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。

2、 traces.txt 日志分析

当APP不响应、响应慢了、或者WatchDog的监视没有得到回应时，系统就会dump出一个traces.txt文件，存放在文件目录:/data/anr/traces.txt，通过traces文件，我们可以拿到线程名、堆栈信息、线程当前状态、binder call等信息。所以在定位ANR时，要特别注意“main”(tid=1)线程，它是处理UI操作的线程，大部分ANR总是由这个线程被阻塞或执行太多工作引起的。通过adb命令拿到该文件：adb pull /data/anr/traces.txt

有些ROM 可能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里面的一些字段，看看它到底能给我们提供什么信息.

mainmain标识是主线程，如果是线程，那么命名成“Thread-X”的格式,x表示线程id,逐步递增。
prio线程优先级,默认是5
tidtid本质上不是线程的id，是线程唯一标识ID
group是线程组名称
sCount该线程被挂起的次数
dsCount是线程被调试器挂起的次数
obj对象地址
self该线程Native的地址
sysTid线程号(主线程的线程号和进程号相同)
nice线程的调度优先级
sched分别标志了线程的调度策略和优先级
cgrp调度归属组
handle线程处理函数的地址。
state调度状态，（正常有 “R (running)”, “S (sleeping)”, “D (disk sleep)”, “T (stopped)”, “t (tracing stop)”, “Z (zombie)”, “X (dead)”, “x (dead)”, “K (wakekill)”, “W (waking)”,），通常一般的Process 处于的状态都是S (sleeping), 而如果一旦发现处于如D, T, Z (zombie) 等就要认真审查。
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的堆栈信息定位代码位置，最后查看源码，分析与解决问题。

3、bugreport 分析

执行adb bugreport 后会在当前路径下生成一个异常报告压缩包（保存着所有进程的堆栈快照），文件名以bugreport_开头的压缩包，里面包含所有进程的mountinfo、完整堆栈和内存信息等。

windows最好以管理员模式运行cmd

4、adb shell debuggerd -b pid 获取堆栈信息

五、ANR 典型日志

HeapTaskDaemon——GC的守护进程，为了脱敏隐藏了相关的库名和包名，还加了混淆。当然这些日志并不是一定会存在，总之别生搬硬套。

1、死锁

每个线程堆栈都包含一些信息可以检测死锁，线程的状态通常有：Runnable、Sleeping、Waiting、Native或Blocked，当ANR发生时，如果对应的线程已经处于Blocked，意味着被标记为Blocked的线程正试图获取什么互斥锁，以及持有该锁的线程的线程ID (tid)。然后，你可以向下滚动到列表中对应该线程的条目，如果你发现该线程也是Blocked，你可以查看它试图获取的互斥量以及哪个线程持有该互斥量。通常这是第一个线程，这意味着您可能已经检测到存在死锁。典型的日志如下：

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x7477dea0 self=0x5597d71b70
  | sysTid=25967 nice=-1 cgrp=top_visible sched=0/0 handleAndroid 进阶——系统启动之Framework 核心ActivitityManagerService服务启动


 Android 进阶——Framework核心 之Binder Java成员类详解


 Android 进阶——Framework核心 之Binder Java成员类详解


 Android 进阶——Framework 核心之Touch事件分发机制详细攻略


 Android 进阶——Framework 核心之Touch事件分发机制详细攻略


 Android 进阶——Framework 核心之Touch事件分发机制详细攻略