文档章节

android ANR异常分析技巧总结

天王盖地虎626
 天王盖地虎626
发布于 06/06 12:07
字数 3026
阅读 19
收藏 2

前言
ANR异常是android开发中比较常见的异常之一,最近为了看ANR异常,差了不少资料,现在做一个总结。
本文将从以下几个角度来总结ANR异常分析:

1.ANR类型
2.ANR产生的原因
3.ANR日志来源
4.分析ANR问题的套路
1. ANR类型
ANR类型按报错类型主要有Input(输入事件)、Broadcast(广播)、Service(服务), 对应产生ANR的时间分别为:

类型    前台应用    后台应用
Input    5s    5s
Broadcast    10s    6s
Service    20s    200s
上面的只是原生数据,各个厂商可能会对数据进行修改。并且前台应用和后台应用判断是否ANR的时间是不一样的。其中Input时间会直接弹出ANR弹框, 另外的异常如果用户不操作, 只会打印日志,不会弹弹框。

2. ANR产生的原因
产生ANR的原因本质都是:主线程未在规定时间内完成代码的执行, 具体的原因有:

1.耗时操作, 如复杂的Layout,庞大的for循环, IO操作等
2.被Binder 对端block
3.被子线程同步锁block
4.Binder被占满导致主线程无法和System_server进程通信
5.得不到系统资源(CPU/RAM/IO)
第1点比较好理解, 就是在主线程耗时操作太多;

第2点指当前进程的主线程与其他进程进行Binder通信时, 由于Binder通信会让主线程挂起,等待对端的返回, 结果对端由于某些原因一直未返回, 导致当前进程的主线程无法往下执行而超市,产生ANR;

第3点是指主线程与其他线程公用锁但是一直未得到锁, 导致超时,产生ANR;

第4点是指主线程和System_server进程进行Binder通信,由于其他线程或者其他进程与System_server进程之间有太多Binder通信,将Binder池占满,导致主线程的Binder通信一直无法处理,超时产生ANR;

第5点是由于系统资源紧张,CPU占用率过高,负载过大,IO操作太多, 导致主线程无法得到CPU时间片等系统资源去执行,而产生ANR.

其中前四点比较好分析, 通过日志可以找到线索并解决, 而第五种定位比较困难, 因为第五种ANR情况更复杂, 甚至不是软件的问题。

3. ANR日志来源
如果是第三方数据上报,或者测试人员测试时抓取了日志, 我们可以直接查看日志, 但是如果使我们自己发现或者复现了问题,可以用以下方式获取日志:

3.1 traces.txt
ANR优先查看此日志, AMS在ANR发生的时候,dump相关进程(ANR的进程、systemserver、mediaserver,surfaceFinger等)的当前栈到traces.txt。需要注意的是,traces.txt是抓取的是超时后(如input超时就是5s后)的snapshot,并不一定能够真实的反应出block的点。也存在抓到主线程没有block,在idle的情况。

获取traces.txt的方式:adb pull /data/anr/traces.txt

3.2 applogcat-log
我们的logcat信息会打印在此处, 里面有较多的堆栈信息,按照日期,取出里面最新的日志。
获取applogcat-log方式:adb pull /data/log/android_logs

3.3 dropbox
里面会记录不同的错误信息日志, 日志命名格式为 AA_BB@CC.txt, 其中AA表示进程名,BB表示异常类型, CC为时间戳,如 system_server_anr@13457689.txt, 就表示一个ANR异常的日志文件, 找到自己对应的时间及进程的日志信息即可。此日志可作为一个线索。

获取方式:adb pull /data/system/dropbox

4. 分析ANR问题的套路
4.1 在主线程进行耗时操作
这个一般比较好排查,(这个正式APP现在一般也不会有吧。。。), 如果看代码看不出, 可以看一下日志, 打开traces.txt文件, 看到的第一行是这样:

----- pid 13250 at 2018-01-01 23:56:09 -----
1
这个表示进程 13250 的日志就从这里开始了, 一般traces.txt文件的第一个进程就是发生ANR所在进程, 然后继续往下看, 找到主线程的日志, 举个栗子:

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x7425caf8 self=0xb4827800
  | sysTid=671 nice=0 cgrp=default sched=0/0 handle=0xb6febbec
  | state=S schedstat=( 0 0 0 ) utm=1853 stm=50 core=2 HZ=100
  | stack=0xbe7bd000-0xbe7bf000 stackSize=8MB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/671/stack)
  native: #00 pc 000133cc  /system/lib/libc.so (syscall+28)
  native: #01 pc 000a9a83  /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+82)
  native: #02 pc 001b16f1  /system/lib/libart.so (art::JNI::NewString(_JNIEnv*, unsigned short const*, int)+640)
  native: #03 pc 00075887  /system/lib/libandroid_runtime.so (???)
  native: #04 pc 008570ab  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_database_CursorWindow_nativeGetString__JII+110)
  at android.database.CursorWindow.nativeGetString(Native method)
  at android.database.CursorWindow.getString(CursorWindow.java:438)
  at android.database.AbstractWindowedCursor.getString(AbstractWindowedCursor.java:51)
  at android.database.CursorWrapper.getString(CursorWrapper.java:114)
  at com.android.settings.ApnSettings.fillList(ApnSettings.java:259)
  at com.android.settings.ApnSettings.onResume(ApnSettings.java:208)
  at android.app.Fragment.performResume(Fragment.java:2096)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:928)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1067)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1049)
  at android.app.FragmentManagerImpl.dispatchResume(FragmentManager.java:1879)
  at android.app.Activity.performResume(Activity.java:6113)
  at android.app.ActivityThread.performResumeActivity(ActivityThread.java:3015)
  at android.app.ActivityThread.handleResumeActivity(ActivityThread.java:3061)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2415)
  at android.app.ActivityThread.access$800(ActivityThread.java:151)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1313)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5345)
  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:947)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:742)

这一段日志中, 看到第一行的"main"就知道这就是主线程, main是线程名。然后从ApnSettings.java中可以看到fillList这个可能的耗时操作主线程处理的地方有OnResume和OnReceive,因为调用栈到这里就结束了。
且代码中存在使用HandlerThread异步处理这个操作的地方,可以借鉴下将OnResume和OnReceive这两处都放到HandlerThread中去做。

4.2 被Binder 对端block
 "main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x73ee6470 self=0xb4d76500
  | sysTid=22831 nice=0 cgrp=default sched=0/0 handle=0xb6f4bc00
  | state=S schedstat=( 0 0 0 ) utm=22 stm=22 core=0 HZ=100
  | stack=0xbe283000-0xbe285000 stackSize=8MB
  | held mutexes=
  native: #00 pc 000410ac  /system/lib/libc.so (__ioctl+8)
  native: #01 pc 000477e5  /system/lib/libc.so (ioctl+14)
  native: #02 pc 0001e7c5  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+132)
  native: #03 pc 0001ee17  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+38)
  native: #04 pc 0001efcd  /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+124)
  native: #05 pc 00019fb7  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+30)
  native: #06 pc 00086de9  /system/lib/libandroid_runtime.so (???)
  native: #07 pc 00d94629  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+140)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:503)
  at android.net.INetworkPolicyManager$Stub$Proxy.getNetworkPolicies(INetworkPolicyManager.java:410)
  at android.net.NetworkPolicyManager.getNetworkPolicies(NetworkPolicyManager.java:174)
  at com.android.settings.net.NetworkPolicyEditor.read(NetworkPolicyEditor.java:57)
  at com.android.settings.DataUsageSummary.onCreate(DataUsageSummary.java:361)
  at android.app.Fragment.performCreate(Fragment.java:2202)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:942)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1148)
  at android.app.BackStackRecord.run(BackStackRecord.java:793)
  at android.app.FragmentManagerImpl.execPendingActions(FragmentManager.java:1535)
  at android.app.FragmentManagerImpl.executePendingTransactions(FragmentManager.java:562)
  at com.android.settings.SettingsActivity.switchToFragment(SettingsActivity.java:1084)
  at com.android.settings.SettingsActivity.onCreate(SettingsActivity.java:657)
  at android.app.Activity.performCreate(Activity.java:6251)
  at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1110)
  at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2370)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2477)
  at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1345)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:148)
  at android.app.ActivityThread.main(ActivityThread.java:5438)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:762)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:652)

主从日志中看到调用了NetworkPolicyManager.getNetworkPolicies,然后就进行了Binder通信, 然后调用栈就终止在这里了,推断是对端block了, Binder通信的两端方法名是一致的, 所以可以再当前日志搜索getNetworkPolicies,找到对端:

"Binder_4" prio=5 tid=56 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x1321a0a0 self=0xad31e200
  | sysTid=2491 nice=0 cgrp=default sched=0/0 handle=0x9fd00930
  | state=S schedstat=( 0 0 0 ) utm=46441 stm=46582 core=1 HZ=100
  | stack=0x9fc04000-0x9fc06000 stackSize=1014KB
  | held mutexes=
  at com.android.server.net.NetworkPolicyManagerService.getNetworkPolicies(NetworkPolicyManagerService.java:1696)
  - waiting to lock <0x07439315> (a java.lang.Object) held by thread 35
  at android.net.INetworkPolicyManager$Stub.onTransact(INetworkPolicyManager.java:145)
  at android.os.Binder.execTransact(Binder.java:453

被Tid=35的人拿住了一把锁(0x07439315),那么继续看tid=35是谁,有两种方法:

搜索tid=35
搜索0x07439315,找到 - locked <0x07439315> (a java.lang.Object)
"NetworkPolicy" prio=5 tid=35 TimedWaiting
  | group="main" sCount=1 dsCount=0 obj=0x12d98940 self=0x9f91f700
  | sysTid=2415 nice=0 cgrp=default sched=0/0 handle=0xa0f33930
  | state=S schedstat=( 0 0 0 ) utm=7681 stm=7783 core=0 HZ=100
  | stack=0xa0e31000-0xa0e33000 stackSize=1038KB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x02580c1b> (a java.lang.Object)
  at java.lang.Thread.parkFor$(Thread.java:1220)
  - locked <0x02580c1b> (a java.lang.Object)
  at sun.misc.Unsafe.park(Unsafe.java:299)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2053)
  at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:372)
  at com.android.server.NativeDaemonConnector$ResponseQueue.remove(NativeDaemonConnector.java:634)
  at com.android.server.NativeDaemonConnector.executeForList(NativeDaemonConnector.java:426)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:345)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:340)
  at com.android.server.NetworkManagementService.setInterfaceQuota(NetworkManagementService.java:1712)
  - locked <0x0b0f91b8> (a java.lang.Object)
  at com.android.server.net.NetworkPolicyManagerService.setInterfaceQuota(NetworkPolicyManagerService.java:2421)
  at com.android.server.net.NetworkPolicyManagerService.updateNetworkRulesLocked(NetworkPolicyManagerService.java:1232)
  at com.android.server.net.NetworkPolicyManagerService$14.onReceive(NetworkPolicyManagerService.java:1060)
  - locked <0x07439315> (a java.lang.Object)
  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:881)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:148)
  at android.os.HandlerThread.run(HandlerThread.java:61)

可以看到,NetworkPolicy在通过NativeDaemonConnector和netd通信(setInterfaceQuota)
我们结合log来看下在发生ANR的前后的打印:

06-19 15:29:00.997  1235  1270 I am_anr  : [0,22831,com.android.settings,818429509,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.)]
  06-19 15:29:05.683  1235  2415 E NetdConnector: NDC Command {55445 bandwidth setiquota seth_w0 9223372036854775807} took too long (4755ms
  06-19 15:29:05.723  1235  2491 I dvm_lock_sample: [system_server,1,Binder_4,4919,NetworkPolicyManagerService.java,1696,-,1056,100]

从eventslog中还可以发现,setting出现了两次连续的ANR,而上下文中都有类似上面的dvm_lock_sample NetworkPolicyManagerService相关的告警。
因此虽然15:28的这次ANR并没有打出有用的栈,但是我们还是可以猜测出这两次ANR的原因都是netd的command耗时太久导致的(在主线程的调用路径上存在必然的block)
那么,在netd可能无法修改的情况下(至少应用层是无法修改的),我们只能将可能存在block的操作放到非UI线程中去做。

4.3 主线程被子线程同步锁block 导致ANR
这种问题和上面降到的Binder对端block的例子有一部分步骤相似, 只要在主线程的日志中看到这么一句:

 waiting to lock <0x07439315> (a java.lang.Object) held by thread 35
1
说明主线程正在等锁, held by thread 35 标识同步锁被线程号 35 所持有, 我们可以搜索这个线程号或者0x07439315, 去看看这个线程在做什么,找到问题原因。

4.4 系统资源紧张导致ANR
04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.Android.email/com.android.email.activity.SplitScreenActivitypaused=false}.  5009.8ms since event, 5009.5ms since waitstarted
04-0113:12:11.572 I/WindowManager( 220): Input event dispatching timedout sending tocom.android.email/com.android.email.activity.SplitScreenActivity
04-01 13:12:14.123 I/Process(  220): Sending signal. PID: 21404 SIG: 3
04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 3 
……
04-0113:12:15.872 E/ActivityManager(  220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity)
04-0113:12:15.872 E/ActivityManager(  220): Reason:keyDispatchingTimedOut
04-0113:12:15.872 E/ActivityManager(  220): Load: 8.68 / 8.37 / 8.53
04-0113:12:15.872 E/ActivityManager(  220): CPUusage from 4361ms to 699ms ago ----CPU在ANR发生前的使用情况

04-0113:12:15.872 E/ActivityManager(  220):   5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults: 10 minor
04-0113:12:15.872 E/ActivityManager(  220):   4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11 minor 2 major
04-0113:12:15.872 E/ActivityManager(  220):   0.9%52/spi_qsd.0: 0% user + 0.9% kernel
04-0113:12:15.872 E/ActivityManager(  220):   0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
04-0113:12:15.872 E/ActivityManager(  220):   0.5%296/com.android.systemui: 0.5% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait
04-0113:12:15.872 E/ActivityManager(  220): CPUusage from 3697ms to 4223ms later:-- ANR后CPU的使用量======later是标志
04-0113:12:15.872 E/ActivityManager(  220):   25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor
04-0113:12:15.872 E/ActivityManager(  220):    16% 21603/__eas(par.hakan: 16% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220):    7.2% 21406/GC: 7.2% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220):    1.8% 21409/Compiler: 1.8% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220):   5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
04-0113:12:15.872 E/ActivityManager(  220):    5.5% 263/InputDispatcher: 0% user + 5.5% kernel
04-0113:12:15.872 E/ActivityManager(  220): 32%TOTAL: 28% user + 3.7% kernel

上述日志中,有这么三行:

04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 3—发生ANR的时间和生成trace.txt的时间
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago ----CPU在ANR发生前的使用情况
04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms later:-- ANR后CPU的使用量
从这个日志中可以看到CPU使用率很高,IO操作占比很大(87% iowait), 由此导致系统资源紧张,但是也只能推测ANR非常可能由此产生,却不能100%确定, 因为这个CPU统计是一个时间段的,不是一个实时的, 具体还需要在日志中找找其他线索,以确定问题。
 

本文转载自:https://blog.csdn.net/qq475703980/article/details/80428514

天王盖地虎626

天王盖地虎626

粉丝 34
博文 553
码字总数 21578
作品 0
南京
私信 提问
android ANR异常及其解决方式

ANR定义 在Android上,如果你的应用程序有一段时间响应不够灵敏,系统会向用户显示一个对话框,这个对话框称作应用程序无响应(ANR:Application Not Responding)对话框。用户可以选择让程序...

长平狐
2012/09/03
437
0
Android开发高手课之崩溃优化

《Android开发高手课》是极客时间上为数不多的质量高的课程,通过学习确实让我开拓了眼界,之前对于Android的优化可能仅仅停留在基础的阶段,通过对这个课程的学习,确实了解了更多的监测手段...

小菜鸟程序媛
02/21
0
0
xCrash 2.4.0 发布,新增 Android ANR 捕获功能

xCrash 能为安卓 APP 提供捕获 java 崩溃,native 崩溃和 ANR 的能力。并且,不需要 root 权限或任何系统权限。 xCrash 能在 App 进程崩溃或 ANR 时,在你指定的目录中生成一个 tombstone 文...

nomagic
09/09
235
0
谈谈 ANR 之 Service 超时

1. 核心源码 关键类 路径(/frameworks/base/) ActiveServices.java services/core/java/com/android/server/am/ActiveServices.java ActivityManagerService.java services/core/java/com/......

DeepCoder
04/29
0
0
Android ANR错误有讲解

Android ANR这个错误大家并不陌生,但是从Android 2.2开始出错的ANR信息会自动上传给Google进行系统分析改进,当然了你的应用ANR错误其实保存在一个文件中,在/data/anr /traces.txt文件中,...

阿酷
2011/12/26
3.3K
1

没有更多内容

加载失败,请刷新页面

加载更多

前端技术之:Prisma Demo服务部署过程记录

安装前提条件: 1、已经安装了docker运行环境 2、以下命令执行记录发生在MackBook环境 3、已经安装了PostgreSQL(我使用的是11版本) 4、Node开发运行环境可以正常工作 首先需要通过Node包管...

popgis
今天
5
0
数组和链表

数组 链表 技巧一:掌握链表,想轻松写出正确的链表代码,需要理解指针获引用的含义: 对指针的理解,记住下面的这句话就可以了: 将某个变量赋值给指针,实际上就是将这个变量的地址赋值给指...

code-ortaerc
今天
4
0
栈-链式(c/c++实现)

上次说“栈是在线性表演变而来的,线性表很自由,想往哪里插数据就往哪里插数据,想删哪数据就删哪数据...。但给线性表一些限制呢,就没那么自由了,把线性表的三边封起来就变成了栈,栈只能...

白客C
今天
42
0
Mybatis Plus service

/** * @author beth * @data 2019-10-20 23:34 */@RunWith(SpringRunner.class)@SpringBootTestpublic class ServiceTest { @Autowired private IUserInfoService iUserInfoS......

一个yuanbeth
今天
5
0
php7-internal 7 zval的操作

## 7.7 zval的操作 扩展中经常会用到各种类型的zval,PHP提供了很多宏用于不同类型zval的操作,尽管我们也可以自己操作zval,但这并不是一个好习惯,因为zval有很多其它用途的标识,如果自己...

冻结not
昨天
6
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部