Android性能优化之ANR

2021-02-15 本文已影响0人 ying1229

ANR是什么

ANR全称为Application Not Responding,意为应用程序无响应，当应用的主线程被长时间阻塞时会触发这个问题，在日常开发或者使用手机时，或多或少都会遇到下面这个对话框，点击OK，APP将会被强行退出：

image.png

此时如果查看log，一般可以发现导致此问题的蛛丝马迹：

image.png

例如上图，可以很清晰的看到发生了ANR的原因是用户的输入事件未得到及时处理，并且详细日志存储到了/data/data/traces.txt文件中。

产生原因

只有当应用的主线程响应超时才会触发ANR，根据不同的情况，超时时间也有所区别：

KeyDisptachTimeout，最常见的异常类型，原因是View的按钮或者触摸事件在5秒内未响应，要产生这种超时，最少有两个输入事件，首先第一个输入事件A系统将其分发给用户正在操作的APP，然后如果此时再产生一个输入事件B，发现A在0.5秒内未处理完，系统会设置一个5秒的定时器，5秒之后如果A事件仍未处理完成，则触发ANR
BroadcastTimeout，由于BroadcastReceiver的onReceiver方法运行在主线程中，如果该方法在10秒内未处理完，则触发ANR
ServiceTimeout，比较少见，原因是Service的生命周期方法在20秒内未处理完成

典型场景

应用在主线程进行耗时操作，例如大量缓慢的I/O操作、长时间复杂的计算。
与另一个进程在进行binder通信，该进程未及时返回
主线程处于阻塞状态，等待其他线程释放某个锁
主线程处于死锁状态

如何检测

为了将问题尽量提前暴露在开发和测试阶段，可以通过一些简单的配置和工具来进行检测，提前发现问题，从而有效的避免线上ANR的产生。

严格模式-StrictMode

StrictMode是Android SDK提供的用来检测代码中是否有I/O或者内存方面违规操作的工具类，详细API可参考官方文档，一般需要在Application或者Lancher Activity的onCreate方法中开启，需要注意的是，只能在开发版本中使用，release版本不能使用严格模式

if (BuildConfig.DEBUG){
    // 开启所有线程策略
    StrictMode.setThreadPolicy(StrictMode.ThreadPolicy.Builder().detectAll().penaltyLog().build())
    // 开启所有虚拟机策略
    StrictMode.setVmPolicy(StrictMode.VmPolicy.Builder().detectAll().penaltyLog().build())
}

其中线程策略主要监控一些发生在主线程中的I/O和耗时操作：

detectDiskReads：检查是否有磁盘读操作
detectDiskWrites：检查是否有磁盘写操作
detectNetwork：检查是否有网络操作
detectAll：开启所有支持的检查项目

虚拟机策略主要监控内存问题：

detectLeakedSqlLiteObjects：检查是否存在Sqlite对象泄漏
detectLeakedClosableObjects：检查是否存在未关闭的Closable对象
detectActivityLeaks：检查是否存在Activity泄漏
detectAll：开启所有支持的检查项目

当开启了严格模式之后，如果在代码中出现了被监控的违规操作之后，系统就会按照上面配置的提醒方式发出警告，在上面的示例中配置的是penaltyLog，表示出现问题输出日志到logcat，同时我们也可以根据需求自己配置其他的提醒方式，例如直接crash、弹窗、回调指定方法等。

当配置的是penaltyLog时，出现了被监控的违规操作后，会出现如下日志：

StrictMode

可以看到日志中详细的列出了在 AnrActivity的第28行，在主线程中有一个读磁盘的操作，耗时29ms。

启用后台 ANR 对话框

bg_anr

对于BroadcastTimeout，只有在设备的开发者选项中启用了显示所有 ANR 时，Android 才会针对花费过长时间处理广播消息的应用显示 ANR 对话框。因此，在开发测试的过程中最好将这个设置打开，以便于充分的暴露问题。

获取ANR详细日志

系统会在遇到 ANR 时存储跟踪信息。在较低的操作系统版本中，设备上只有一个 /data/anr/traces.txt 文件。在较新的操作系统版本中，有多个 /data/anr/anr_* 文件，可以通过adb命令或者AS的Device File Explorer功能将这个文件导入到PC中进行分析。：

ANRlog

如何定位与分析

首先通过以下代码制造一次ANR：

btn.setOnClickListener {
    synchronized(lock) {
        Log.d(TAG, "ANR caused by deadlock")
    }
}

var work = object : Thread() {
    override fun run() {
        synchronized(lock) {
            Log.d(TAG, "locked by ${currentThread()}")
            sleep(60 * 1000)
        }
    }
}
work.start()

代码逻辑很简单，首先在工作线程对lock进行加锁，然后工作线程休眠60秒，此时点击按钮尝试获取锁，由于锁已经被工作线程占用了，所以此时主线程进入阻塞等待状态，当等待超时后，就会触发ANR。

Logcat日志信息分析

首先看ANR触发时的logcat日志信息

ActivityManager: ANR in com.comoko.myapplication (com.comoko.myapplication/.anr.AnrActivity)
    PID: 6194
    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: 2.  Wait queue head age: 5645.9ms.)
    Load: 0.08 / 0.06 / 0.07
    CPU usage from 140282ms to 0ms ago (2021-02-16 22:10:25.805 to 2021-02-16 22:12:46.086):
      6.9% 1870/system_server: 3.4% user + 3.4% kernel / faults: 47281 minor
      4.2% 1723/surfaceflinger: 1.3% user + 2.8% kernel / faults: 158 minor
      2.5% 1610/android.hardware.sensors@1.0-service: 0% user + 2.4% kernel
      1.7% 1595/android.hardware.audio@2.0-service: 0.1% user + 1.6% kernel
      1.7% 1910/android.hardware.graphics.composer@2.1-service: 0.2% user + 1.5% kernel / faults: 23 minor
      1.5% 1614/audioserver: 0.8% user + 0.6% kernel / faults: 11 minor
      1.4% 5334/adbd: 0% user + 1.3% kernel / faults: 119518 minor
      1.4% 2027/com.android.systemui: 0.9% user + 0.4% kernel / faults: 259 minor
      0.9% 2586/com.android.launcher3: 0.6% user + 0.2% kernel / faults: 3178 minor
      0.8% 5625/transport: 0.5% user + 0.2% kernel
      0.4% 2176/com.android.phone: 0.2% user + 0.2% kernel / faults: 214 minor 2 major
      0.3% 1539/logd: 0.2% user + 0.1% kernel / faults: 10 minor
      0.2% 4932/kworker/u8:2: 0% user + 0.2% kernel
      0.1% 7/rcu_preempt: 0% user + 0.1% kernel
      0.1% 5734/kworker/0:2: 0% user + 0.1% kernel
      0.1% 1736/statsd: 0% user + 0% kernel
      0.1% 5928/kworker/u8:1: 0% user + 0.1% kernel
     +0% 6105/kworker/u8:0: 0% user + 0% kernel
     +0% 6129/kworker/1:2: 0% user + 0% kernel
     +0% 6191/logcat: 0% user + 0% kernel
     +0% 6194/com.comoko.myapplication: 0% user + 0% kernel
    4.2% TOTAL: 1.8% user + 2.2% kernel + 0% iowait + 0% softirq
    CPU usage from 24ms to 300ms later (2021-02-16 22:12:46.111 to 2021-02-16 22:12:46.387):
      24% 1870/system_server: 0% use

可以看到，logcat日志中的信息主要包含以下内容：

发生ANR的进程名及id：com.comoko.myapplication，PID: 6194
发生ANR的类名及包名：com.comoko.myapplication/.anr.AnrActivity
发生ANR的原因：Input dispatching timed out
系统CPU占用情况：.2% TOTAL: 1.8% user + 2.2% kernel + 0% iowait + 0% softirq

traces文件信息分析

通过logcat可以大概了解到ANR发生的原因、类，以及当时的CPU占用情况，但是不足以定位到具体的代码位置，为了进一步的分析问题发生原因，我们需要分析上一小节中获取到的ANR详细日志，这个日志一般会比较庞大，不过我们只需关心与我们相关的即可，通过第一步对logcat日志的分析，我们知道了发生ANR的粗略信息，例如进程名称和id等，通过在ANR的详细日志中搜索相关信息，可以很快的找到与我们有关的信息，例如下面这个日志：

----- pid 6194 at 2021-02-16 22:12:46 -----
Cmd line: com.comoko.myapplication
Build fingerprint: 'Android/sdk_phone_x86_64/generic_x86_64:9/PSR1.180720.012/4923214:userdebug/test-keys'
ABI: 'x86_64'
Build type: optimized
Zygote loaded classes=10642 post zygote classes=358
Intern table: 74152 strong; 365 weak
JNI: CheckJNI is on; globals=600 (plus 22 weak)
...
Heap: 35% free, 5MB/8MB; 56540 objects
...
DALVIK THREADS (14):

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x750fda08 self=0x7a3186014c00
  | sysTid=6194 nice=-10 cgrp=default sched=0/0 handle=0x7a320b7e2548
  | state=S schedstat=( 1038269434 221502550 503 ) utm=78 stm=25 core=0 HZ=100
  | stack=0x7ffec331d000-0x7ffec331f000 stackSize=8MB
  | held mutexes=
  at com.comoko.myapplication.anr.AnrActivity$onCreate$1.onClick(AnrActivity.kt:32)
  - waiting to lock <0x0aab8a86> (a java.lang.Object) held by thread 13
  at android.view.View.performClick(View.java:6597)
  at android.view.View.performClickInternal(View.java:6574)
  at android.view.View.access$3100(View.java:778)
  at android.view.View$PerformClick.run(View.java:25885)
  at android.os.Handler.handleCallback(Handler.java:873)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:193)
  at android.app.ActivityThread.main(ActivityThread.java:6669)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)
...

可以看到这里面能帮助定位的相关信息有：

发生ANR的进程id及时间：pid 6194 at 2021-02-16 22:12:46
CPU架构：x86_64
堆内存信息：Heap: 35% free, 5MB/8MB; 56540 objects
主线程基本信息：名称（"main"），优先级（ prio=5 ），线程锁id （tid=1），线程状态（Blocked-阻塞）
主线程详细信息
线程堆栈信息，从中可以看到这次的ANR是由于等待锁导致的，这个锁被id为13的线程持有了：

at com.comoko.myapplication.anr.AnrActivity$onCreate$1.onClick(AnrActivity.kt:32)
  - waiting to lock <0x0aab8a86> (a java.lang.Object) held by thread 13

然后我们继续通过id=13去在文件内进行全局搜索，可以很容易的找到以下信息：

"Thread-2" prio=5 tid=13 Sleeping
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x1544f4a8 self=0x7a31861fdc00
  | sysTid=6219 nice=0 cgrp=default sched=0/0 handle=0x7a316e5014f0
  | state=S schedstat=( 7782128 9870407 7 ) utm=0 stm=0 core=3 HZ=100
  | stack=0x7a316e3fe000-0x7a316e400000 stackSize=1041KB
  | held mutexes=
  at java.lang.Thread.sleep(Native method)
  - sleeping on <0x08a5c912> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:373)
  - locked <0x08a5c912> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:314)
  at com.comoko.myapplication.anr.AnrActivity$onCreate$work$1.run(AnrActivity.kt:41)
  - locked <0x0aab8a86> (a java.lang.Object)

可以看到id为13的线程确实持有了主线程等待的锁0x0aab8a86，并且状态是Sleeping，至此一次ANR的分析基本结束。

参考文档

开发者指南-ANR

《Android高级进阶》