当前位置:   article > 正文

Android性能优化 - ANR的分析、监控和解决_anr文件分析

anr文件分析

一、ANR概念

1.定义

“Application Not Responding”的缩写,即“应用程序无响应”。如果你应用程序在UI线程被阻塞太长时间,就会出现ANR。

2.类型

① KeyDispatchTimeout(常见)

input事件5S内没有处理完成发生了ANR。
logcat日志关键字:Input event dispatching timed out

② BroadcastTimeout
Broadcast:onReceiver在10S内没有处理完成发生ANR。
logcat日志关键字:Timeout of broadcast BroadcastRecord

③ ServiceTimeout
Service:onCreate,onStart,onBind等生命周期在20s内没有处理完成发生ANR
logcat日志关键字:Timeout executing service

④ ContentProviderTimeout
ContentProvider 在10S内没有处理完成发生ANR。
logcat日志关键字:timeout publishing content providers

3.出现的原因

(1)主线程频繁进行耗时的IO操作:如数据库读写。(一般会打印dataBase的读写日志,同时提示locked <0x0db193bf(随机)>  下面有例子) 
(2)多线程操作的死锁,主线程被block;(提示waiting on <0x0db193bf(随机)>下面有例子参考)
(3)主线程被Binder 对端block(系统Binder服务被其他应用占用导致当前应用主线程block,下面有例子);
(4)主线程无问题,但CPU被其他应用强占(参考下面例子)
(5)service binder的连接达到上线无法和和System Server通信。(下面有例子参考)

4、如何分析ANR

(1)日志分析:ANR发生时都会在log中输出错误信息,从log中可以获得ANR的类型,CPU使用率,ANR发生的进程名和pid。 

(2)traces文件分析: /data/anr/traces.txt 这个文件是分析ANR原因的关键文件,使用adb指令进行赋权后拉出。通过log、trace文件以及代码结合分析ANR的成因(iowait?Memoryleak?Block?)

(3)traces文件无法分析的:不过还存在一些ANR问题,trace文件是分析不了的,例如我们的系统上,人脸识别活体攻击的时候,native算法耗尽cpu资源导致其他app无法抢占cpu时间片导致anr,需要补充。。???

二、ANR定位流程

1、ANR发生时系统保存日志的源码位置:

framework/base/services/core/java/com/android/server/am/AppErrors.java

ANR发生的时候,会将ANR记录到log中

2、查看log日志

从日志中搜索关键字:ANR in com.xxxx ,找到出现ANR的时间点、进程PID、ANR类型。在分析ANR的时候,我们首先要确认是不是当时CPU很紧张、各路APP都在抢占资源,CPU无法及时响应最终导致了ANR?为了排查这种情况,我们就需要获取ANR发生时候的CPU状态参数。

①场景1

如日志:

07-20 15:36:36.472  1000  1520  1597 I am_anr  : [0,1480,com.xxxx.moblie,952680005,Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]

从上面的log我们可以看出: 应用com.xxxx.moblie 在07-20 15:36:36.472时间,发生了一次KeyDispatchTimeout类型的ANR,它的进程号是1480.
把关键的信息整理一下:

ANR时间:07-20 15:36:36.472
进程pid:1480
进程名:com.xxxx.moblie
ANR类型:KeyDispatchTimeout
我们已经知道了发生KeyDispatchTimeout的ANR是因为 input事件在5秒内没有处理完成。那么在这个时间07-20 15:36:36.472 的前5秒,也就是(15:36:30 ~15:36:31)时间段左右程序到底做了什么事情?这个简单,因为我们已经知道pid了,再搜索一下pid = 1480的日志.这些日志表示该进程所运行的轨迹,关键的日志如下:

  1. 07-20 15:36:29.749 10102 1480 1737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE
  2. 07-20 15:36:30.136 10102 1480 1737 D moblie-Application: receiving an empty message, drop
  3. 07-20 15:36:35.791 10102 1480 1766 I Adreno : QUALCOMM build : 9c9b012, I92eb381bc9
  4. 07-20 15:36:35.791 10102 1480 1766 I Adreno : Build Date : 12/31/17
  5. 07-20 15:36:35.791 10102 1480 1766 I Adreno : OpenGL ES Shader Compiler Version: EV031.22.00.01
  6. 07-20 15:36:35.791 10102 1480 1766 I Adreno : Local Branch :
  7. 07-20 15:36:35.791 10102 1480 1766 I Adreno : Remote Branch : refs/tags/AU_LINUX_ANDROID_LA.UM.6.4.R1.08.00.00.309.049
  8. 07-20 15:36:35.791 10102 1480 1766 I Adreno : Remote Branch : NONE
  9. 07-20 15:36:35.791 10102 1480 1766 I Adreno : Reconstruct Branch : NOTHING
  10. 07-20 15:36:35.826 10102 1480 1766 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.msm8998.so from the current namespace instead.
  11. 07-20 15:36:36.682 10102 1480 1480 W ViewRootImpl[MainActivity]: Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_PERIOD, scanCode=0, metaState=0, flags=0x28, repeatCount=0, eventTime=16099429, downTime=16099429, deviceId=-1, source=0x101 }

从上面我们可以知道,在时间 07-20 15:36:29.749 程序收到了一个action消息。
原来是应用com.xxxx.moblie 收到了一个推送消息(com.ttt.push.RECEIVE_MESSAGE)导致了阻塞,我们再串联一下目前所获取到的信息:在时间07-20 15:36:29.749 应用com.xxxx.moblie 收到了一下推送信息action=com.ttt.push.RECEIVE_MESSAGE发生阻塞,5秒后发生了KeyDispatchTimeout的ANR。

②场景2

  1. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: ANR in com.xxxx.moblie (com.xxxx.moblie/.ui.MainActivity) (关键字ANR in + 进程名 + Activity名称)
  2. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: PID: 1480 (进程pid)
  3. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Reason: Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)(ANR的原因,输入分发超时)
  4. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0 (Load表明是1分钟,5分钟,15分钟CPU的负载)
  5. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: CPU usage from 20ms to 20286ms later (2018-07-20 15:36:36.170 to 2018-07-20 15:36:56.436):
  6. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 42% 6774/pressure: 41% user + 1.4% kernel / faults: 168 minor
  7. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 34% 142/kswapd0: 0% user + 34% kernel
  8. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 31% 1520/system_server: 13% user + 18% kernel / faults: 58724 minor 1585 major
  9. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 13% 29901/com.ss.android.article.news: 7.7% user + 6% kernel / faults: 56007 minor 2446 major
  10. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 13% 32638/com.android.quicksearchbox: 9.4% user + 3.8% kernel / faults: 48999 minor 1540 major
  11. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 11% (CPU的使用率)1480/com.xxxx.moblie: 5.2%(用户态的使用率) user + (内核态的使用率) 6.3% kernel / faults: 76401 minor 2422 major
  12. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 8.2% 21000/kworker/u16:12: 0% user + 8.2% kernel
  13. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 0.8% 724/mtd: 0% user + 0.8% kernel / faults: 1561 minor 9 major
  14. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 8% 29704/kworker/u16:8: 0% user + 8% kernel
  15. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.9% 24391/kworker/u16:18: 0% user + 7.9% kernel
  16. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.1% 30656/kworker/u16:14: 0% user + 7.1% kernel
  17. 07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.1% 9998/kworker/u16:4: 0% user + 7.1% kernel

通过上面所提供的案例我们可以分析出以下几点:

  • ANR发生的位置是:com.xxxx.moblie/.ui.MainActivity
  • com.xxxx.moblie 占用了11%的CPU,CPU的使用率并不是很高,基本可以排除CPU负载的原因
  • Reason提示我们是输入分发超时导致的ANR

通过上面几点我们虽然排除了CPU过度负载的可能,但我们并不能准确定位出ANR的确切位置,要想准确定位出ANR发生的确切位置,就要借助系统为了解决ANR问题而提供的终极大杀器——traces.txt文件了。

3. traces.txt 文件分析

当APP不响应、响应慢了、或者WatchDog的监视没有得到回应时,系统就会dump出一个traces.txt文件,存放在文件目录:/data/anr/文件夹中,通过traces文件,我们可以拿到线程名、堆栈信息、线程当前状态、binder call等信息。
我们可以通过adb命令获取到该文件夹下面的所有traces文件:adb pull /data/anr

  1. trace:
  2. Cmd line:com.xxxx.moblie
  3. "main" prio=5 tid=1 Runnable
  4. | group="main" sCount=0 dsCount=0 obj=0x73bcc7d0 self=0x7f20814c00
  5. | sysTid=20176 nice=-10 cgrp=default sched=0/0 handle=0x7f251349b0
  6. | state=R schedstat=( 0 0 0 ) utm=12 stm=3 core=5 HZ=100
  7. | stack=0x7fdb75e000-0x7fdb760000 stackSize=8MB
  8. | held mutexes= "mutator lock"(shared held)
  9. // java 堆栈调用信息,可以查看调用的关系,定位到具体位置
  10. at ttt.push.InterceptorProxy.addMiuiApplication(InterceptorProxy.java:77)
  11. at ttt.push.InterceptorProxy.create(InterceptorProxy.java:59)
  12. at android.app.Activity.onCreate(Activity.java:1041)
  13. at miui.app.Activity.onCreate(SourceFile:47)
  14. at com.xxxx.moblie.ui.b.onCreate(SourceFile:172)
  15. at com.xxxx.moblie.ui.MainActivity.onCreate(SourceFile:68)
  16. at android.app.Activity.performCreate(Activity.java:7050)
  17. at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1214)
  18. at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2807)
  19. at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2929)
  20. at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
  21. at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1618)
  22. at android.os.Handler.dispatchMessage(Handler.java:105)
  23. at android.os.Looper.loop(Looper.java:171)
  24. at android.app.ActivityThread.main(ActivityThread.java:6699)
  25. at java.lang.reflect.Method.invoke(Native method)
  26. at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:246)
  27. at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:783)

这里详细解析一下traces.txt里面的一些字段,看看它到底能给我们提供什么信息.

  • main:main标识是主线程,如果是线程,那么命名成“Thread-X”的格式,x表示线程id,逐步递增。
  • prio:线程优先级,默认是5
  • tid:tid不是线程的id,是线程唯一标识ID
  • group:是线程组名称
  • sCount:该线程被挂起的次数
  • dsCount:是线程被调试器挂起的次数
  • obj:对象地址
  • self:该线程Native的地址
  • sysTid:是线程号(主线程的线程号和进程号相同)
  • nice:是线程的调度优先级
  • sched:分别标志了线程的调度策略和优先级
  • cgrp:调度归属组
  • handle:线程处理函数的地址。
  • state:是调度状态
  • schedstat:从 /proc/[pid]/task/[tid]/schedstat读出,三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度,不支持这项信息的三个值都是0;
  • utm:是线程用户态下使用的时间值(单位是jiffies)
  • stm:是内核态下的调度时间值
  • core:是最后执行这个线程的cpu核的序号。

Java的堆栈信息是我们最关心的,它能够定位到具体位置。从上面的traces,我们可以判断ttt.push.InterceptorProxy.addMiuiApplicationInterceptorProxy.java:77 导致了com.xxxx.moblie发生了ANR。这时候可以对着源码查看,找到出问题,并且解决它。

三、ANR分析流程总结

总结一下上面我们分析ANR的主体流程:

  1. 1、首先我们搜索am_anr,找到出现ANR的时间点、进程PID、ANR类型、然后再找搜索PID,找前5秒左右的日志。
  2. 2、过滤ANR IN 查看CPU信息
  3. 3、接着查看traces.txt,找到java的堆栈信息定位代码位置,最后查看源码,分析与解决问题。

到这里,通过上面三个步骤我们基本就能定位出来大部分ANR的来龙去脉了。下面是更多其他不同的ANR场景

四、ANR其他场景

1. 主线程无卡顿,处于正常状态堆栈

  1. "main" prio=5 tid=1 Native
  2. | group="main" sCount=1 dsCount=0 flags=1 obj=0x74b38080 self=0x7ad9014c00
  3. | sysTid=23081 nice=0 cgrp=default sched=0/0 handle=0x7b5fdc5548
  4. | state=S schedstat=( 284838633 166738594 505 ) utm=21 stm=7 core=1 HZ=100
  5. | stack=0x7fc95da000-0x7fc95dc000 stackSize=8MB
  6. | held mutexes=
  7. kernel: __switch_to+0xb0/0xbc
  8. kernel: SyS_epoll_wait+0x288/0x364
  9. kernel: SyS_epoll_pwait+0xb0/0x124
  10. kernel: cpu_switch_to+0x38c/0x2258
  11. native: #00 pc 000000000007cd8c /system/lib64/libc.so (__epoll_pwait+8)
  12. native: #01 pc 0000000000014d48 /system/lib64/libutils.so (android::Looper::pollInner(int)+148)
  13. native: #02 pc 0000000000014c18 /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+60)
  14. native: #03 pc 00000000001275f4 /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
  15. at android.os.MessageQueue.nativePollOnce(Native method)
  16. at android.os.MessageQueue.next(MessageQueue.java:330)
  17. at android.os.Looper.loop(Looper.java:169)
  18. at android.app.ActivityThread.main(ActivityThread.java:7073)
  19. at java.lang.reflect.Method.invoke(Native method)
  20. at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:536)
  21. at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:876)

上述主线程堆栈就是一个很正常的空闲堆栈,表明主线程正在等待新的消息

如果ANR日志里主线程是这样一个状态,那可能有两个原因:

该ANR是CPU抢占或内存紧张等其他因素引起

这份ANR日志抓取的时候,主线程已经恢复正常

遇到这种空闲堆栈,可以按照第3节的方法去分析CPU、内存的情况。其次可以关注抓取日志的时间和ANR发生的时间是否相隔过久,时间过久这个堆栈就没有分析意义了。

2.主线程被其他多线程lock,导致死锁

waiting on <0x1cd570> (a android.os.MessageQueue)

  1. DALVIK THREADS:
  2. "main" prio=5 tid=3 TIMED_WAIT
  3. | group="main" sCount=1 dsCount=0 s=0 obj=0x400143a8
  4. | sysTid=691 nice=0 sched=0/0 handle=-1091117924
  5. at java.lang.Object.wait(Native Method)
  6. - waiting on <0x1cd570> (a android.os.MessageQueue)
  7. at java.lang.Object.wait(Object.java:195)
  8. at android.os.MessageQueue.next(MessageQueue.java:144)
  9. at android.os.Looper.loop(Looper.java:110)
  10. at android.app.ActivityThread.main(ActivityThread.java:3742)
  11. at java.lang.reflect.Method.invokeNative(Native Method)
  12. at java.lang.reflect.Method.invoke(Method.java:515)
  13. at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:739)
  14. at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:497)
  15. at dalvik.system.NativeStart.main(Native Method)
  16. "Binder Thread #3" prio=5 tid=15 NATIVE
  17. | group="main" sCount=1 dsCount=0 s=0 obj=0x434e7758
  18. | sysTid=734 nice=0 sched=0/0 handle=1733632
  19. at dalvik.system.NativeStart.run(Native Method)
  20. "Binder Thread #2" prio=5 tid=13 NATIVE
  21. | group="main" sCount=1 dsCount=0 s=0 obj=0x1cd570
  22. | sysTid=696 nice=0 sched=0/0 handle=1369840
  23. at dalvik.system.NativeStart.run(Native Method)
  24. "Binder Thread #1" prio=5 tid=11 NATIVE
  25. | group="main" sCount=1 dsCount=0 s=0 obj=0x433aca10
  26. | sysTid=695 nice=0 sched=0/0 handle=1367448
  27. at dalvik.system.NativeStart.run(Native Method)
  28. ----- end 691 -----

3、主线程做IO等耗时的操作:比如数据库读写。

  1. "main" prio=5 tid=1 Native
  2. held mutexes=
  3. kernel: (couldn't read /proc/self/task/11003/stack)
  4. native: #00 pc 000492a4 /system/lib/libc.so (nanosleep+12)
  5. native: #01 pc 0002dc21 /system/lib/libc.so (usleep+52)
  6. native: #02 pc 00009cab /system/lib/libsqlite.so (???)
  7. native: #03 pc 00011119 /system/lib/libsqlite.so (???)
  8. native: #04 pc 00016455 /system/lib/libsqlite.so (???)
  9. native: #16 pc 0000fa29 /system/lib/libsqlite.so (???)
  10. native: #17 pc 0000fad7 /system/lib/libsqlite.so (sqlite3_prepare16_v2+14)
  11. native: #18 pc 0007f671 /system/lib/libandroid_runtime.so (???)
  12. native: #19 pc 002b4721 /system/framework/arm/boot-framework.oat (Java_android_database_sqlite_SQLiteConnection_nativePrepareStatement__JLjava_lang_String_2+116)
  13. at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:294)
  14. at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:215)
  15. at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)
  16. at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)
  17. at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)
  18. at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)
  19. at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:808)
  20. locked <0x0db193bf> (a java.lang.Object)
  21. at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:793)
  22. at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:696)
  23. at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:690)
  24. at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:299)
  25. at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:223)
  26. at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:163)
  27. locked <0x045a4a8c> (a com.xxxx.video.common.data.DataBaseHelper)
  28. at com.xxxx.video.common.data.DataBaseORM.<init>(DataBaseORM.java:46)
  29. at com.xxxx.video.common.data.DataBaseORM.getInstance(DataBaseORM.java:53)
  30. locked <0x017095d5> (a java.lang.Class<com.xxxx.video.common.data.DataBaseORM>)

4、CPU被抢占

  1. CPU usage from 0ms to 10625ms later (2020-03-09 14:38:31.633 to 2020-03-09 14:38:42.257):
  2. 543% 2045/com.alibaba.android.rimet: 54% user + 89% kernel / faults: 4608 minor 1 major ————关键行!!!
  3. 99% 674/android.hardware.camera.provider@2.4-service: 81% user + 18% kernel / faults: 403 minor
  4. 24% 32589/com.wang.test: 22% user + 1.4% kernel / faults: 7432 minor 1 major
  5. ........省略N行.....

如上日志,第二行是钉钉的进程,占据CPU高达543%,抢占了大部分CPU资源,因而导致发生ANR。

5、系统内存紧张导致ANR

如果有一份日志,CPU和堆栈都很正常(不贴出来了),仍旧发生ANR,考虑是内存紧张。

从CPU第一行信息可以发现,ANR的时间点是2020-10-31 22:38:58.468—CPU usage from 0ms to 21752ms later (2020-10-31 22:38:58.468 to 2020-10-31 22:39:20.220)

接着去系统日志里搜索am_meminfo, 这个没有搜索到。再次搜索onTrimMemory,果然发现了很多条记录;

  1. 10-31 22:37:19.749 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
  2. 10-31 22:37:33.458 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
  3. 10-31 22:38:00.153 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
  4. 10-31 22:38:58.731 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
  5. 10-31 22:39:02.816 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0

可以看出,在发生ANR的时间点前后,内存都处于紧张状态,level等级是80,查看Android API 文档;

  1. /**
  2. * Level for {@link #onTrimMemory(int)}: the process is nearing the end
  3. * of the background LRU list, and if more memory isn't found soon it will
  4. * be killed.
  5. */
  6. static final int TRIM_MEMORY_COMPLETE = 80;

可知80这个等级是很严重的,应用马上就要被杀死,被杀死的这个应用从名字可以看出来是桌面,连桌面都快要被杀死,那普通应用能好到哪里去呢?

一般来说,发生内存紧张,会导致多个应用发生ANR,所以在日志中如果发现有多个应用一起ANR了,可以初步判定,此ANR与你的应用无关。

5、系统服务超时导致ANR

系统服务超时一般会包含BinderProxy.transactNative关键字,请看如下日志:

  1. "main" prio=5 tid=1 Native
  2. | group="main" sCount=1 dsCount=0 flags=1 obj=0x727851e8 self=0x78d7060e00
  3. | sysTid=4894 nice=0 cgrp=default sched=0/0 handle=0x795cc1e9a8
  4. | state=S schedstat=( 8292806752 1621087524 7167 ) utm=707 stm=122 core=5 HZ=100
  5. | stack=0x7febb64000-0x7febb66000 stackSize=8MB
  6. | held mutexes=
  7. kernel: __switch_to+0x90/0xc4
  8. kernel: binder_thread_read+0xbd8/0x144c
  9. kernel: binder_ioctl_write_read.constprop.58+0x20c/0x348
  10. kernel: binder_ioctl+0x5d4/0x88c
  11. kernel: do_vfs_ioctl+0xb8/0xb1c
  12. kernel: SyS_ioctl+0x84/0x98
  13. kernel: cpu_switch_to+0x34c/0x22c0
  14. native: #00 pc 000000000007a2ac /system/lib64/libc.so (__ioctl+4)
  15. native: #01 pc 00000000000276ec /system/lib64/libc.so (ioctl+132)
  16. native: #02 pc 00000000000557d4 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+252)
  17. native: #03 pc 0000000000056494 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
  18. native: #04 pc 00000000000562d0 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+216)
  19. native: #05 pc 000000000004ce1c /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)
  20. native: #06 pc 00000000001281c8 /system/lib64/libandroid_runtime.so (???)
  21. native: #07 pc 0000000000947ed4 /system/framework/arm64/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+196)
  22. at android.os.BinderProxy.transactNative(Native method) ————————————————关键行!!!
  23. at android.os.BinderProxy.transact(Binder.java:804)
  24. at android.net.IConnectivityManager$Stub$Proxy.getActiveNetworkInfo(IConnectivityManager.java:1204)—关键行!
  25. at android.net.ConnectivityManager.getActiveNetworkInfo(ConnectivityManager.java:800)
  26. at com.xiaomi.NetworkUtils.getNetworkInfo(NetworkUtils.java:2)
  27. at com.xiaomi.frameworkbase.utils.NetworkUtils.getNetWorkType(NetworkUtils.java:1)
  28. at com.xiaomi.frameworkbase.utils.NetworkUtils.isWifiConnected(NetworkUtils.java:1)

从堆栈可以看出获取网络信息发生了ANR:getActiveNetworkInfo。

前文有讲过:系统的服务都是Binder机制(16个线程),服务能力也是有限的,有可能系统服务长时间不响应导致ANR。如果其他应用占用了所有Binder线程,那么当前应用只能等待。

可进一步搜索:blockUntilThreadAvailable关键字:

at android.os.Binder.blockUntilThreadAvailable(Native method)

如果有发现某个线程的堆栈,包含此字样,可进一步看其堆栈,确定是调用了什么系统服务。此类ANR也是属于系统环境的问题,如果某类型机器上频繁发生此问题,应用层可以考虑规避策略。

6、binder 通信失败

  1. 07-21 06:04:35.580 <6>[32837.690321] binder: 1698:2362 transaction failed 29189/-3, size 100-0 line 3042
  2. 07-21 06:04:35.594 <6>[32837.704042] binder: 1765:4071 transaction failed 29189/-3, size 76-0 line 3042
  3. 07-21 06:04:35.899 <6>[32838.009132] binder: 1765:4067 transaction failed 29189/-3, size 224-8 line 3042
  4. 07-21 06:04:36.018 <6>[32838.128903] binder: 1765:2397 transaction failed 29189/-22, size 348-0 line 2916

ANR场景监控

线下拿到ANR日志

  • adb pull /data/anr/
  • adb bugreport

缺陷:

  • 只能线下,用户反馈时,无法获取ANR日志

线上监控:

可采用字节的matrix库, 采用了ASM插装方式;

ANR 监控则更简单,在每一帧 doFrame 到来时,重置一个定时器,并往 buffer 数组里插入一个结点,如果 5s 内没有 cancel,则认为发生了 ANR,从之前插入的结点开始,到最后一个结点,收集中间执行过的方法数据,可以认为导致 ANR 的关键方法就在这里面,计算时间戳即可得到关键方法。

声明:本文内容由网友自发贡献,不代表【wpsshop博客】立场,版权归原作者所有,本站不承担相应法律责任。如您发现有侵权的内容,请联系我们。转载请注明出处:https://www.wpsshop.cn/w/Monodyee/article/detail/619512
推荐阅读
相关标签
  

闽ICP备14008679号