相关文章： [Android性能优化 -- ANR问题定位分析](https://juejin.cn/post/7136534172096528398) 对于ANR，相信伙伴们并不陌生，对于ANR发生的场景，在四大组件中的超时机制，在上面的这篇文章中已经详细介绍了，但是虽然我们拿到了ANR的trace日志，但是貌似很难去定位问题，甚至连发生问题的原因也无法分析出来，所以本篇文章算是帮助大家在处理ANR问题时提供一些思路。 # 1 ANR再了解当系统发生ANR时，会主动dump trace日志并保存在data/anr/trace.txt文件夹下，我们在拿到anr日志之后，就可以着手分析日志；或者可以通过bugreport命令来拉取日志，具体命令如下： ```java adb bugreport [要保存日志的路径] ``` 当然我们在解读日志的时候，肯定是需要一些关键字去查询，判断到底是哪种类型的问题导致了ANR。 ## 1.1 logcat日志关键字我们知道，导致ANR发生的场景主要有以下几个： **（1）用户输入事件** 例如点击、滑动、长按等，在5s内没有处理，那么就会产生ANR，这种类型的问题，可以通过搜索如下关键字： ```java input event dispatching timed out ``` 这种是最常见的ANR，通常在我们点击某个按钮的时候就会导致页面卡死，出现ANR，但是**这个只是在logcat日志中的，我们在开发过程中出现ANR，可以通过搜索这个关键字找到出现ANR的原因，具体trace日志中怎么分析，后面会详细介绍**。 ```java I/WindowManager: Input event dispatching timed out sending to com.lay.layzproject/com.lay.datastore.DataStoreActivity. Reason: Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 3. Wait queue head age: 5527.5ms. ``` **（2）广播接收器** 前台广播接收器，onReceive在10s以内没有处理完成，会触发ANR\ 后台广播接收器，onReceive在60s以内没有处理完成，会触发ANR logcat关键字为： ```java timeout of broadcast BroadcastRecord ``` 注意在分析的时候，需要区分前台和后台广播。 **（3）Service** 前台服务，onCreate、onStart、onBind 在20s以内没有处理完成，会触发ANR\ 后台服务，onCreate、onStart、onBind 在200s以内没有处理完成，会触发ANR logcat关键字为： ```java timeout executing service ``` **（4）Contentprovider** Contentprovider在10s内没有处理完成，例如执行一个query操作，就会触发ANR logcat关键字为： ```java timeout publishing content providers ``` 当然这也是在我们开发过程中，如果碰到了ANR，可以直接在编译器中获取日志信息，但是大部分的场景下，其实是在测试场景或者用户场景中出现这个问题，那么就需要获取到trace日志来具体分析。 ## 1.2 ANR出现的原因总结（**1）主线程进行频繁的IO操作，例如文件读写、SP存储、数据库读写，导致主线程阻塞；** **（2）多线程出现死锁，主线程被block** 其实我们在客户端的开发中，多线程的场景很少，尤其Kotlin出现协程的概念之后，线程池几乎都很少见了，死锁的概率也很低；然而在单线程的场景中，**如果使用协程，也会出现主线程一直等待结果返回，导致超时ANR**。 **（3）主线程被Binder对端block** 其实Binder在通信的时候，可以是同步的，也可以是异步的，但是如果是同步Binder通信，考虑到传输效率的问题，很有可能就会导致主线程一直阻塞block，导致ANR **（4）系统资源已经被耗尽，例如CPU、IO等** # 2 读懂trace日志假设我们在开发或者提测之后，QA伙伴提出了某个app在使用的时候出现的anr，并通过bugreport导出了对应的日志文件，我们在拿到这个文件之后，如何去快速定位问题呢？ ## 2.1 ANR问题定位的流程（1）定位ANR发生的时间；（2）查看trace日志，看是否存在cpu异常、锁的竞争、耗时的message、耗时的binder调用；（3）查看主线程的状态；（4）查看其他线程的状态；其实从以上4点开始出发，一步一步排除1.2中提到的可能出现的问题，最终确认事故发生点，出最终的解决方案，但是有些场景还是需要配合业务上下文来分析。 ## 2.2 trace日志关键字分析 ```java ----- pid 32012 at 2023-04-16 12:19:57 ----- Cmd line: com.lay.layzproject Build fingerprint: 'google/sdk_gphone_x86_arm/generic_x86_arm:9/PSR1.180720.122/6736742:userdebug/dev-keys' ABI: 'x86' Build type: optimized Zygote loaded classes=10642 post zygote classes=1095 Intern table: 74397 strong; 365 weak JNI: CheckJNI is on; globals=609 (plus 26 weak) Libraries: /data/app/com.lay.layzproject-ctmKoWSLQO-XwViIKfoW5Q==/lib/x86/libmmkv.so /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libsoundpool.so /system/lib/libwebviewchromium_loader.so libjavacore.so libopenjdk.so (10) //已经分配了堆内存大小3M，已经使用了2M，创建了43648个对象 Heap: 20% free, 2MB/3MB; 43648 objects // GC的一些信息，可以不关注 Dumping cumulative Gc timings Cumulative bytes moved 6114552 Cumulative objects moved 141676 Peak regions allocated 416 (104MB) / 1536 (384MB) Total number of allocations 43648 Total bytes allocated 2MB Total bytes freed 0B Free memory 774KB Free memory until GC 774KB Free memory until OOME 381MB Total memory 3MB Max memory 384MB Zygote space size 1308KB Total mutator paused time: 0 Total time waiting for GC to complete: 31us Total GC count: 0 Total GC time: 0 Total blocking GC count: 0 Total blocking GC time: 0 Registered native bytes allocated: 265097 Current JIT code cache size: 12KB Current JIT data cache size: 10KB Current JIT mini-debug-info size: 27KB Current JIT capacity: 64KB Current number of JIT JNI stub entries: 0 Current number of JIT code cache entries: 53 Total number of JIT compilations: 53 Total number of JIT compilations for on stack replacement: 0 Total number of JIT code cache collections: 0 Memory used for stack maps: Avg: 70B Max: 524B Min: 24B Memory used for compiled code: Avg: 209B Max: 3KB Min: 1B Memory used for profiling info: Avg: 62B Max: 1384B Min: 16B Start Dumping histograms for 53 iterations for JIT timings Compiling: Sum: 124.695ms 99% C.I. 0.107ms-10.841ms Avg: 2.352ms Max: 10.934ms TrimMaps: Sum: 4.898ms 99% C.I. 6us-743.999us Avg: 92.415us Max: 820us Done Dumping histograms Memory used for compilation: Avg: 15KB Max: 159KB Min: 7KB ProfileSaver total_bytes_written=0 ProfileSaver total_number_of_writes=0 ProfileSaver total_number_of_code_cache_queries=0 ProfileSaver total_number_of_skipped_writes=0 ProfileSaver total_number_of_failed_writes=0 ProfileSaver total_ms_of_sleep=5000 ProfileSaver total_ms_of_work=0 ProfileSaver max_number_profile_entries_cached=0 ProfileSaver total_number_of_hot_spikes=0 ProfileSaver total_number_of_wake_ups=1 suspend all histogram: Sum: 734us 99% C.I. 0.304us-105us Avg: 38.631us Max: 105us // DALVIK THREADS (14): "Signal Catcher" daemon prio=5 tid=3 Runnable | group="system" sCount=0 dsCount=0 flags=0 obj=0x13100020 self=0xe375e000 | sysTid=32028 nice=0 cgrp=default sched=0/0 handle=0xdd37e970 | state=R schedstat=( 9020262 11182596 24 ) utm=0 stm=0 core=2 HZ=100 | stack=0xdd283000-0xdd285000 stackSize=1010KB | held mutexes= "mutator lock"(shared held) native: #00 pc 004151b6 /system/lib/libart.so (art::DumpNativeStack(std::__1::basic_ostream>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+198) native: #01 pc 0051034e /system/lib/libart.so (art::Thread::DumpStack(std::__1::basic_ostream>&, bool, BacktraceMap*, bool) const+382) native: #02 pc 0050b603 /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream>&, bool, BacktraceMap*, bool) const+83) native: #03 pc 0052e424 /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+916) native: #04 pc 00526146 /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+534) native: #05 pc 00525394 /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream>&, bool)+1316) native: #06 pc 00524d8d /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream>&)+941) native: #07 pc 004ec186 /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream>&)+214) native: #08 pc 004fafde /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+1806) native: #09 pc 004f9a4f /system/lib/libart.so (art::SignalCatcher::Run(void*)+431) native: #10 pc 0008f065 /system/lib/libc.so (__pthread_start(void*)+53) native: #11 pc 0002485b /system/lib/libc.so (__start_thread+75) (no managed stack frames) //主线程调用栈 "main" prio=5 tid=1 Sleeping | group="main" sCount=1 dsCount=0 flags=1 obj=0x7583df30 self=0xe36f4000 | sysTid=32012 nice=-10 cgrp=default sched=0/0 handle=0xe83b5494 | state=S schedstat=( 4837530082 1301459614 14038 ) utm=141 stm=342 core=2 HZ=100 | stack=0xff753000-0xff755000 stackSize=8MB | held mutexes= at java.lang.Thread.sleep(Native method) - sleeping on <0x06bde954> (a java.lang.Object) at java.lang.Thread.sleep(Thread.java:373) - locked <0x06bde954> (a java.lang.Object) at java.lang.Thread.sleep(Thread.java:314) at com.lay.datastore.DataStoreActivity.onCreate$lambda-0(DataStoreActivity.kt:20) at com.lay.datastore.DataStoreActivity.$r8$lambda$afdjO_vwWNd-vtjqRlagos86bqM(DataStoreActivity.kt:-1) at com.lay.datastore.DataStoreActivity$$ExternalSyntheticLambda0.onClick(D8$$SyntheticClass:-1) at android.view.View.performClick(View.java:6597) at com.google.android.material.button.MaterialButton.performClick(MaterialButton.java:1219) at android.view.View.performClickInternal(View.java:6574) at android.view.View.access$3100(View.java:778) at android.view.View$PerformClick.run(View.java:25885) at android.os.Handler.handleCallback(Handler.java:873) at android.os.Handler.dispatchMessage(Handler.java:99) at android.os.Looper.loop(Looper.java:193) at android.app.ActivityThread.main(ActivityThread.java:6669) at java.lang.reflect.Method.invoke(Native method) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858) ``` 上面是我自己造的一个ANR异常，然后通过bugreport导出来的日志，通过关键字”ANR“找到了关于我们项目的一个ANR日志信息，其中一些字段的含义，我这里介绍一下。 ### 2.2.1 字段的含义（1）Cmd line 显示了当前应用的包名，意味着当前应用发生了ANR；（2）Heap: 20% free, 2MB/3MB; 43648 objects 这段代表的意思是，在堆内存分配了3M的内存，已经使用了2M，一共创建了43648个对象（3）DALVIK THREADS (14): 当前进程一共有14个线程 ### 2.2.2 线程调用栈参数介绍 ```java "main" prio=5 tid=1 Sleeping | group="main" sCount=1 dsCount=0 flags=1 obj=0x7583df30 self=0xe36f4000 | sysTid=32012 nice=-10 cgrp=default sched=0/0 handle=0xe83b5494 | state=S schedstat=( 4837530082 1301459614 14038 ) utm=141 stm=342 core=2 HZ=100 | stack=0xff753000-0xff755000 stackSize=8MB | held mutexes= ``` 这里我们拿主线程的调用栈来做参数的介绍：第一行： - 线程名：main，如果有daemon这个参数，就是守护线程，例如Signal Catcher线程 - prio：线程优先级 - tid：线程内部id - 线程状态：Sleeping，关于线程状态，稍后做解释第二行： - group：线程所属的线程组 - sCount：线程被挂起的次数 - dsCount：用于调试（debug）的线程挂起次数 - obj：当前线程关联的线程java对象 - self：当前线程的地址第三行： - sysTid：线程真正意义上的tid - nice：调度优先级，**nice的值越小优先级越高，-10的优先级已经很高了**。 - cgrp：进程所属的进程调度组 - sched：调度策略 - handle：函数处理地址第四行： - state：线程状态 - schedstat：CPU调度时间统计 - utm/stm：用户态/内核态的CPU时间 - core：该线程最后运行所在的核心 - HZ：时钟频率第五行： - stack：线程栈的地址区间 - stackSize：栈的大小第六行： - held mutexes：持有锁的类型，包含独占锁exclusive和共享锁shared两种对于CPU调度时间统计这个参数，我着重介绍一下： ```java schedstat=( 4837530082 1301459614 14038 ) ``` 我们看到括号里有3个值，分别为Running、Runable、Switch，代表CPU时间片轮转机制中的3个值： - Running：CPU运行的时间，单位为ns - Runable：RQ队列的等待时间，单位为ns - Switch：CPU调度切换的次数紧接着就是utm和stm： - utm：该线程在用户态所执行的时间，单位为jiffies，默认为10ms - stm：该线程在内核态所执行的时间，单位为jiffies，默认为10ms 所以CPU在内核态和用户态运行的时间为：141 * 10 + 342 * 10 = 4830ms，CPU运行的时间为 4837530082ns，也就是4837ms，大致等于utm + stm的时间，也就是schedstat的第一个参数。所以从线程的调用栈中，我们能得到发生ANR的时候，线程所属的状态，以及当下CPU的一个运转情况，尤其是线程的状态。 ### 2.2.3 线程的状态查看我们知道，当一个线程从无到有，从创建到销毁都有自己的一个状态，如果线程正常运转，那么就会处于Runnable的状态，除此之外，线程还有什么状态呢？ ```java public enum State { NEW, RUNNABLE, /** * Thread state for a thread blocked waiting for a monitor lock. * A thread in the blocked state is waiting for a monitor lock * to enter a synchronized block/method or * reenter a synchronized block/method after calling * {@link Object#wait() Object.wait}. */ BLOCKED, /** * Thread state for a waiting thread. * A thread is in the waiting state due to calling one of the * following methods: *

{@link Object#wait() Object.wait} with no timeout
{@link #join() Thread.join} with no timeout
{@link LockSupport#park() LockSupport.park}

* *

A thread in the waiting state is waiting for another thread to * perform a particular action. * 例如当前主线程调用了wait方法，需要等待另一个线程调用notify来唤醒，那么此时线程就处于 WAITING状态 */ WAITING, /** 调用了wait方法，但是没有超时时间，也就意味着可能一直无法被唤醒而一直处于等待状态 */ TIMED_WAITING, /** * Thread state for a terminated thread. * The thread has completed execution. */ TERMINATED; } ``` **（1）Runnable / Native** 页面UI的更新，往往是由主线程来完成的，当主线程已经准备好更新UI并且总体上相应速度较快，就会处于Runnable的状态，此时主线程会等待资源获取到之后进行UI的更新。 > it maybe waiting for other resources from the operating system such as processor. 即便Runnable是正常的状态，官方声明中也说明了此状态可能在等待操作系统的其他资源，所以如果资源到位比较慢，这个时候就会存在ANR的风险，此时主线程一直处于等待的状态，那么超时5s之后就会ANR，所以如果ANR分析时，**发现线程为Runnable状态，就需要考虑是否存在主线程等待资源导致阻塞的场景**。我们看下面这个场景：主线程开启一个异步任务，此异步任务与主线程同时持有一把锁，只有当异步任务执行完成之后，锁被释放，主线程才能拿到锁进行处理。 ```kotlin findViewById