ANR分析小纪

/ 0评 / 1赞

前言

ANR：Application Not Responding，也就是应用无响应，当我们在主线程里面执行长时间操作系统就会弹出一个对话框提示用户应用失去响应是否关闭，定义看起来很简单，不过要分析出ANR的原因以及定位ANR发生的位置就不是那么简单了，下面记录下自己分析ANR的过程用作以后的参考。

ANR发生场景

ANR常见原因

1、主线程被IO操作（从4.0之后网络IO不允许在主线程中）阻塞，读/写取大文件。

2、主线程中存在耗时的计算，计算时间很长，导致程序卡死。

3、主线程中错误的操作，Thread.wait或者Thread.sleep等

由于Android系统会监控程序的响应状况，一旦出现下面情况，则会弹出ANR对话框

1、应用在 5秒 内未响应用户的输入事件（如按键或者触摸）

2、BroadcastReceiver未在 10秒 内完成相关的处理

3、前台service未在20秒内，后台service未在200秒内完成相关的处理

以上常量定义在ActivityManagerService.Java，ActiveServices.java中，参看:http://blog.csdn.net/ameyume/article/details/7038265

ANR分析流程

获取ANR日志:当ANR发生的时候，系统会保存相应信息到/data/anr/traces.txt中，然后结合系统log即可分析ANR原因。

查看traces.txt文件:当我们打开traces.txt的时候，首先看到的就是一堆系统信息打印。如下，其实对我们来说有用的部分为第一句 pid 31293 at 2017-05-09 16:15:47，以及DALVIK THREADS后面的线程堆栈信息(部分信息使用...省略)。

----- pid 31293 at 2017-05-09 16:15:47 -----
Cmd line: com.eostek.mediabrowser
ABI: arm
Build type: optimized
Zygote loaded classes=3405 post zygote classes=667
Intern table: 41436 strong; 590 weak
JNI: CheckJNI is off; globals=926
.....

DALVIK THREADS (44):
"main" prio=5 tid=1 Native
......

通过第一句我们可以知道崩溃的时间以及崩溃的时候的进程id为31293。通过这个pid我们可以在系统log中过滤出此应用的所有log。

DALVIK THREADS下面是应用中线程的堆栈信息，由于ANR主要发生在主线程，所以我们直接查看主线程的的即可(部分信息使用...省略)。

DALVIK THREADS (44):
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x73a57700 self=0xb483d000
  | sysTid=31293 nice=0 cgrp=default sched=0/0 handle=0xb6fa3bec
  | state=R schedstat=( 84255720780 9604438354 43585 ) utm=7278 stm=1147 core=3 HZ=100
  | stack=0xbe4fe000-0xbe500000 stackSize=8MB
  | held mutexes=
  native: #00 pc 000203be  /system/lib/libpng.so (png_read_filter_row_paeth3_neon+37)
  native: #01 pc 0000d8e5  /system/lib/libpng.so (png_read_row+320)
  native: #02 pc 0000dadd  /system/lib/libpng.so (png_read_rows+56)
  native: #03 pc 00154d0d  /system/lib/libskia.so (???)
  native: #04 pc 001555f7  /system/lib/libskia.so (SkPNGImageDecoder::onDecode(SkStream*, SkBitmap*, SkImageDecoder::Mode)+594)
  native: #05 pc 00151655  /system/lib/libskia.so (SkImageDecoder::decode(SkStream*, SkBitmap*, SkColorType, SkImageDecoder::Mode)+38)
  native: #06 pc 0008d0d7  /system/lib/libandroid_runtime.so (???)
  native: #07 pc 0008d613  /system/lib/libandroid_runtime.so (???)
  native: #08 pc 0007a745  /system/framework/arm/boot.oat (Java_android_graphics_BitmapFactory_nativeDecodeFileDescriptor__Ljava_io_FileDescriptor_2Landroid_graphics_Rect_2Landroid_graphics_BitmapFactory_00024Options_2+152)
  at android.graphics.BitmapFactory.nativeDecodeFileDescriptor(Native method)
  at android.graphics.BitmapFactory.decodeFileDescriptor(BitmapFactory.java:672)
  at com.eostek.mediabrowser.c.a.a(unavailable:-1)
  at com.eostek.mediabrowser.photoplayer.PhotoPlayerActivity.b(unavailable:-1)
  at com.eostek.mediabrowser.photoplayer.PhotoPlayerActivity.a(unavailable:-1)
  at com.eostek.mediabrowser.photoplayer.i.run(unavailable:-1)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5280)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:963)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:758)

通过上面的日志可以看到，ANR发生的时候调用了at com.eostek.mediabrowser.c.a.a(unavailable:-1)方法，由于应用源码被混淆了，所以无法得知具体方法，但是我们已经可以定位到大致的类。

查看系统log日志:在系统日志中搜索" ANR "(大小写匹配).即可定位到ANR发生时的系统打印(部分信息使用...省略)。

E/ActivityManagerService(  414): ANR in com.eostek.mediabrowser (com.eostek.mediabrowser/.photoplayer.PhotoPlayerActivity)
E/ActivityManagerService(  414): PID: 31293
E/ActivityManagerService(  414): Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
E/ActivityManagerService(  414): Load: 2.25 / 3.37 / 3.86
..... ANR发生之前 .....
E/ActivityManagerService(  414): CPU usage from 4047ms to -8077ms ago:
E/ActivityManagerService(  414):   101% 31293/com.eostek.mediabrowser: 94% user + 7.6% kernel / faults: 6496 minor 8 major
......
E/ActivityManagerService(  414): 62% TOTAL: 38% user + 23% kernel + 0.2% iowait + 0.2% softirq
..... ANR发生之后 .....
E/ActivityManagerService(  414): CPU usage from 7065ms to 7635ms later:
E/ActivityManagerService(  414):   96% 31293/com.eostek.mediabrowser: 92% user + 3.6% kernel / faults: 3 minor
E/ActivityManagerService(  414):     96% 1790/Thread-1112: 92% user + 3.6% kernel
......
E/ActivityManagerService(  414): 38% TOTAL: 29% user + 9.1% kernel

通过上面的日志我们可以知道，当ANR发生的时候，系统CPU占用过高，而iowait很低，所以可能的原因是应用在主线程中进行了耗时的计算，消耗了大量的CPU，而且这里我们也可以看到PID为31293。记录下ANR的行数。

然后在系统log中搜索"(31293)"，即可获取到应用的所有打印，根据ANR打印的行数向上查找最近的打印即可获取到具体信息(使用Notepad+双击31293会高亮所有的31293哦)。

I/BitmapUtils(31293): outWidth 9600 outHeight 6400
I/BitmapUtils(31293): width 150 height 150
I/BitmapUtils(31293): inSampleSize 42
W/ViewRootImpl(31293): Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_ENTER, scanCode=28, metaState=0, flags=0x28, repeatCount=0, eventTime=9346010, downTime=9345926, deviceId=4, source=0x101 }
I/PhoneWindow(31293): 66Key up: repeat=0 flags=0x28
W/ViewRootImpl(31293): Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_ENTER, scanCode=28, metaState=0, flags=0x28, repeatCount=0, eventTime=9346010, downTime=9345926, deviceId=4, source=0x101 }
W/ViewRootImpl(31293): Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_ENTER, scanCode=28, metaState=0, flags=0x28, repeatCount=0, eventTime=9346010, downTime=9345926, deviceId=4, source=0x101 }
W/ViewRootImpl(31293): Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_ENTER, scanCode=28, metaState=0, flags=0x28, repeatCount=0, eventTime=9346010, downTime=9345926, deviceId=4, source=0x101 }
D/PhoneWindowManager(  414): Unhandled key: win=Window{34158590 u0 com.eostek.mediabrowser/com.eostek.mediabrowser.photoplayer.PhotoPlayerActivity}, action=1, flags=8, keyCode=66, scanCode=28, metaState=0, repeatCount=0, policyFlags=1644167168
D/PhoneWindowManager(  414): No fallback.
I/Choreographer(31293): Skipped 41 frames!  The application may be doing too much work on its main thread.
I/Process (  414): Sending signal. PID: 855 SIG: 3
I/art     (  855): Thread[5,tid=864,WaitingInMainSignalCatcherLoop,Thread*=0xb4841600,peer=0x12c000a0,"Signal Catcher"]: reacting to signal 3

通过上面的日志可以看到，BitmapUtils里面进行图片缩放的时候，系统打印出了很多事件取消，事件未处理等信息，而且缩放图片也需要占用大量CPU，所以可以定位到ANR发生的原因就是ANR发生的时候系统CPU占用过高，这个时候进行图片缩放 （9600*6400->150*150）,CPU饥渴，所以缩放消耗的时间很长造成ANR。我们回顾下traces.txt中的DALVIK THREADS下面"main"节点查看主线程堆栈也可以看到，最后调用的位置如下，可以很清楚的看到，确实和图片处理相关的，所以能进一步确认ANR位置。

at android.graphics.BitmapFactory.nativeDecodeFileDescriptor(Native method)
at android.graphics.BitmapFactory.decodeFileDescriptor(BitmapFactory.java:672)

写在最后

由于ANR情况多样，这里只是给出了定位的思路，所以具体情况应该具体分析。在查找资料的过程中还发现了一个由于线程死锁造成的ANR，由于没有遇到过，所以仅仅贴出参考地址:

http://blog.csdn.net/oujunli/article/details/9102101,主要是查看traces.txt中的DALVIK THREADS下面的held by信息查看被锁住的位置。

其他参考博客:http://blog.csdn.net/jiangguohu1/article/details/52636470

发表回复

您的邮箱地址不会被公开。 必填项已用 * 标注