相关文章：

Android功能优化 — ANR问题定位剖析

关于ANR，相信同伴们并不陌生，关于ANR发生的场景，在四大组件中的超时机制，在上面的这篇文章中现已详细介绍了，可是尽管咱们拿到了ANR的trace日志，可是形似很难去定位问题，甚至连发生问题的原因也无法剖析出来，所以本篇文章算是帮助咱们在处理ANR问题时提供一些思路。

1 ANR再了解

当系统发生ANR时，会主动dump trace日志并保存在data/anr/trace.txt文件夹下，咱们在拿到anr日志之后，就能够着手剖析日志；或许能够经过bugreport指令来拉取日志，详细指令如下：

adb bugreport [要保存日志的途径]

当然咱们在解读日志的时分，肯定是需求一些关键字去查询，判别到底是哪种类型的问题导致了ANR。

1.1 logcat日志关键字

咱们知道，导致ANR发生的场景主要有以下几个：

（1）用户输入事情

例如点击、滑动、长按等，在5s内没有处理，那么就会发生ANR，这种类型的问题，能够经过搜索如下关键字：

input event dispatching timed out

这种是最常见的ANR，通常在咱们点击某个按钮的时分就会导致页面卡死，呈现ANR，可是这个只是在logcat日志中的，咱们在开发过程中呈现ANR，能够经过搜索这个关键字找到呈现ANR的原因，详细trace日志中怎样剖析，后面会详细介绍。

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关键字为：

timeout of broadcast BroadcastRecord

注意在剖析的时分，需求区别前台和后台播送。

（3）Service

前台服务，onCreate、onStart、onBind 在20s以内没有处理完结，会触发ANR
后台服务，onCreate、onStart、onBind 在200s以内没有处理完结，会触发ANR

logcat关键字为：

timeout executing service

（4）Contentprovider

Contentprovider在10s内没有处理完结，例如履行一个query操作，就会触发ANR

logcat关键字为：

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日志关键字剖析

----- 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<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+198)
  native: #01 pc 0051034e  /system/lib/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+382)
  native: #02 pc 0050b603  /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, 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<char, std::__1::char_traits<char>>&, bool)+1316)
  native: #06 pc 00524d8d  /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+941)
  native: #07 pc 004ec186  /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+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 线程调用栈参数介绍

"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调度时刻计算这个参数，我侧重介绍一下：

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的状况，除此之外，线程还有什么状况呢？

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:
     * <ul>
     *   <li>{@link Object#wait() Object.wait} with no timeout</li>
     *   <li>{@link #join() Thread.join} with no timeout</li>
     *   <li>{@link LockSupport#park() LockSupport.park}</li>
     * </ul>
     *
     * <p>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状况，就需求考虑是否存在主线程等候资源导致堵塞的场景。

咱们看下面这个场景：主线程开启一个异步使命，此异步使命与主线程一同持有一把锁，只有当异步使命履行完结之后，锁被开释，主线程才能拿到锁进行处理。

findViewById<Button>(R.id.btn_anr).setOnClickListener {
    CostTimeTask().execute("test")
    Log.d("TAG","execute --- ")
    synchronized(mLock){
        Toast.makeText(this,"异步使命履行完结",Toast.LENGTH_SHORT).show()
    }
}

inner class CostTimeTask : AsyncTask<String,Int,String>(){
     override fun doInBackground(vararg params: String?): String {
         synchronized(mLock){
             while (true){
             }
         }
     }
 }

我这边在模拟异步使命中的耗时操作，由于主线程只能比及异步使命处理完结之后，才能获取这把锁，否则就一向处于堵塞的状况，直到获取了这把锁。

"AsyncTask #1" prio=5 tid=15 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x12cbe0f0 self=0xc83e0400
  | sysTid=6148 nice=10 cgrp=default sched=0/0 handle=0xc454e970
  | state=R schedstat=( 6304787005 112481313 737 ) utm=629 stm=1 core=2 HZ=100
  | stack=0xc444b000-0xc444d000 stackSize=1042KB
  | held mutexes= "mutator lock"(shared held)
  at com.lay.datastore.DataStoreActivity$CostTimeTask.doInBackground(DataStoreActivity.kt:42)
  at com.lay.datastore.DataStoreActivity$CostTimeTask.doInBackground(DataStoreActivity.kt:38)
  at android.os.AsyncTask$2.call(AsyncTask.java:333)
  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:245)
  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" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x7583df30 self=0xe36f4000
  | sysTid=6084 nice=-10 cgrp=default sched=0/0 handle=0xe83b5494
  | state=S schedstat=( 4210489664 1169737873 12952 ) utm=123 stm=298 core=2 HZ=100
  | stack=0xff753000-0xff755000 stackSize=8MB
  | held mutexes=
  at com.lay.datastore.DataStoreActivity.onCreate$lambda-1(DataStoreActivity.kt:29)
  - waiting to lock <0x0493299a> (a java.lang.Object) held by thread 15
  at com.lay.datastore.DataStoreActivity.$r8$lambda$IFZrCDzOUja7d5eTPj5Nq-CEC-8(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)

（2）Blocked / Monitor

当主线程无法持续履行，那么就会进入Blocked的状况(假如日志中呈现状况为Monitor，那么也是跟Blocked相同)，一切的事情都将无法呼应；

Android进阶宝典 -- 如何通过ANR日志分析问题原因

此时线程的状况就处于Wait或许Monitor，一旦线程进入到这种状况，那么便是”濒死“的边际，此时线程处于堵塞挂起的状况

（3）Sleeping

如2.2 看到的日志，此时主线程的状况为Sleeping，从日志中看出由于在点击事情的时分，调用了sleep办法，从而导致的ANR，此时线程的状况也是反常的。

其实主线程的状况，是整个App的生命线，当主线程的状况呈现反常的时分，即便是没有发生ANR，那么也离ANR现已不远了，所以在剖析ANR状况的时分，在扫除了CPU等问题之后，要点需求重视主线程的状况，或许跟主线程归于同一个group的其他线程的状况。

2.2.4 ”死锁“问题的查找

其实在线程的堆栈最后一行，是带有mutexes锁信息的，假如不知道是否发生死锁，能够运用”held by“查找是否有对应的日志信息，假如查找到了，那么大概率便是死锁导致的，可是在客户端的开发过程中，死锁这种好像见到的还是比较少的。

看一下2.2.3中的例子，这种状况下主线程一向等候线程15开释锁从而导致了死锁，线程15便是AsyncTask线程，这同归于main线程组。

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

最终主线程就处于Blocked的状况，无法持续履行，导致ANR，而AsyncTask #1 线程则是处于Runnable的状况，一向等候，直到办法结束开释资源，可是这种状况下不会开释资源了。

相信同伴们看完这篇文章，再次拿到ANR日志之后，或许就没有那么难以下手了，当然这儿只是列举了最常见的ANR场景，像一些耗时Binder、cpu问题导致的ANR并没有介绍，由于在项目中或许也见的比较少，假如后续碰到这种日志信息，也会贴出来跟同伴们一同分享。

最近刚开通了微信公众号，各位同伴能够搜索【layz4Android】，或许扫码重视，每周不定时更新，也有惊喜红包哦，也能够后台留言感兴趣的专题，给各位同伴们产出文章。

Android进阶宝典 -- 如何通过ANR日志分析问题原因