查找ANR异常

一、ANR异常解决方案

Android应用中出现ANR异常是一个耳熟能详的问题，出现ANR的原因是因为有一个方法很耗时，并且是在UI线程中调用了该方法导致的。在开发中，我比较少遇到，一般遇到了就是回想自己刚刚做了什么功能了才出现的，这样也容易找到原因，但是在我最近的一个项目中，运行后使用都是正常的，只是用着用着偶然就出现的ANR异常，这时我就不知道从何找起了，不知道是项目的哪个模块的哪个方法导致的ANR，我刚开始就是一个一个方法的打印运行时间，这样的效率太慢了，一个项目的方法何其多啊，很难找到真正耗时的那个方法。

其实在报出ANR异常的时候，在控制台会有信息输出的，从Log信息中可以看到系统把ANR的信息保存在/data/anr/traces.txt文件中了，有这个文件就可以分析出现ANR是哪个耗时方法导致的了。

1. 导出traces.txt：adb pull data/anr D:/test ，这个命令是把anr整个目录都导出到D盘的test目录中。网上有的文章说如果出现多次ANR会有多个traces.txt，但是在我的设备上，出现多次ANR也只会有一个traces.txt，且traces.txt中保存的是最近出现的那次ANR信息。
2. 打开traces.txt，在大概200行左右的地方就能看到报出ANR异常的方法是哪个了，如下：

      "main" prio=5 tid=1 Native
     | group="main" sCount=1 dsCount=0 obj=0x758cca10 self=0x7f7ee95a00
     | sysTid=14969 nice=-10 cgrp=default sched=0/0 handle=0x7f82db9a98
     | state=S schedstat=( 39182160268 4596760347 54475 ) utm=3593 stm=325 core=4 HZ=100
     | stack=0x7fe2848000-0x7fe284a000 stackSize=8MB
     | held mutexes=
     kernel: __switch_to+0x8c/0x98
     kernel: futex_wait_queue_me+0xd8/0x130
     kernel: futex_wait+0xec/0x1f8
     kernel: do_futex+0xdc/0x878
     kernel: SyS_futex+0x110/0x19c
     kernel: el0_svc_naked+0x24/0x28
     native: #00 pc 000000000001c16c  /system/lib64/libc.so (syscall+28)
     native: #01 pc 0000000000069134  /system/lib64/libc.so (_ZL33__pthread_mutex_lock_with_timeoutP24pthread_mutex_internal_tbPK8timespec+744)
     native: #02 pc 00000000002a1ad0  /data/app/cn.dazhou.railway.monitor-2/lib/arm64/libtinyWRAP.so (tsk_mutex_lock+28)
     at org.doubango.tinyWRAP.tinyWRAPJNI.InviteSession_hangup__SWIG_1(Native method)
     at org.doubango.tinyWRAP.InviteSession.hangup(InviteSession.java:55)
     at org.doubango.ngn.sip.NgnAVSession.hangUpCall(NgnAVSession.java:847)
     at cn.dazhou.railway.monitor.camera.SipVideoPresenterImpl.closeVideo(SipVideoPresenterImpl.kt:189)
     at cn.dazhou.railway.monitor.sip.video.VideoService.reCall(VideoService.kt:99)
     at cn.dazhou.railway.monitor.sip.video.VideoService$registerBroadcastReceiver$1.onReceive(VideoService.kt:62)
     at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:1122)
     at android.os.Handler.handleCallback(Handler.java:751)
     at android.os.Handler.dispatchMessage(Handler.java:95)
     at android.os.Looper.loop(Looper.java:154)
     at android.app.ActivityThread.main(ActivityThread.java:6121)
     at java.lang.reflect.Method.invoke!(Native method)
     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:889)
     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:779)
   

从异常信息中可以看到，这是libc.so中的函数很耗时导致的，而这个libc.so又是由libtinyWRAP.so调用，libtinyWRAP.so又由是InviteSession_hangup__SWIG_1()这个native函数调用的，这个函数又是由hangup()函数调用，嗯，非常棒，很容易就找到了那个耗时的方法了，我们把这个耗时的方法改成在子线程中调用即可。

在我的一个公司设备上是这样的，其他设备上不知道异常信息是不是也大概在这个位置，traces.txt中的内容非常多，大概9千行，我在一台公司设备上出现过两次ANR，每次都是不同方法导致的，但是异常信息大概都在200行的位置。如果在别的设备上不是在这个位置的话，如果找不到，可以直接搜索App的包名，如：cn.dazhou.railway.monitor，这样找起来就很快了，traces.txt中出现应用包名的地方也就几个地方而已。

二、模拟一个ANR异常

前面讲解了如何解决ANR异常，因为之前项目这出现了两次，有些内容也记不太清，我想搞清楚一点，于是就想到了自己模拟一个ANR异常不就行了吗，然后可以在各种手机上运行测试一下。

1. 创建一个全新的项目，界面如下：
   
   界面很简单，就一个按钮
2. 按钮单击事件如下：

   fun onClick(view: View) {
      Log.i("MainActivity", "准备在UI线程睡20秒钟")
      Thread.sleep(20 * 1000)
      Log.i("MainActivity", "大哥睡醒了！")
   }
   

   代码很简单，就是单击按钮的时候睡20秒钟

3. 单击“模拟一个ANR”按钮，此时查看控制台日志，如下：
   
   可以看到，睡了20秒，且睡醒了，并没有出现ANR异常，但是可以看到系统日志“Skipped 931 frames! The application may be doing too much work on its main thread.”,翻译成中文意思为“跳过931帧!应用程序可能在其主线程上做了太多的工作。”
4. 没有出现我们期待的ANR异常。我们再换一种操作：单击“模拟一个ANR”按钮，然后按返回按钮，会发现界面是卡住了，过一会就能看到ANR异常信息了（注：其实也可以连接按多次“模拟一个ANR”按钮也会出现ANR，如果只连按两次也不会出现），如下：

   I/MainActivity: 准备在UI线程睡20秒钟
   I/ViewRootImpl[MainActivity]: ANR Key Analyze: No Key event currently.
   I/ViewRootImpl[MainActivity]: ANR Key Analyze: Previeous Event null,finish at 1970-01-01 08:00:00.000
   I/ViewRootImpl[MainActivity]: ANR Motion Analyze: No motion event currently.
   I/ViewRootImpl[MainActivity]: ANR Motion Analyze: Previeous Event MotionEvent { action=ACTION_UP, actionButton=0, id[0]=0, x[0]=570.4718, y[0]=1084.4352, toolType[0]=TOOL_TYPE_FINGER, buttonState=0, metaState=0, flags=0x0, edgeFlags=0x0, pointerCount=1, historySize=0, eventTime=22612318, downTime=22612281, deviceId=3, source=0x1002 },finish at 2021-03-29 16:23:49.980
   I/art: Thread[3,tid=30975,WaitingInMainSignalCatcherLoop,Thread*=0x769708ca00,peer=0x12cb8430,"Signal Catcher"]: reacting to signal 3
   I/art: Wrote stack traces to '/data/anr/traces.txt'
   I/art: ::: a0ea219 68d8987 59e62c8 d53b473 319369c
   I/art: ::: 319369c bf90460 80f30d5 9e191c3 12eb0c5
   I/art: ::: 12eb0c5 645e477 d5adee8 5a158d4 a8b78e6
    。。。此处省略3百多行art日志
   I/art: ::: e1a50ed c1cc94e 39a7e6f fcc1cc4 2bcd093
   I/art: ::: 2bcd093 9da4924 647768f ac55f9f 8b1da17
   I/art: ::: 8b1da17 0 0 0 0
   I/art: ::: 0 0 9e92a074 1c087c29 ff56c79f
   I/MainActivity: 大哥睡醒了！
   I/Choreographer: Skipped 932 frames!  The application may be doing too much work on its main thread.
   

   从日志中可以看到“I/art: Wrote stack traces to ‘/data/anr/traces.txt’”，这告诉了我们anr异常保存的位置。这里的日志我省略了日志时间，从日志的时间看，从准备睡眠到出现ANR异常，大概是8秒钟时间。日志中间有3百多行的art日志信息，这里我做了省略处理，从日志可以看到，虽然出现了ANR，但是最终大哥还是睡醒了，App并没有崩溃，还是可以继承使用的，点击ANR对话框的“等待”按钮可以继承使用App，ANR异常对话框如下（注：ANR日志会比ANR对话框会早几秒钟出来）：
   
   点击“等待”按钮之后，界面停留在了我们的App上，按正常按返回的话，应该是退出当前App界面的，所以，当我们的程序在UI线程做耗时操作的时候，按键事件就被吃掉了。
5. 我们还可以使用ANRManager进行过滤，但是要去掉“Show only selected application"的限制，如下：
   
   日志内容如下：

   D/ANRManager: isANRFlowSkipped() AnrFlow = 0
   I/ANRManager: enableTraceLog: false
   I/ANRManager: enableBinderLog: false
   E/ANRManager: writeStringToFile error: /sys/kernel/debug/binder/transaction_log_enable java.io.FileNotFoundException: /sys/kernel/debug/binder/transaction_log_enable (Permission denied)
   I/ANRManager: startAsyncDump: AnrDumpRecord{ Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.) ProcessRecord{66566af 13102:cn.android666.anrdemo/u0a717} IsCompleted:false IsCancelled:false }
   I/ANRManager: dumpAnrDebugInfo begin: AnrDumpRecord{ Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.) ProcessRecord{66566af 13102:cn.android666.anrdemo/u0a717} IsCompleted:false IsCancelled:false }, isAsyncDump = false
   I/ANRManager: setZramTag: 6
   I/ANRManager: setZramMonitor: false
   I/ANRManager: dumpAnrDebugInfoLocked: AnrDumpRecord{ Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.) ProcessRecord{66566af 13102:cn.android666.anrdemo/u0a717} IsCompleted:false IsCancelled:false }, isAsyncDump = false
   D/ANRManager: file isn't exist
   I/ANRManager: START_ANR_DUMP_MSG: AnrDumpRecord{ Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.) ProcessRecord{66566af 13102:cn.android666.anrdemo/u0a717} IsCompleted:false IsCancelled:false }
   I/ANRManager: dumpAnrDebugInfo begin: AnrDumpRecord{ Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.) ProcessRecord{66566af 13102:cn.android666.anrdemo/u0a717} IsCompleted:false IsCancelled:false }, isAsyncDump = true
   I/ANRManager: setZramTag: 6
   I/ANRManager: setZramMonitor: false
   E/ANRManager: ANR in cn.android666.anrdemo (cn.android666.anrdemo/.MainActivity), time=26620676
       Reason: Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.)
   

这里也只贴了最前面的一些Log，可以看到：ANR in cn.android666.anrdemo (cn.android666.anrdemo/.MainActivity)，这表明ANR异常是在MainActivity这个类中引起，所以比较笨的办法也可以在这个类中看看哪个函数的调用是耗时的。还有Reason: Input dispatching timed out (Waiting to send key event，这说明了ANR的原因：输入分发超时，等待发送key事件，也就是我们按下返回键，这个事件要发送给主线程处理，但是此时我们的主线程在睡大觉，等了8秒钟主线程都没空处理，所以就报出ANR异常了。

6. 查找ANR异常最好的方式还是要看traces.txt，导出anr目录，此时我使用了另一部手机，这次我看到了好多文件，如：
   
   如上图，有很多native文件，这些native打头的文件都是空文件，不知道是干嘛用的。traces_1 ~ traces_9则是旧的，所以一般出现ANR异常时直接看traces.txt即可，不需要看traces_1这些，当然，如果有时间也可以看看，万一它们不是同一个方法导致的呢。这次发现ANR异常的信息在126行的位置，跟之前另一台设备的不一样，所以，搜索包名还是最快的方式，打开traces.txt后，第三行就有我们应用的包名，第一行是空行，第二行有pid，第三行则包含有我们应用的包名，如下：

   
   ----- pid 1836 at 2021-03-29 18:42:17 -----
   Cmd line: cn.android666.anrdemo
   Build fingerprint: 'conquest-S8/full_tdc1801/tdc1801:7.1.1/N4F26M/1533882872:user/test-keys'
   ABI: 'arm64'
   Build type: optimized
   Zygote loaded classes=4400 post zygote classes=368
   

   具体异常如下：

   "main" prio=5 tid=1 Sleeping
     | group="main" sCount=1 dsCount=0 obj=0x753015c0 self=0x76a0c96a00
     | sysTid=28877 nice=-10 cgrp=default sched=0/0 handle=0x76a539ea98
     | state=S schedstat=( 345239698 21377772 193 ) utm=28 stm=6 core=1 HZ=100
     | stack=0x7fef0bf000-0x7fef0c1000 stackSize=8MB
     | held mutexes=
     at java.lang.Thread.sleep!(Native method)
     - sleeping on <0x09af1c12> (a java.lang.Object)
     at java.lang.Thread.sleep(Thread.java:371)
     - locked <0x09af1c12> (a java.lang.Object)
     at java.lang.Thread.sleep(Thread.java:313)
     at cn.android666.anrdemo.MainActivity.onClick(MainActivity.kt:17)
     at java.lang.reflect.Method.invoke!(Native method)
     at androidx.appcompat.app.AppCompatViewInflater$DeclaredOnClickListener.onClick(AppCompatViewInflater.java:409)
     at android.view.View.performClick(View.java:5703)
     at com.google.android.material.button.MaterialButton.performClick(MaterialButton.java:1119)
     at android.view.View$PerformClick.run(View.java:22811)
     at android.os.Handler.handleCallback(Handler.java:836)
     at android.os.Handler.dispatchMessage(Handler.java:103)
     at android.os.Looper.loop(Looper.java:203)
     at android.app.ActivityThread.main(ActivityThread.java:6297)
     at java.lang.reflect.Method.invoke!(Native method)
     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1084)
     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:945)
   

总结

查找ANR原因步骤：

1. 出现ANR异常后，立马导出异常文件：adb pull data/anr D:/test
2. 打开traces.txt，第三行就是我们应用的包名，直接复制该包名并进行搜索。
3. 有时候traces.txt文件中会保存多次ANR异常信息，旧的在前面，新的在后面，比如A方法产生一个ANR异常，在文件生成时保存在120行，我们修复了该异常，然后运行时，另一个方法B又产生一个ANR异常，该ANR异常可能保存在文件的980行，注：这里说的行数是随意说的，只是用来说明旧的ANR在文件的前面，新的ANR在后面。
4. 有的设备在产生ANR异常时，会重复写到traces.txt文件中，所以，如果出现多次ANR，则该设备上只保存有最近那一次的ANR异常信息。而有的设备可能会重命名traces.txt为traces_1.txt ~ traces_9.txt，用于保存最近的9个ANR异常，最新的ANR异常信息依然是保存在traces.txt文件中。