Android—ANR日志分析

获取ANR日志：

ANR路径：/data/anr
ADB指令：adb bugreport D:\bugrep.zip

ANR日志分析步骤：

“main” prio=：主线程状态
beginning of crash：搜索 crash 相关信息
CPU usage from：搜索 cpu 使用信息

主线程状态：

RUNNABLE：线程正在运行或准备运行。
BLOCKED：线程被阻塞，等待获取一个锁。
WAITING：线程在等待某个条件发生（如等待其他线程的通知）。
TIMED_WAITING：线程在等待某个条件发生，但有时间限制（如使用Thread.sleep()或Object.wait(long timeout)）。
TERMINATED：线程已经完成执行并终止。
NATIVE：线程正在执行本地代码（JNI调用）。

主线程处于 BLOCKED / WAITING / TIME_WAITING 状态，基本上是函数阻塞导致的 anr。

案例分析：

5.1 主线程无卡顿，处于正常状态堆栈

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

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

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

该ANR是CPU抢占或内存紧张等其他因素引起
这份ANR日志抓取的时候，主线程已经恢复正常

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

5.2 主线程执行耗时操作

“main” prio=5 tid=1 Runnable
| group=“main” sCount=0 dsCount=0 flags=0 obj=0x72deb848 self=0x7748c10800
| sysTid=8968 nice=-10 cgrp=default sched=0/0 handle=0x77cfa75ed0
| state=R schedstat=( 24783612979 48520902 756 ) utm=2473 stm=5 core=5 HZ=100
| stack=0x7fce68b000-0x7fce68d000 stackSize=8192KB
| held mutexes= “mutator lock”(shared held)
at com.example.test.MainActivity$onCreate$2.onClick(MainActivity.kt:20)——关键行！！！
at android.view.View.performClick(View.java:7187)
at android.view.View.performClickInternal(View.java:7164)
at android.view.View.access3500 ( V i e w . j a v a : 813 ) a t a n d r o i d . v i e w . V i e w 3500(View.java:813) at android.view.View3500(View.java:813)atandroid.view.ViewPerformClick.run(View.java:27640)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:230)
at android.app.ActivityThread.main(ActivityThread.java:7725)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:526)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1034)

上述日志表明，主线程正处于执行状态，看堆栈信息可知不是处于空闲状态，发生ANR是因为一处click监听函数里执行了耗时操作。

5.3 主线程被锁阻塞

“main” prio=5 tid=1 Blocked
| group=“main” sCount=1 dsCount=0 flags=1 obj=0x72deb848 self=0x7748c10800
| sysTid=22838 nice=-10 cgrp=default sched=0/0 handle=0x77cfa75ed0
| state=S schedstat=( 390366023 28399376 279 ) utm=34 stm=5 core=1 HZ=100
| stack=0x7fce68b000-0x7fce68d000 stackSize=8192KB
| held mutexes=
at com.example.test.MainActivity$onCreate$1.onClick(MainActivity.kt:15)

waiting to lock <0x01aed1da> (a java.lang.Object) held by thread 3 ——————关键行！！！
at android.view.View.performClick(View.java:7187)
at android.view.View.performClickInternal(View.java:7164)
at android.view.View.access3500 ( V i e w . j a v a : 813 ) a t a n d r o i d . v i e w . V i e w 3500(View.java:813) at android.view.View3500(View.java:813)atandroid.view.ViewPerformClick.run(View.java:27640)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:230)
at android.app.ActivityThread.main(ActivityThread.java:7725)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:526)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1034)

…省略N行…

“WQW TEST” prio=5 tid=3 TimeWating
| group=“main” sCount=1 dsCount=0 flags=1 obj=0x12c44230 self=0x772f0ec000
| sysTid=22938 nice=0 cgrp=default sched=0/0 handle=0x77391fbd50
| state=S schedstat=( 274896 0 1 ) utm=0 stm=0 core=1 HZ=100
| stack=0x77390f9000-0x77390fb000 stackSize=1039KB
| held mutexes=
at java.lang.Thread.sleep(Native method)

sleeping on <0x043831a6> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:440)
locked <0x043831a6> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:356)
at com.example.test.MainActivity$onCreate2 22thread$1.run(MainActivity.kt:22)
locked <0x01aed1da> (a java.lang.Object)————————————————————关键行！！！
at java.lang.Thread.run(Thread.java:919)

这是一个典型的主线程被锁阻塞的例子；

waiting to lock <0x01aed1da> (a java.lang.Object) held by thread 3

其中等待的锁是<0x01aed1da>，这个锁的持有者是线程 3。进一步搜索 “tid=3” 找到线程3，发现它正在TimeWating。

那么ANR的原因找到了：线程3持有了一把锁，并且自身长时间不释放，主线程等待这把锁发生超时。在线上环境中，常见因锁而ANR的场景是SharePreference写入。

5.4 CPU被抢占

这个日志一般在 bugreport.txt 文件中可以查看。

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

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

5.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。

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

5.6 系统服务超时导致ANR

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

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