关于android:干货ANR日志分析全面解析

7次阅读

共计 13924 个字符，预计需要花费 35 分钟才能阅读完成。

解决 ANR 始终是 Android 开发者须要把握的重要技巧，个别从三个方面着手。

开发阶段：通过工具查看各个办法的耗时，卡顿状况，发现一处批改一处。

线上阶段：这个阶段次要依附监控工具发现 ANR 并上报，比方 matrix。

分析阶段：如果线上用户产生 ANR，并且你获取了一份日志，这就波及了本文要分享的内容——ANR 日志剖析技巧。

网上艰深的一段面试答题

ANR——利用无响应，Activity 是 5 秒，BroadCastReceiver 是 10 秒，Service 是 20 秒。

这句话说的很抽象，要想深入分析定位 ANR，须要晓得更多知识点，一般来说，ANR 按产生机制，分为 4 类：

InputEvent Timeout

a.InputDispatcher 发送 key 事件给 对应的过程的 Focused Window，对应的 window 不存在、处于暂停态、或通道 (input channel) 占满、通道未注册、通道异样、或 5s 内没有解决完一个事件，就会产生 ANR

b.InputDispatcher 发送 MotionEvent 事件有个例外之处：当对应 Touched Window 的 input waitQueue 中有超过 0.5s 的事件，inputDispatcher 会暂停该事件，并期待 5s，如果仍旧没有收到 window 的‘finish’事件，则触发 ANR

c. 下一个事件达到，发现有一个超时事件才会触发 ANR

BroadcastReceiver Timeout

a. 动态注册的播送和有序播送会 ANR，动静注册的非有序播送并不会 ANR

b. 播送发送时，会判断该过程是否存在，不存在则创立，创立过程的耗时也算在超时工夫里

c. 只有当过程存在前台显示的 Activity 才会弹出 ANR 对话框，否则会间接杀掉以后过程

d. 当 onReceive 执行超过阈值（前台 15s，后盾 60s），将产生 ANR

e. 如何发送前台播送：Intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)

Service Timeout

a.Service 的以下办法都会触发 ANR：onCreate(),onStartCommand(), onStart(), onBind(), onRebind(), onTaskRemoved(), onUnbind(),
onDestroy().

b. 前台 Service 超时工夫为 20s，后盾 Service 超时工夫为 200s

c. 如何辨别前台、后盾执行————以后 APP 处于用户态，此时执行的 Service 则为前台执行。
d. 用户态：有前台 activity、有前台播送在执行、有 foreground service 执行

a.ContentProvider 创立公布超时并不会 ANR

b. 应用 ContentProviderclient 来拜访 ContentProverder 能够自主抉择触发 ANR，超时工夫本人定
client.setDetectNotResponding(PROVIDER_ANR_TIMEOUT);

ps：Activity 生命周期超时会不会 ANR？——经测试并不会。

override fun onCreate(savedInstanceState: Bundle?) {Thread.sleep(60000)
       super.onCreate(savedInstanceState)
       setContentView(R.layout.activity_main)
   }

很多开发者认为，那就是耗时操作导致 ANR，全副是 app 应用层的问题。实际上，线上环境大部分 ANR 由零碎起因导致。

a. 函数阻塞：如死循环、主线程 IO、解决大数据

b. 锁出错：主线程期待子线程的锁

c. 内存缓和：零碎调配给一个利用的内存是有下限的，长期处于内存缓和，会导致频繁内存替换，进而导致利用的一些操作超时

a. CPU 被抢占：一般来说，前台在玩游戏，可能会导致你的后盾播送被抢占 CPU

b. 零碎服务无奈及时响应：比方获取零碎联系人等，零碎的服务都是 Binder 机制，服务能力也是无限的，有可能零碎服务长时间不响应导致 ANR

c. 其余利用占用的大量内存

产生 ANR 的时候，零碎会产生一份 anr 日志文件（手机的 /data/anr 目录下，文件名称可能各厂商不一样，业内大多称说为 trace 文件），内含如下几项重要信息。

Load: 2.62 / 2.55 / 2.25
CPU usage from 0ms to 1987ms later (2020-03-10 08:31:55.169 to 2020-03-10 08:32:17.156):
  41% 2080/system_server: 28% user + 12% kernel / faults: 76445 minor 180 major
  26% 9378/com.xiaomi.store: 20% user + 6.8% kernel / faults: 68408 minor 68 major
........ 省略 N 行.....
66% TOTAL: 20% user + 15% kernel + 28% iowait + 0.7% irq + 0.7% softirq

如上所示：

第一行：1、5、15 分钟内正在应用和期待应用 CPU 的流动过程的平均数
第二行：表明负载信息抓取在 ANR 产生之后的 0~1987ms。同时也指明了 ANR 的工夫点：2020-03-10 08:31:55.169
两头局部：各个过程占用的 CPU 的详细情况
最初一行：各个过程共计占用的 CPU 信息。

名词解释：

a. user: 用户态,kernel: 内核态

b. faults: 内存缺页，minor——轻微的，major——重度，须要从磁盘拿数据

c. iowait:IO 应用（期待）占比

d. irq: 硬中断，softirq: 软中断

留神：

iowait 占比很高，意味着有很大可能，是 io 耗时导致 ANR，具体进一步查看有没有过程 faults major 比拟多。
单过程 CPU 的负载并不是以 100% 为下限，而是有几个核，就有百分之几百，如 4 核下限为 400%。

Total number of allocations 476778  过程创立到当初一共创立了多少对象

Total bytes allocated 52MB 过程创立到当初一共申请了多少内存

Total bytes freed 52MB   过程创立到当初一共开释了多少内存

Free memory 777KB    不扩大堆的状况下可用的内存

Free memory until GC 777KB  GC 前的可用内存

Free memory until OOME 383MB  OOM 之前的可用内存

Total memory 以后总内存（已用 + 可用）
Max memory 384MB  过程最多能申请的内存

从含意能够得出结论：Free memory until OOME 的值很小的时候，曾经处于内存紧张状态。利用可能是占用了过多内存。

另外，除了 trace 文件中有内存信息，一般的 eventlog 日志中，也有内存信息（不肯定打印）

04-02 22:00:08.195  1531  1544 I am_meminfo: [350937088,41086976,492830720,427937792,291887104]

以上四个值别离指的是：

Cached
Free,
Zram,
Kernel,Native

Cached+Free 的内存代表着以后整个手机的可用内存，如果值很小，意味着处于内存紧张状态。个别低内存的断定阈值为：4G 内存手机以下阀值：350MB，以上阀值则为：450MB

ps: 如果 ANR 工夫点前后，日志里有打印 onTrimMemory，也能够作为内存缓和的一个参考判断

堆栈信息是最重要的一个信息，展现了 ANR 产生的过程以后所有线程的状态。

suspend all histogram:  Sum: 2.834s 99% C.I. 5.738us-7145.919us Avg: 607.155us Max: 41543us
DALVIK THREADS (248):
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x74b17080 self=0x7bb7a14c00
  | sysTid=2080 nice=-2 cgrp=default sched=0/0 handle=0x7c3e82b548
  | state=S schedstat=(757205342094 583547320723 2145008) utm=52002 stm=23718 core=5 HZ=100
  | stack=0x7fdc995000-0x7fdc997000 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 0000000000127474  /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 com.android.server.SystemServer.run(SystemServer.java:508)
  at com.android.server.SystemServer.main(SystemServer.java:340)
  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:856)
   
  ........ 省略 N 行.....
   
  "OkHttp ConnectionPool" daemon prio=5 tid=251 TimedWaiting
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x13daea90 self=0x7bad32b400
  | sysTid=29998 nice=0 cgrp=default sched=0/0 handle=0x7b7d2614f0
  | state=S schedstat=(951407 137448 11) utm=0 stm=0 core=3 HZ=100
  | stack=0x7b7d15e000-0x7b7d160000 stackSize=1041KB
  | held mutexes=
  at java.lang.Object.wait(Native method)
  - waiting on <0x05e5732e> (a com.android.okhttp.ConnectionPool)
  at com.android.okhttp.ConnectionPool$1.run(ConnectionPool.java:103)
  - locked <0x05e5732e> (a com.android.okhttp.ConnectionPool)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
  at java.lang.Thread.run(Thread.java:764)

如上日志所示，本文截图了两个线程信息，一个是主线程 main，它的状态是 native。

另一个是 OkHttp ConnectionPool，它的状态是 TimeWaiting。家喻户晓，教科书上说线程状态有 5 种：新建、就绪、执行、阻塞、死亡。而 Java 中的线程状态有 6 种，6 种状态都定义在：java.lang.Thread.State 中

问题来了，上述 main 线程的 native 是什么状态，哪来的？其实 trace 文件中的状态是是 CPP 代码中定义的状态，上面是一张对应关系表。

由此可知，main 函数的 native 状态是正在执行 JNI 函数。堆栈信息是咱们剖析 ANR 的第一个重要的信息，一般来说：

main 线程处于 BLOCK、WAITING、TIMEWAITING 状态，那基本上是函数阻塞导致 ANR；

如果 main 线程无异样，则应该排查 CPU 负载和内存环境。

"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 日志抓取的时候，主线程曾经恢复正常

遇到这种闲暇堆栈，能够依照第 3 节的办法去剖析 CPU、内存的状况。其次能够关注抓取日志的工夫和 ANR 产生的工夫是否相隔过久，工夫过久这个堆栈就没有剖析意义了。

"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.access$3500(View.java:813)
  at android.view.View$PerformClick.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 监听函数里执行了耗时操作。

"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.access$3500(View.java:813)
  at android.view.View$PerformClick.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$onCreate$2$thread$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 写入。

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。

如果有一份日志，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

能够看出，在产生 ANR 的工夫点前后，内存都处于紧张状态，level 等级是 80，查看 Android API 文档；

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

可知 80 这个等级是很重大的，利用马上就要被杀死，被杀死的这个利用从名字能够看进去是桌面，连桌面都快要被杀死，那一般利用能好到哪里去呢？

一般来说，产生内存缓和，会导致多个利用产生 ANR，所以在日志中如果发现有多个利用一起 ANR 了，能够初步断定，此 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&, android::Parcel*, unsigned int)+216)
  native: #05 pc 000000000004ce1c  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)
  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_Parcel_2Landroid_os_Parcel_2I+196)
  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)

从堆栈能够看出获取网络信息产生了 ANR：getActiveNetworkInfo。

前文有讲过：零碎的服务都是 Binder 机制（16 个线程），服务能力也是无限的，有可能零碎服务长时间不响应导致 ANR。如果其余利用占用了所有 Binder 线程，那么以后利用只能期待。

可进一步搜寻：blockUntilThreadAvailable 关键字：

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

如果有发现某个线程的堆栈，蕴含此字样，可进一步看其堆栈，确定是调用了什么零碎服务。此类 ANR 也是属于零碎环境的问题，如果某类型机器上频繁产生此问题，应用层能够思考躲避策略。

本文总结的技巧来自笔者工作中的大量 ANR 日志剖析教训，如有错漏请留言指出，交换促使提高！

作者：vivo 互联网客户端团队—Wang Qinwei

正文完

android

发表至： android

2021-06-08

0

关于android:如何进行性能优化这篇360°全方面性能调优含一线大厂Android端性能优化方案帮您分分钟解决APP卡顿

关于android:如何成为一名合格的-Android-开发工程师

关于android:MobPush推送查询API

关于android:Hilt-测试最佳实践-MAD-Skills

关于后端:一例-Go-编译器代码优化-bug-定位和修复解析

关于android:干货ANR日志分析全面解析

一、概述

二、ANR 产生机制

2.1 输出事件超时(5s)

2.2 播送类型超时（前台 15s，后盾 60s）

2.3 服务超时（前台 20s，后盾 200s）

2.4 ContentProvider 类型

三、导致 ANR 的起因

3.1 应用层导致 ANR（耗时操作）

3.2 零碎导致 ANR

四、剖析日志

4.1 CPU 负载

4.2 内存信息

4.3 堆栈音讯

五、典型案例剖析

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

5.2 主线程执行耗时操作

5.3 主线程被锁阻塞

5.4 CPU 被抢占

5.5 内存缓和导致 ANR

5.6 零碎服务超时导致 ANR

六、结语

站内搜索