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

45次阅读

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

一、概述

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

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

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

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

二、ANR 产生机制

网上艰深的一段面试答题

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

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

2.1 输出事件超时(5s)

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

2.2 播送类型超时(前台 15s,后盾 60s)

BroadcastReceiver Timeout

a. 动态注册的播送和有序播送会 ANR,动静注册的非有序播送并不会 ANR
​
b. 播送发送时,会判断该过程是否存在,不存在则创立,创立过程的耗时也算在超时工夫里
​
c. 只有当过程存在前台显示的 Activity 才会弹出 ANR 对话框,否则会间接杀掉以后过程
​
d. 当 onReceive 执行超过阈值(前台 15s,后盾 60s),将产生 ANR
​
e. 如何发送前台播送:Intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)

2.3 服务超时(前台 20s,后盾 200s)

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 执行

2.4 ContentProvider 类型

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 的起因

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

3.1 应用层导致 ANR(耗时操作)

a. 函数阻塞:如死循环、主线程 IO、解决大数据
​
b. 锁出错:主线程期待子线程的锁
​
c. 内存缓和:零碎调配给一个利用的内存是有下限的,长期处于内存缓和,会导致频繁内存替换,进而导致利用的一些操作超时

3.2 零碎导致 ANR

a. CPU 被抢占:一般来说,前台在玩游戏,可能会导致你的后盾播送被抢占 CPU
​
b. 零碎服务无奈及时响应:比方获取零碎联系人等,零碎的服务都是 Binder 机制,服务能力也是无限的,有可能零碎服务长时间不响应导致 ANR
​
c. 其余利用占用的大量内存

四、剖析日志

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

4.1 CPU 负载

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%。

4.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 以后总内存(已用 + 可用)​
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,也能够作为内存缓和的一个参考判断

4.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 负载和内存环境。

五、典型案例剖析

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

遇到这种闲暇堆栈,能够依照第 3 节的办法去剖析 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.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 监听函数里执行了耗时操作。

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.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 写入。

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

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

能够看出,在产生 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 与你的利用无关。

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&, 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

正文完
 0