[关闭]
@TryLoveCatch 2022-05-18T03:40:44.000000Z 字数 15313 阅读 1419

Android知识体系之异常处理-ANR

Android知识体系

ANR介绍

ANR(Application Not Responding)，应用程序无响应，会严重影响用户体验。ANR的直观体验是用户在操作APP的过程中，感觉界面卡顿，如果 Android应用的界面线程处于阻塞状态的时间过长，会触发“应用无响应”(ANR) 错误，如下图所示，ANR 对话框会为用户提供强行退出应用的选项

首先，我们再来回顾一下ANR的几种常见的类型，如下所示：

Service 与 Bradcast 只会打印 trace 信息，不会提示用户 ANR 弹窗，大部分可感知的 ANR 都是由于 InputEvent。

ANR执行流程

原理

老师给我布置了个作业，要求我10分钟内完成，他说10分钟后再来检查。

但是，这里有个问题，假如我5分钟就写完了作业，是不是可以主动去告诉老师，而不是让他再多等5分钟呢？
当然可以！
这样就可以提前结束本次等待过程，大大节省时间从而提高效率。

上述过程就简单的模拟了ANR的实现原理，更术语的说法如下。

ANR的检测逻辑有两个参与者:观测者A和被观测者B。

当然，A和B这两者是不在同一个线程中的。

由于A和B是在不同线程中的，所以B即使死循环，也不会影响C的检测过程。
如果是同一个线程，B如果陷入死循环，那么C永远都执行不到了，还检测个毛。

所以，我们可以将ANR更精炼的总结为: 埋雷、拆雷和爆雷。

InputEvennt

InputEvennt不同于其他，它的 ANR 触发需要下一次输入，也很容易理解，上一次事件在处理中，虽然可能超时，但是下一次事件还没到来，如果下一次输入事件到来，则检测上一次事件是否超时。

其他

分析

  1. "main" prio=5 tid=1 Native
  2.   | group="main" sCount=1 dsCount=0 obj=0x757855c8 self=0xb4d76500
  3.   | sysTid=3276 nice=0 cgrp=default sched=0/0 handle=0xb6ff5b34
  4.   | state=S schedstat=( 50540218363 186568972172 209049 ) utm=3290 stm=1764 core=3 HZ=100
  5.   | stack=0xbe307000-0xbe309000 stackSize=8MB
  6.   | held mutexes=
  7.   kernel: (couldn't read /proc/self/task/3276/stack)
  8.   native: #00 pc 0004099c  /system/lib/libc.so (__epoll_pwait+20)
  9.   native: #01 pc 00019f63  /system/lib/libc.so (epoll_pwait+26)
  10.   native: #02 pc 00019f71  /system/lib/libc.so (epoll_wait+6)
  11.   native: #03 pc 00012ce7  /system/lib/libutils.so (_ZN7android6Looper9pollInnerEi+102)
  12.   native: #04 pc 00012f63  /system/lib/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+130)
  13.   native: #05 pc 00086abd  /system/lib/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+22)
  14.   native: #06 pc 0000055d  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+96)
  15.   at android.os.MessageQueue.nativePollOnce(Native method)
  16.   at android.os.MessageQueue.next(MessageQueue.java:323)
  17.   at android.os.Looper.loop(Looper.java:138)
  18.   at android.app.ActivityThread.main(ActivityThread.java:5528)
  19.   at java.lang.reflect.Method.invoke!(Native method)
  20.   at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:740)
  21.   at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:630)

当然这种情况很有可能是由于该进程的其他线程消耗掉了CPU资源，这就需要分析其他线程的trace以及ANR前后该进程自己输出的log了。

ChkBugReport

https://blog.csdn.net/gjsisi/article/details/12105145?utm_medium=distribute.pc_relevant.none-task-blog-BlogCommendFromMachineLearnPai2-2.nonecase&depth_1-utm_source=distribute.pc_relevant.none-task-blog-BlogCommendFromMachineLearnPai2-2.nonecase

  1. adb bugreport /Users/xxx/

ANR reason主要有以下几类：

监测方案

BlockCanary

BlockCanary是国内开发者 markzhai 开发的一款非侵入式的轻量性能监控组件，在 Github 上有接近 4000 star，可以检测主线程上的各种卡顿问题，并提供各种堆栈信息。

原理

BlockCanary — 轻松找出Android App界面卡顿元凶

利用了Android 原生 Looper.loop 中的一个 log 打印逻辑。

主要代码如下：

  1.  public static void loop() {
  2.     final Looper me = myLooper();
  3.     if (me == null) {
  4.         throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");
  5.     }
  6.     final MessageQueue queue = me.mQueue;
  8.     for (;;) {
  9.         Message msg = queue.next(); // might block
  10.         if (msg == null) {
  11.             // No message indicates that the message queue is quitting.
  12.             return;
  13.         }
  15.         // This must be in a local variable, in case a UI event sets the logger
  16.         final Printer logging = me.mLogging;
  17.         if (logging != null) {
  18.             logging.println(">>>>> Dispatching to " + msg.target + " " +
  19.                     msg.callback + ": " + msg.what);
  20.         }
  21.         try {
  22.             msg.target.dispatchMessage(msg);
  23.         } finally {
  24.         }
  25.         if (logging != null) {
  26.             logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
  27.         }
  28.     }
  29. }

关键是这两句：

  1. logging.println(">>>>> Dispatching to " + msg.target + " " + msg.callback + ": " + msg.what);
  2. logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);

通过Looper提供的接口设置logging：

  1. Looper.getMainLooper().setMessageLogging(mainLooperPrinter);

在mainLooperPrinter中判断start和end，来获取主线程dispatch该message的开始和结束时间，并判定该时间超过阈值(如2000毫秒)为主线程卡慢发生，并dump出各种信息，提供开发者分析性能瓶颈。

  1. @Override
  2. public void println(String x) {
  3.     if (!mStartedPrinting) {
  4.         mStartTimeMillis = System.currentTimeMillis();
  5.         mStartThreadTimeMillis = SystemClock.currentThreadTimeMillis();
  6.         mStartedPrinting = true;
  7.     } else {
  8.         final long endTime = System.currentTimeMillis();
  9.         mStartedPrinting = false;
  10.         if (isBlock(endTime)) {
  11.             notifyBlockEvent(endTime);
  12.         }
  13.     }
  14. }
  16. private boolean isBlock(long endTime) {
  17.     return endTime - mStartTimeMillis > mBlockThresholdMillis;
  18. }

优缺点

BlockCanary改进版(闲鱼)

https://developer.aliyun.com/article/782573

原理


在 print 方法中时，取消上一次异步线程延迟任务，重新触发一次延迟任务）。若 UI Looper 任务发生卡顿，则延迟任务被执行，且在卡顿期间的获取主线程堆栈信息，之后在下一次 print 方法被执行的时候，若确认发生卡顿，则可把主线程堆栈信息当做卡顿堆栈记录上报。

优缺点

缺点
  1. logging.println(">>>>> Dispatching to " + msg.target + " " +
  2.                     msg.callback + ": " + msg.what);

在线上环境，大部分场景下并不会发生卡顿，但卡顿检测 SDK 会一直执行。可以发现 app 每一帧时间(16.6ms)，UI Looper 中的任务会执行多次，最终产生大量的无效字符串拼接操作和大量小对象碎片。

改进

使用 Android 帧回调代替 Looper Task 方案，同时满足以上 2 个条件：

此外，还有一个优点：

为避免 BlockCanary 方案延迟任务触发和取消的频率过高的问题，仅在帧回调处记录时间戳，不再取消延迟任务，但在延迟任务执行时判断是否发生卡顿，同时记录主线程堆栈。

假设 500ms 以上为卡顿，整体方案流程图如下：

定义 5s 以上卡顿为 ANR，为检测 ANR，同样通过 500ms 卡顿检测，并做卡顿堆栈聚合，当连续发生卡顿大于 5s 且堆栈信息不变，则认为发生 ANR。发生 ANR 时，记录当前设备 CPU 负载等信息。

优点

ANR-WatchDog

https://juejin.cn/post/6844904066259091469

原理

ANR-WatchDog 是参考 Android WatchDog 机制（com.android.server.WatchDog.java）起个单独线程向主线程发送一个变量 +1 操作，自我休眠自定义 ANR 的阈值，休眠过后判断变量是否 +1 完成，如果未完成则告警。

优缺点

优点
缺点

SafeLooper

SafeLooper是个比较新奇的思路，本身就是一个堵塞的消息，在自己内部进行消息的处理，通过反射接管主线程Looper的功能。

原理

也可以参考这里。

优缺点

FileObserver

原理

当 ANR 发生的时候，我们是可以通过监听/data/anr 文件夹的写入情况来判断是否发生了 ANR，看起来这是一个不错的时机。需要注意的是，所有应用发生 ANR 的时候都会进行回调，因此需要做一些过滤与判断，如包名、进程号等。

优缺点

优点
缺点

最大的困难是兼容性问题，这个方案受限于Android系统的SELinux机制，5.0以后基本已经使低权限应用无法监听到Trace文件，但是可以在开发内测阶段通过root手机修改app对应的te文件提权进行监控。

获取日志

https://droidyue.com/blog/2021/03/07/view-android-anr-stacktrace/

xCrash

微信Matrix

常见的ANR

主线程耗时操作

比如网络访问、访问数据库、文件读写、频繁的大量的计算赋值逻辑，这些都是常见的ANR原因，具体根据ANR的Trace文件调用堆栈信息可以直接看出来，这边不再赘述。

以上的ANR一般使用异步的方式解决，当然不是简单的new一个线程，最好根据业务场景以及频率来决定，Android常用的异步操作有AsyncTask，IntentService，线程池(官方四种或自定义)，最好用一个线程池管理操作线程，不建议每次直接new一个线程。相关阅读见Android 子线程更新UI详解。

CPU过高

比如下面这份ANR日志信息，CPU数值异常偏高到186%，导致CPU过高的原因可能是频繁地IO读写，频繁调用耗时JNI接口。

  1. ActivityManager: ANR in com.autonavi.amapauto (com.autonavi.amapauto/.MainMapActivity)
  2. ActivityManager: PID: 7321
  3. ActivityManager: Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 5. Wait queue head age: 5765.8ms.)
  4. ActivityManager: Load: 16.72 / 11.58 / 8.91
  5. ActivityManager: CPU usage from 0ms to 13484ms later:
  6. ActivityManager: 186% 7321/com.autonavi.amapauto: 105% user + 80% kernel / faults: 2474 minor 3 major
  7. ActivityManager: 49% 620/system_server: 22% user + 26% kernel / faults: 2787 minor
  8. ActivityManager: 30% 1172/com.tencent.wecarspeech: 23% user + 7.2% kernel / faults: 3955 minor 2 major
  9. ActivityManager: 11% 1536/com.android.bluetooth: 7.1% user + 4.2% kernel / faults: 2405 minor 2 major
  10. ActivityManager: 4.7% 215/logd: 4.2% user + 0.4% kernel / faults: 13 minor
  11. ActivityManager: 4% 239/debuggerd: 0.6% user + 3.4% kernel / faults: 4584 minor 1 major
  12. ActivityManager: 6.8% 1296/com.android.phone: 4.1% user + 2.6% kernel / faults: 1230 minor
  13. ActivityManager: 6.4% 925/com.nforetek.bt: 2.6% user + 3.7% kernel / faults: 1097 minor 1 major
  14. ActivityManager: 5.8% 7537/com.tencent.wecarnavi:wecarbase: 2.9% user + 2.8% kernel / faults: 1150 minor
  15. ActivityManager: 5.7% 7509/com.tencent.wecarnavi: 3% user + 2.6% kernel / faults: 951 minor
  16. ActivityManager: 4.6% 866/sdcard: 0% user + 4.5% kernel / faults: 1 minor
  17. ActivityManager: 4.3% 242/mediaserver: 3.2% user + 1.1% kernel
  18. ActivityManager: 3.7% 858/com.android.launcher: 2.7% user + 0.9% kernel / faults: 741 minor 1 major
  19. ActivityManager: 3.3% 792/gaei.cluster.service: 1.9% user + 1.4% kernel / faults: 908 minor
  20. ActivityManager: 2.8% 1125/com.tencent.wecarnews: 1.4% user + 1.4% kernel / faults: 477 minor
  21. ActivityManager: 2.7% 881/com.android.systemui: 1.5% user + 1.1% kernel / faults: 963 minor 2 major
  22. ActivityManager: 2.6% 8825/top: 0.8% user + 1.8% kernel
  23. ActivityManager: 2.3% 798/com.gaei.bt: 0.9% user + 1.4% kernel / faults: 846 minor
  24. ActivityManager: 2.1% 1101/com.tencent.wecarmusicp: 0.7% user + 1.4% kernel / faults: 42 minor
  25. ActivityManager: 2.1% 7744/com.autonavi.amapauto:push: 1.1% user + 1% kernel / faults: 30916 minor
  26. ActivityManager: 1.1% 1269/com.gaei.settings: 0.5% user + 0.5% kernel / faults: 955 minor
  27. ActivityManager: 1.5% 110/mmcqd/3: 0% user + 1.5% kernel
  28. ActivityManager: 0.8% 833/gaei.reverse: 0.4% user + 0.3% kernel / faults: 826 minor
  29. ActivityManager: 0.7% 5949/logcat: 0.4% user + 0.3% kernel
  30. ActivityManager: 1.2% 803/gaei.thirdparty.media.adapter: 0.7% user + 0.5% kernel / faults: 654 minor
  31. ActivityManager: 0.6% 998/gaei.cluster: 0.3% user + 0.3% kernel / faults: 759 minor
  32. ActivityManager: 0.6% 1279/com.gaei.gaeihvsmsettings: 0.3% user + 0.3% kernel / faults: 868 minor
  33. ActivityManager: 1.1% 233/surfaceflinger: 0.5% user + 0.5% kernel
  34. ActivityManager: 0.5% 838/gaei.lockscreen: 0.3% user + 0.2% kernel / faults: 750 minor
  35. ActivityManager: 0.5% 964/gaei.ecallbcall: 0.2% user + 0.2% kernel / faults: 719 minor
  36. ActivityManager: 0.5% 1256/com.thundersoft.update: 0.3% user + 0.1% kernel / faults: 745 minor
  37. ActivityManager: 0.5% 1274/gaei.bluetooth: 0.2% user + 0.2% kernel / faults: 732 minor
  38. ActivityManager: 0.5% 1285/com.gaei.vehichesetting: 0.3% user + 0.1% kernel / faults: 786 minor
  39. ActivityManager: 0.5% 8916/kworker/0:2: 0% user + 0.5% kernel
  40. ActivityManager: 0.5% 2439/cn.gaei.appstore: 0.4% user + 0% kernel / faults: 60 minor
  41. ActivityManager: 0.3% 232/servicemanager: 0.1% user + 0.2% kernel
  42. ActivityManager: 0.2% 252/rild: 0% user + 0.2% kernel
  43. ActivityManager: 0.2% 2131/com.thundersoft.connectivity: 0.2% user + 0% kernel / faults: 133 minor
  44. ActivityManager: 0.2% 2153/com.excelfore.hmiagent: 0% user + 0.2% kernel / faults: 1779 minor
  45. ActivityManager: 0.1% 7383/com.autonavi.amapauto:locationservice: 0.1% user + 0% kernel / faults: 266 minor
  46. ActivityManager: 0.2% 7/rcu_preempt: 0% user + 0.2% kernel
  47. ActivityManager: 0% 7360/com.autonavi.amapauto:adiu: 0% user + 0% kernel / faults: 223 minor
  48. ActivityManager: 0.1% 8892/kworker/u8:0: 0% user + 0.1% kernel
  49. ActivityManager: 0% 1//init: 0% user + 0% kernel
  50. ActivityManager: 0% 3/ksoftirqd/0: 0% user + 0% kernel
  51. ActivityManager: 0% 107/debounce_task: 0% user + 0% kernel
  52. ActivityManager: 0% 108/irq/43-mm-irq-t: 0% user + 0% kernel
  53. ActivityManager: 0% 210/jbd2/mmcblk3p4-: 0% user + 0% kernel
  54. ActivityManager: 0% 237/netd: 0% user + 0% kernel / faults: 15 minor
  55. ActivityManager: 0% 244/smcd: 0% user + 0% kernel
  56. ActivityManager: 0% 248/system_setting_service: 0% user + 0% kernel
  57. ActivityManager: 0% 1087/com.trumpchi.assistant.app: 0% user + 0% kernel / faults: 2 minor
  58. ActivityManager: 0% 2009/com.thunderst.update: 0% user + 0% kernel / faults: 17 minor
  59. ActivityManager: 93% TOTAL: 51% user + 41% kernel + 0.1% iowait + 0.3% softirq
  60. ActivityManager: CPU usage from 11778ms to 12377ms later:
  61. ActivityManager: 46% 620/system_server: 23% user + 23% kernel
  62. ActivityManager: rename tracefile/data/anr/traces.txt to /data/anr/traces_com.autonavi.amapauto_20190906_110548.txt
  63. 在CPU异常偏高的情况下，系统记录的ANR Trace文件里面不会有ANR应用的调用逻辑堆栈信息，比如只有下面的“main”信息。
  65. "main" prio=5 tid=1 Native
  66.  | group="main" sCount=1 dsCount=0 obj=0x74030258 self=0xb4df6500
  67.  | sysTid=1336 nice=0 cgrp=default sched=0/0 handle=0xb6f90b34
  68.  | state=S schedstat=( 14858997090 10346952287 41860 ) utm=903 stm=582 core=1 HZ=100
  69.  | stack=0xbe7b2000-0xbe7b4000 stackSize=8MB
  70.  | held mutexes=
  71.  kernel: (couldn't read /proc/self/task/1336/stack)
  72.  native: #00 pc 00040d04 /system/lib/libc.so (__epoll_pwait+20)
  73.  native: #01 pc 0001a17f /system/lib/libc.so (epoll_pwait+26)
  74.  native: #02 pc 0001a18d /system/lib/libc.so (epoll_wait+6)
  75.  native: #03 pc 00012cfb /system/lib/libutils.so (android::Looper::pollInner(int)+102)
  76.  native: #04 pc 00012f77 /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+130)
  77.  native: #05 pc 000807ad /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, _jobject*, int)+22)
  78.  native: #06 pc 00008ebd /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+96)
  79.  at android.os.MessageQueue.nativePollOnce(Native method)
  80.  at android.os.MessageQueue.next(MessageQueue.java:323)
  81.  at android.os.Looper.loop(Looper.java:135)
  82.  at android.app.ActivityThread.main(ActivityThread.java:5487)
  83.  at java.lang.reflect.Method.invoke!(Native method)
  84.  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
  85.  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)

这个时候应该根据ANR的时间点分析应用的日志文件，往前10s看应用调用逻辑信息，分析下哪部分逻辑模块的日志输出过于频繁。但有一个例外情况，如果问题出在应用日志输出写文件过于频繁，则需要精简下日志，去除不必要的日志信息。过于频繁的日志输出占用IO带宽，竞争CPU资源，特别是在设备IO带宽偏低的情况下，很容易影响到。

如果是耗时JNI接口频繁调用导致的ANR，可根据场景规避减少JNI接口的调用，遇到过性能差的设备即使是在JNI层调用setInt赋值一个参数都会耗时50ms的情况。

卡在IO读写

一般是文件操作导致，比如下面的日志信息：

  1. ANRManager: 100% TOTAL: 2% user + 2.1% kernel + 95% iowait + 0.1% softirq

iowait占比95%，分析ANR Trace文件，通过应用包名过滤调用堆栈信息，或者在ANR时间点往前看10s应用日志，看看当时做什么文件操作，一般也是用异步的方式来解决这个问题。

死锁或锁等待

对于这种问题，一般会尝试将锁改为超时锁，比如lock的trylock，超时会自动释放锁，避免一直持有锁的情况发生。

主线程Binder调用等待超时

主线程执行了Binder请求，对端迟迟未返回很容易出现这个问题，一般使用异步的方法解决。

Binder线程池被占满

系统对每个进程最多分配15个Binder线程，如果另一个进程发送太多重复Binder请求，那么就会导致接收端Binder线程被占满，从而处理不了其它的Binder请求。

判断Binder是否用完，可以在trace中搜索关键字”binder_f”，如果搜索到则表示已经用完，接着分析日志看是谁一直在消耗Binder或者是有死锁发生。

解决的方法就是降低极短时间内大量Binder请求，比如在发送BInder请求的函数中做时间差过滤，限定在500ms内最多执行一次。

参考

Android ANR的设计原理
Qtest测试之道 Android ANR 监测方案解析
Android性能优化杂谈-如何监控和解决ANR问题？
今日头条 ANR 优化实践系列 - 设计原理及影响因素

微信APM Matrix解析
深入探索Android卡顿优化（下）

性能优化集合
彻底理解安卓应用无响应机制

Android ANR日志分析指南

添加新批注
在作者公开此批注前，只有你和作者可见。
回复批注