【Android】ANR日志分析

一、ANR出的问题原因

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

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

1、函数阻塞：如死循环、主线程IO、处理大数据
2、锁出错：主线程等待子线程的锁
3、内存紧张：系统分配给一个应用的内存是有上限的，长期处于内存紧张，会导致频繁内存交换，进而导致应用的一些操作超时

系统导致ANR

1、CPU被抢占：一般来说，前台在玩游戏，可能会导致你的后台广播被抢占CPU
2、系统服务无法及时响应：比如获取系统联系人等，系统的服务都是Binder机制，服务能力也是有限的，有可能系统服务长时间不响应导致ANR
3、其他应用占用的大量内存

二、日志分析

2.1 CPU 负载

CPU usage from 28360ms to 0ms ago (2024-02-29 13:10:31.735 to 2024-02-29 13:11:00.095):
  90% 1377/system_server: 42% user + 48% kernel / faults: 72533 minor 370 major
  22% 295/logd: 5.4% user + 16% kernel / faults: 4061 minor
  20% 789/surfaceflinger: 8.6% user + 12% kernel / faults: 1413 minor
........省略N行.....
83% TOTAL: 32% user + 37% kernel + 4.7% iowait + 7.5% irq + 1.5% softirq

如上所示：

• 第一行：表明负载信息抓取在ANR发生之后的0~28360ms。同时也指明了ANR的时间点：2024-02-29 13:11:00.095

• 中间部分：各个进程占用的CPU的详细情况

• 最后一行：各个进程合计占用的CPU信息。

  a. user:用户态,kernel:内核态
  b. faults:内存缺页，minor——轻微的，major——重度，需要从磁盘拿数据
  c. iowait:IO使用（等待）占比
  d. irq:硬中断，softirq:软中断

• iowait占比很高，意味着有很大可能，是io耗时导致ANR，具体进一步查看有没有进程faults major比较多。

• 单进程CPU的负载并不是以100%为上限，而是有几个核，就有百分之几百，如4核上限为400%。

2.2 内存

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 28MB//当前总内存（已用+可用）

Max memory 384MB  //进程最多能申请的内存

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

ps:如果ANR时间点前后，日志里有打印onTrimMemory，也可以作为内存紧张的一个参考判断

2.3 堆栈信息

堆栈信息是最重要的一个信息，展示了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负载和内存环境。

三、案例分析

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

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

3.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.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监听函数里执行了耗时操作。

3.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.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)

这是一个典型的主线程被锁阻塞的例子；
其中等待的锁是<0x01aed1da>，这个锁的持有者是线程 3。进一步搜索 “tid=3” 找到线程3， 发现它正在TimeWating。
那么ANR的原因找到了：线程3持有了一把锁，并且自身长时间不释放，主线程等待这把锁发生超时。在线上环境中，常见因锁而ANR的场景是SharePreference写入。

3.4 CPU被抢占

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。

3.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)
接着去logcat里搜索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 文档；
可知80这个等级是很严重的，应用马上就要被杀死，被杀死的这个应用从名字可以看出来是桌面，连桌面都快要被杀死，那普通应用能好到哪里去呢？
一般来说，发生内存紧张，会导致多个应用发生ANR，所以在日志中如果发现有多个应用一起ANR了，可以初步判定，此ANR与你的应用无关。

3.6 系统服务超时导致ANR

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

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x72bce768 self=0xb400e7ca23a0b010
  | sysTid=4647 nice=0 cgrp=default sched=1073741825/1 handle=0xe7cb4a3fb4f8
  | state=S schedstat=( 64276581 1072197042 239 ) utm=3 stm=3 core=0 HZ=100
  | stack=0xffffe912e000-0xffffe9130000 stackSize=8192KB
  | held mutexes=
  native: (backtrace::Unwind failed for thread 4647: Thread has not responded to signal in time)
  at libcore.io.Linux.access(Native method)
  at libcore.io.ForwardingOs.access(ForwardingOs.java:72)
  at libcore.io.BlockGuardOs.access(BlockGuardOs.java:73)
  at libcore.io.ForwardingOs.access(ForwardingOs.java:72)
  at android.app.ActivityThread$AndroidOs.access(ActivityThread.java:7584)
  at java.io.UnixFileSystem.checkAccess(UnixFileSystem.java:281)
  at java.io.File.exists(File.java:815)
  at android.app.ContextImpl.ensureExternalDirsExistOrFilter(ContextImpl.java:2892)
  at android.app.ContextImpl.getExternalFilesDirs(ContextImpl.java:766)
  - locked <0x07a54129> (a java.lang.Object)
  at android.content.ContextWrapper.getExternalFilesDirs(ContextWrapper.java:278)
  at k0.a$b.b(ContextCompat.java:-1)
  at k0.a.f(ContextCompat.java:-1)
  at androidx.core.content.FileProvider.parsePathStrategy(FileProvider.java:18)
  at androidx.core.content.FileProvider.getPathStrategy(FileProvider.java:3)
  - locked <0x09ed6cae> (a java.util.HashMap)
  at androidx.core.content.FileProvider.attachInfo(FileProvider.java:8)
  at android.app.ActivityThread.installProvider(ActivityThread.java:7287)
  at android.app.ActivityThread.installContentProviders(ActivityThread.java:6828)
  at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6745)
  at android.app.ActivityThread.access$1300(ActivityThread.java:240)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1920)
  at android.os.Handler.dispatchMessage(Handler.java:106)
  at android.os.Looper.loop(Looper.java:223)
  at android.app.ActivityThread.main(ActivityThread.java:7707)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)

以上可以看出来，是在从堆栈可以看出ANR：getExternalFilesDirs。

at android.app.ActivityThread.installProvider(ActivityThread.java:7287)
at android.app.ActivityThread.installContentProviders(ActivityThread.java:6828)
at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6745)

可以看出来是在AMS创建APP时出现的问题，因此可以给系统侧分析。

3.7 Input dispatching timed out

ANR部分日志信息：
PID: 32640
UID: 1110155
Input dispatching timed out (4e4035c com.aaa/com.aaa.home.MainActivity (server) is not responding. Waited 5001ms for MotionEvent(deviceId=-1, eventTime=85286596000000, source=0x00001002, displayId=0, action=DOWN, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, classification=NONE, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, xCursorPosition=nan, yCursorPosition=nan, pointers=[0: (525.0, 957.0)]), policyFlags=0x6b000000)

CPU usage from 0ms to 31081ms later (2024-10-22 07:03:11.876 to 2024-10-22 07:03:42.956):

这个导致的原因有很多，这个问题无法从ANR日志里去分析，就需要从系统日志里去查找问题，这个报错的时间上，需要往前去找日志信息，从日志里可以找到关键的信息，如下

10-22 07:03:07.795 17729 17830 I InputDispatcher: Not sending touch event to 4e4035c com.aaa/com.aaa.home.MainActivity because it is paused

点击事件没有发送成功，说明这里就是发生问题的关键时间点，顺藤摸瓜，往上找一下有没有什么错误信息，
10-22 07:03:07.634 1015 15113 D EMS:ExceptionHandlerFactory: Get handler : STRICT_MODE
10-22 07:03:07.634 1015 15113 E JavaBinder: *** Uncaught remote exception! (Exceptions are not yet supported across processes.)
10-22 07:03:07.634 1015 15113 E JavaBinder: java.util.concurrent.RejectedExecutionException: Task c.a.a.a.u@4f72b0e rejected from java.util.concurrent.ThreadPoolExecutor@735f423[Running, pool size = 8, active threads = 8, queued tasks = 6, completed tasks = 19620]
10-22 07:03:07.634 1015 15113 E JavaBinder: at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2086)10-2207:03:07.634101515113EJavaBinder:atjava.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:848)10-2207:03:07.634101515113EJavaBinder:atjava.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1394)10-2207:03:07.634101515113EJavaBinder:atc.a.a.a.v.a(UnknownSource:2)10-2207:03:07.634101515113EJavaBinder:atc.a.a.a.t.p(UnknownSource:104)10-2207:03:07.634101515113EJavaBinder:atc.a.a.a.t.j(UnknownSource:102)10-2207:03:07.634101515113EJavaBinder:atc.b.a.b$a.onTransact(Unknown Source:207)
10-22 07:03:07.634 1015 15113 E JavaBinder: at android.os.Binder.execTransactInternal(Binder.java:1179)
10-22 07:03:07.634 1015 15113 E JavaBinder: at android.os.Binder.execTransact(Binder.java:1143)

1015进程频繁过量使用binder线程导致系统Binder线程池满载, 带来后果就是系统做binder进程通讯变慢亦或停止，界面点击响应不及时

如下图: 1015进程频繁抛出RejectedExcutionException, 该进程频繁进行binder进程间通信，使得系统binder线程池满载(Runing 8个+ active 8个共计16个)，导致其他程序在和system_server进程间通信过程中存在等待延迟，拖慢点击事件响应而出现ANR。