一、前言：
前兩天，我已經(jīng)寫了一篇文章對(duì) ANR 的產(chǎn)生原理進(jìn)行了簡(jiǎn)單的探討，鏈接如下：
感興趣的大佬可以前去觀摩觀摩，今天這篇文章，將寫寫如何進(jìn)行 ANR 日志的分析。
注意：導(dǎo)致 ANR 的原因如下:
1、應(yīng)用層導(dǎo)致的ANR（耗時(shí)操作）
- 主線程耗時(shí)長(zhǎng)
- 主線程方法執(zhí)行了死循環(huán)
- 主線程等待子線程釋放鎖時(shí)間過長(zhǎng)
- 應(yīng)用內(nèi)存緊張，當(dāng)一個(gè)應(yīng)用長(zhǎng)期處于內(nèi)存緊張狀態(tài)，會(huì)導(dǎo)致頻繁內(nèi)存交換，進(jìn)而導(dǎo)致應(yīng)用的一些操作超時(shí)
2、系統(tǒng)層導(dǎo)致的ANR
- CPU被搶占：一般來說，前臺(tái)在玩游戲，可能會(huì)導(dǎo)致你的后臺(tái)廣播被搶占CPU
- 系統(tǒng)服務(wù)無法及時(shí)響應(yīng)：比如獲取系統(tǒng)聯(lián)系人等，系統(tǒng)的服務(wù)都是Binder機(jī)制，服務(wù)能力也是有限的，有可能系統(tǒng)服務(wù)長(zhǎng)時(shí)間不響應(yīng)導(dǎo)致ANR
- 其他應(yīng)用占用的大量?jī)?nèi)存
3、導(dǎo)出并查看 ANR 日志
當(dāng)系統(tǒng)出現(xiàn) ANR 時(shí)，設(shè)備會(huì)自動(dòng)將 ANR 日志輸出到 /data/anr/ 目錄下，如下所示：
image.png
可以導(dǎo)出設(shè)備所有 bug 日志，執(zhí)行命令后，在指定文件夾內(nèi)得到一個(gè) zip 文件，將文件解壓后打開，文件目錄如下所示：
解壓之后：
image.png
另外，該文件 D:\mybug\bugrep\bugreport-device.200216.002-2022-06-16-15-30-10.txt 內(nèi)也有有 anr 日志的打印，我們可以通過以下關(guān)鍵詞搜索該文件的一些異常信息，如：
特別注意搜索方式：
“main” prio=：搜索 anr 相關(guān)信息
beginning of crash：搜索 crash 相關(guān)信息
CPU usage from：搜索 cpu 使用信息
二、如何分析 ANR 日志
一個(gè) ANR 日志，會(huì)包含當(dāng)前設(shè)備中所有進(jìn)程的使用情況，每個(gè)進(jìn)程開頭都會(huì)
以----- pid 16808 at date ----- 來開頭，
以----- end 16808 -----來結(jié)尾，
如下所示：
----- pid 16808 at 2022-06-16 16:56:04 -----
Cmd line: com.example.demoproject
...
...
...
----- end 16808 -----
另外，每個(gè)進(jìn)程日志中都會(huì)有一些進(jìn)程內(nèi)存相關(guān)的信息，如：
----- pid 16808 at 2022-06-16 16:56:04 -----
Cmd line: com.example.demoproject
...
...
Total number of allocations 59378 // 進(jìn)程創(chuàng)建到現(xiàn)在一共創(chuàng)建了多少對(duì)象
Total bytes allocated 8815KB // 進(jìn)程創(chuàng)建到現(xiàn)在一共申請(qǐng)了多少內(nèi)存
Total bytes freed 6847KB // 進(jìn)程創(chuàng)建到現(xiàn)在一共釋放了多少內(nèi)存
Free memory 23MB // 空閑內(nèi)存（可用內(nèi)存）
Free memory until GC 23MB // GC前的空閑內(nèi)存
Free memory until OOME 190MB // OOM之前的可用內(nèi)存，當(dāng)這個(gè)值很小的時(shí)候，已經(jīng)處于內(nèi)存緊張狀態(tài)，應(yīng)用可能占用了過多的內(nèi)存
Total memory 25MB // 當(dāng)前總內(nèi)存（已用+可用）
Max memory 192MB // 進(jìn)程最多能申請(qǐng)的內(nèi)存
...
----- end 16808 -----
另外，每個(gè)進(jìn)程日志中都會(huì)有進(jìn)程堆棧信息，堆棧信息非常重要，它展示了發(fā)生 ANR 的進(jìn)程當(dāng)前的所有線程狀態(tài)。
----- pid 16808 at 2022-06-16 16:56:04 -----
...
suspend all histogram: Sum: 114us 99% C.I. 2us-27us Avg: 12.666us Max: 27us
DALVIK THREADS (14):
"Signal Catcher" daemon prio=5 tid=7 Runnable
| group="system" sCount=0 dsCount=0 flags=0 obj=0x182c0298 self=0x7914b9c000
| sysTid=16819 nice=0 cgrp=default sched=0/0 handle=0x791a98fd50
| state=R schedstat=( 28572293 3522448 11 ) utm=1 stm=1 core=0 HZ=100
| stack=0x791a899000-0x791a89b000 stackSize=991KB
| held mutexes= "mutator lock"(shared held)
native: #00 pc 00000000004108e8 /apex/com.android.runtime/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)
native: #01 pc 00000000004f8040 /apex/com.android.runtime/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+512)
native: #02 pc 000000000051297c /apex/com.android.runtime/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+828)
native: #03 pc 000000000050b7a0 /apex/com.android.runtime/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+456)
native: #04 pc 000000000050ac84 /apex/com.android.runtime/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool)+1964)
native: #05 pc 000000000050a364 /apex/com.android.runtime/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+844)
native: #06 pc 00000000004c5778 /apex/com.android.runtime/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+200)
native: #07 pc 00000000004d9bb0 /apex/com.android.runtime/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1352)
native: #08 pc 00000000004d8c5c /apex/com.android.runtime/lib64/libart.so (art::SignalCatcher::Run(void*)+252)
native: #09 pc 00000000000e68a0 /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+36)
native: #10 pc 0000000000084b6c /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)
(no managed stack frames)
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x72e0ee78 self=0x79aafbcc00
| sysTid=16808 nice=-10 cgrp=default sched=0/0 handle=0x79ac524ed0
| state=S schedstat=( 1140726262 41301458 368 ) utm=94 stm=20 core=0 HZ=100
| stack=0x7fe35ed000-0x7fe35ef000 stackSize=8192KB
| held mutexes=
at com.example.demoproject.view.MainActivity.doSomething(MainActivity.kt:51)
- waiting to lock <0x02250ad8> (a com.example.demoproject.view.MainActivity) held by thread 18
at com.example.demoproject.view.MainActivity.click2(MainActivity.kt:36)
at java.lang.reflect.Method.invoke(Native method)
at androidx.appcompat.app.AppCompatViewInflater$DeclaredOnClickListener.onClick(AppCompatViewInflater.java:441)
at android.view.View.performClick(View.java:7259)
at com.google.android.material.button.MaterialButton.performClick(MaterialButton.java:1194)
at android.view.View.performClickInternal(View.java:7236)
at android.view.View.access$3600(View.java:801)
at android.view.View$PerformClick.run(View.java:27896)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:214)
at android.app.ActivityThread.main(ActivityThread.java:7397)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:935)
"Jit thread pool worker thread 0" daemon prio=5 tid=2 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x182c0220 self=0x7919600000
| sysTid=16814 nice=0 cgrp=default sched=0/0 handle=0x791aa94d40
| state=S schedstat=( 44810570 11604064 76 ) utm=4 stm=0 core=0 HZ=100
| stack=0x791a996000-0x791a998000 stackSize=1023KB
| held mutexes=
kernel: (couldn't read /proc/self/task/16814/stack)
native: #00 pc 000000000008033c /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)
native: #01 pc 000000000014b1f4 /apex/com.android.runtime/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
native: #02 pc 00000000005143dc /apex/com.android.runtime/lib64/libart.so (art::ThreadPool::GetTask(art::Thread*)+256)
native: #03 pc 0000000000513768 /apex/com.android.runtime/lib64/libart.so (art::ThreadPoolWorker::Run()+144)
native: #04 pc 0000000000513228 /apex/com.android.runtime/lib64/libart.so (art::ThreadPoolWorker::Callback(void*)+148)
native: #05 pc 00000000000e68a0 /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+36)
native: #06 pc 0000000000084b6c /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)
(no managed stack frames)
...
----- end 16808 -----
如上截圖中，有三個(gè)線程，一個(gè)是 Signal Catcher 線程，一個(gè)是 main 線程，一個(gè)是 Jit thread pool worker thread 0，他們的線程狀態(tài)分別是 Runnable 、 blocked 和 native 狀態(tài)。
而在 Java 中，線程狀態(tài)有6種（具體可參考我之前寫的文章，了解更詳細(xì)的多線程和并發(fā)知識(shí)：一文搞懂多線程和并發(fā)編程
），如下所示：
- NEW - 創(chuàng)建狀態(tài)
- RUNNABLE - 就緒或運(yùn)行狀態(tài)
- BLOCKED - 阻塞狀態(tài)
- WATING - 等待狀態(tài)
- TIMED_WAITING - 定時(shí)等待狀態(tài)
- TERMINATED - 終止?fàn)顟B(tài)
那么，上述日志中的 native 狀態(tài)是什么呢？
其實(shí)該狀態(tài)是 cpp 代碼中定義的線程狀態(tài)，他跟 java 定義的線程狀態(tài)關(guān)系如下：
image.png
由上可知，native 狀態(tài)對(duì)應(yīng)的 java 線程狀態(tài)是 runnable 狀態(tài)。
堆棧信息是我們分析ANR的第一個(gè)重要的信息，一般來說：
- 主線程處于 BLOCK / WAITING / TIMEWAITING 狀態(tài)，基本上是函數(shù)阻塞導(dǎo)致的 anr
- 若主線程無異常，則應(yīng)該排查 CPU 負(fù)載和內(nèi)存環(huán)境等其他因素
另外，在 anr 日志中，還有一些常見參數(shù)，他們的含義如下：
- group：線程所處的線程組
- sCount：線程被正常掛起的次數(shù)
- dsCount：線程因調(diào)試而掛起次數(shù)
- nice：線程的調(diào)度優(yōu)先級(jí)
- utm：線程在用戶態(tài)中調(diào)度時(shí)間值
- stm：線程在內(nèi)核態(tài)中的調(diào)度時(shí)間值
- core：最后執(zhí)行這個(gè)線程的CPU核序號(hào)
三、ANR 案例分析
1、案例一 - Slepping anr
MainActivity 代碼如下：
class MainActivity : AppCompatActivity() {
override fun onCreate(savedInstanceState: Bundle?) {
super.onCreate(savedInstanceState)
setContentView(R.layout.activity_main)
}
/**
* 點(diǎn)擊睡眠 10s
*/
fun clickToSleep(view: View) {
Thread.sleep(10_000)
}
}
當(dāng)點(diǎn)擊按鈕睡眠 10s 后，我們左滑或者點(diǎn)擊返回鍵退出 MainActivity（由于主線程正在睡眠，所以此時(shí)是無法退出成功的），等待一段時(shí)間，系統(tǒng)將會(huì)彈出 ANR 彈窗。
我們導(dǎo)出 ANR 日志并打開：
"main" prio=5 tid=1 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x72e0ee78 self=0x79aafbcc00
| sysTid=16356 nice=-10 cgrp=default sched=0/0 handle=0x79ac524ed0
| state=S schedstat=( 1075827038 33414740 291 ) utm=93 stm=14 core=2 HZ=100
| stack=0x7fe35ed000-0x7fe35ef000 stackSize=8192KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x04fbafa5> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:440)
- locked <0x04fbafa5> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:356)
at com.example.demoproject.view.MainActivity.clickToSleep(MainActivity.kt:57)
at java.lang.reflect.Method.invoke(Native method)
at androidx.appcompat.app.AppCompatViewInflater$DeclaredOnClickListener.onClick(AppCompatViewInflater.java:441)
at android.view.View.performClick(View.java:7259)
at com.google.android.material.button.MaterialButton.performClick(MaterialButton.java:1194)
at android.view.View.performClickInternal(View.java:7236)
at android.view.View.access$3600(View.java:801)
at android.view.View$PerformClick.run(View.java:27896)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:214)
at android.app.ActivityThread.main(ActivityThread.java:7397)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:935)
從堆棧信息中也很容易發(fā)現(xiàn)，在執(zhí)行到 MainActivity.clickToSleep 方法時(shí)，線程進(jìn)行了睡眠，最終導(dǎo)致 anr。
2、案例二 - Blocked anr
MainActivity 代碼如下：
class MainActivity : AppCompatActivity() {
override fun onCreate(savedInstanceState: Bundle?) {
super.onCreate(savedInstanceState)
setContentView(R.layout.activity_main)
}
/**
* 點(diǎn)擊按鈕1 - 創(chuàng)建一個(gè)子線程并持有當(dāng)前 Activity 對(duì)象鎖然后開始睡眠 10s
*/
fun click1(view: View) {
testBlockThread()
}
/**
* 點(diǎn)擊按鈕2 - 在主線程中嘗試獲取 Activity 對(duì)象鎖并打印 log
*/
fun click2(view: View) {
doSomething()
}
private fun testBlockThread() {
val thread = Thread {
synchronized(this) {
Log.i("testLog", "開始睡眠 10s.. 當(dāng)前線程名稱=${Thread.currentThread().name} 線程id=${Thread.currentThread().id}")
Thread.sleep(10_000)
}
}
thread.name = "MyTestBlockThread"
thread.start()
}
private fun doSomething() {
synchronized(this) {
Log.i("testLog", "doSomething.. 當(dāng)前線程名稱=${Thread.currentThread().name} 線程id=${Thread.currentThread().id}")
}
}
當(dāng)首先點(diǎn)擊按鈕1時(shí)，會(huì)創(chuàng)建一個(gè)子線程 MyTestBlockThread 并持有當(dāng)前 Activity 對(duì)象鎖然后開始睡眠 10s，然后繼續(xù)點(diǎn)擊按鈕2，此時(shí)主線程將會(huì)嘗試獲取 Activity 對(duì)象鎖并執(zhí)行，由于鎖正在被子線程 MyTestBlockThread持有，因此，主線程將會(huì)一直被 block直到子線程釋放鎖。
在主線程被 block 期間，我們左滑或者點(diǎn)擊返回鍵退出 MainActivity（由于主線程正在被 block，所以此時(shí)是無法退出成功的），等待一段時(shí)間，系統(tǒng)將會(huì)彈出 ANR 彈窗。
下面我們導(dǎo)出 ANR 日志并打開：
image.png
可以發(fā)現(xiàn)，這里有一行：
- waiting to lock <0x02250ad8> (a com.example.demoproject.view.MainActivity) held by thread 18
其含義就是，主線程正在被 block， 其正在等待 線程18 釋放鎖，最終因此導(dǎo)致出現(xiàn)了 ANR。
那么，這個(gè) 線程18 是誰呢？我們繼續(xù)看 anr 日志：
image.png
在這里，發(fā)現(xiàn)這一行日志：
"MyTestBlockThread" prio=5 tid=18 Sleeping
其含義就是：線程 MyTestBlockThread 正在 Sleeping，它的 prio=5 tid=18。
3、案例三 - 耗時(shí)或死循環(huán)方法
MainActivity 代碼如下：
class MainActivity : AppCompatActivity() {
override fun onCreate(savedInstanceState: Bundle?) {
super.onCreate(savedInstanceState)
setContentView(R.layout.activity_main)
}
fun click(view: View) {
doSomething()
}
private fun doSomething() {
while (true) {
Log.i("testLog", "doSomething.. 當(dāng)前線程名稱=${Thread.currentThread().name} 線程id=${Thread.currentThread().id}")
}
}
}
當(dāng)我們點(diǎn)擊按鈕時(shí)，會(huì)在主線程通過一個(gè)死循環(huán)不斷打印 log，因此 doSomething() 方法我們可以認(rèn)為是一個(gè)耗時(shí)方法，點(diǎn)擊按鈕后，我們左滑或者點(diǎn)擊返回鍵退出 MainActivity（由于主線程正在忙碌中，所以此時(shí)是無法退出成功的），等待一段時(shí)間，系統(tǒng)將會(huì)彈出 ANR 彈窗。
下面我們導(dǎo)出 ANR 日志并打開：
----- pid 13231 at 2022-06-17 14:23:41 -----
Cmd line: com.example.demoproject
...
"main" prio=5 tid=1 Runnable
| group="main" sCount=0 dsCount=0 flags=0 obj=0x72b20e78 self=0x77fe5a6c00
| sysTid=13231 nice=-10 cgrp=default sched=0/0 handle=0x77ffb0eed0
| state=R schedstat=( 31694533124 58819622 723 ) utm=1310 stm=1859 core=5 HZ=100
| stack=0x7fdc2b7000-0x7fdc2b9000 stackSize=8192KB
| held mutexes= "mutator lock"(shared held)
native: #00 pc 00000000004108e8 /apex/com.android.runtime/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)
native: #01 pc 00000000004f8040 /apex/com.android.runtime/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+512)
native: #02 pc 000000000051297c /apex/com.android.runtime/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+828)
native: #03 pc 00000000004f8d4c /apex/com.android.runtime/lib64/libart.so (art::Thread::RunCheckpointFunction()+176)
native: #04 pc 00000000003713fc /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::CheckJNI::ReleaseStringCharsInternal(char const*, _JNIEnv*, _jstring*, void const*, bool, bool)+1356)
native: #05 pc 00000000001507cc /system/lib64/libandroid_runtime.so (android::android_util_Log_println_native(_JNIEnv*, _jobject*, int, int, _jstring*, _jstring*)+232)
at android.util.Log.println_native(Native method)
at android.util.Log.i(Log.java:176)
at com.example.demoproject.view.MainActivity.doSomething(MainActivity.kt:52)
at com.example.demoproject.view.MainActivity.click2(MainActivity.kt:36)
at java.lang.reflect.Method.invoke(Native method)
at androidx.appcompat.app.AppCompatViewInflater$DeclaredOnClickListener.onClick(AppCompatViewInflater.java:441)
at android.view.View.performClick(View.java:7259)
at com.google.android.material.button.MaterialButton.performClick(MaterialButton.java:1194)
at android.view.View.performClickInternal(View.java:7236)
at android.view.View.access$3600(View.java:801)
at android.view.View$PerformClick.run(View.java:27896)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:214)
at android.app.ActivityThread.main(ActivityThread.java:7397)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:935)
...
----- end 16808 -----
發(fā)現(xiàn)主線程正處于 Runnable 狀態(tài)，并不是處于空閑狀態(tài)，堆棧信息中有一行關(guān)鍵日志：
at com.example.demoproject.view.MainActivity.doSomething(MainActivity.kt:52)
這就說明是是主線程中正在執(zhí)行 doSomething 這個(gè)方法導(dǎo)致的 anr。
4、案例四 - 正常情況
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x72e0ee78 self=0x79aafbcc00
| sysTid=1496 nice=-2 cgrp=default sched=0/0 handle=0x79ac524ed0
| state=S schedstat=( 50585681414 30364690662 64096 ) utm=3092 stm=1966 core=2 HZ=100
| stack=0x7fe35ed000-0x7fe35ef000 stackSize=8192KB
| held mutexes=
kernel: (couldn't read /proc/self/task/1496/stack)
native: #00 pc 00000000000d0f58 /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
native: #01 pc 00000000000180bc /system/lib64/libutils.so (android::Looper::pollInner(int)+144)
native: #02 pc 0000000000017f8c /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+56)
native: #03 pc 000000000013b8f4 /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:336)
at android.os.Looper.loop(Looper.java:174)
at com.android.server.SystemServer.run(SystemServer.java:546)
at com.android.server.SystemServer.main(SystemServer.java:354)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:913)
上述主線程堆棧就是一個(gè)很正常的空閑堆棧，表明主線程正在等待新的消息。如果ANR日志里主線程是這樣一個(gè)狀態(tài)，那可能有兩個(gè)原因?qū)е?anr：
- 該 anr 是 cpu 資源搶占或內(nèi)存緊張等其他因素引起
- 這份 anr 日志抓取的時(shí)候，主線程已經(jīng)恢復(fù)正常
5、案例五 - CPU 被其他應(yīng)用搶占
當(dāng) anr 日志中找不到有效的信息，這種情況我們就得看 cpu 信息了，
這個(gè)日志一般在 bugreport.txt 文件中可以查看，具體怎么導(dǎo)出 bugreport.txt 文件可見本文的《導(dǎo)出并查看 ANR 日志》那里的步驟。
取出 cpu 信息日志如下：
-------------------------------------------------------------------------------
DUMP OF SERVICE CRITICAL cpuinfo:
Load: 5.28 / 5.71 / 5.58
CPU usage from 275243ms to 190078ms ago (2022-06-16 15:25:36.158 to 2022-06-16 15:27:01.323):
51% 695/audioserver: 35% user + 15% kernel / faults: 3071 minor
17% 1496/system_server: 9% user + 8% kernel / faults: 43598 minor
14% 2077/VosRXThread: 0% user + 14% kernel
3.1% 666/android.hardware.sensors@1.0-service: 0.8% user + 2.3% kernel / faults: 170 minor
3.1% 642/android.hardware.audio@2.0-service: 0.2% user + 2.8% kernel / faults: 2 minor
...................................省略 N 行...........................................
21% TOTAL: 6.4% user + 10% kernel + 0.1% iowait + 2.4% irq + 1.4% softirq
--------- 0.007s was the duration of dumpsys cpuinfo, ending at: 2022-06-16 15:30:11
-------------------------------------------------------------------------------
這個(gè)日志怎么分析呢？它的這個(gè)部分的含義如下：
1、Load: 5.28 / 5.71 / 5.58 // 代表了設(shè)備在 1、5、15 分鐘內(nèi) 正在使用和等待使用CPU 的活動(dòng)進(jìn)程的平均數(shù)
2、CPU usage from 275243ms to 190078ms ago (2022-06-16 15:25:36.158 to 2022-06-16 15:27:01.323) // 表明負(fù)載信息抓取是在 275243ms ~ 190078ms之間的，且時(shí)間點(diǎn)是從 2022-06-16 15:25:36.158 開始
3、中間打印百分比的部分 // 各個(gè)進(jìn)程占用的CPU的詳細(xì)情況
4、最后一行 // 各個(gè)進(jìn)程合計(jì)占用的CPU信息。
還有一些名詞和含義如下：
1、user: 用戶態(tài)
2、kernel: 內(nèi)核態(tài)
3、faults: 內(nèi)存缺頁，minor —— 輕微的，major —— 重度，需要從磁盤拿數(shù)據(jù)
4、iowait: IO 等待占比，如果占比很高，意味著有很大可能是io耗時(shí)導(dǎo)致ANR
5、irq: 硬中斷，
6、softirq: 軟中斷
注意以下兩點(diǎn)：
- 如果 owait 占比很高，意味著有很大可能是 io 耗時(shí)導(dǎo)致的 ANR，具體進(jìn)一步查看有沒有進(jìn)程 faults major 比較多
- 單進(jìn)程 CPU 的負(fù)載并不是以100%為上限，而是有幾個(gè)核就有百分之幾百，如 4 核，那么上限為400%
了解了如何看 cpu 日志后，我們?cè)倩氐骄唧w的日志中查看，
發(fā)現(xiàn)如上排在第一位的進(jìn)程 audioserver 即為系統(tǒng)中占用 cpu 最高的進(jìn)程，達(dá)到 51%，這屬于正常的 cpu 占用范圍，因此，此日志中并沒有發(fā)現(xiàn)導(dǎo)致 anr 的有效日志。
如果發(fā)現(xiàn)排在第一位的進(jìn)程占用了極高的 cpu 資源，那么就極有可能是這個(gè)進(jìn)程導(dǎo)致的 anr 。
6、案例六 - 系統(tǒng)服務(wù)超時(shí)
如果系統(tǒng)服務(wù)超時(shí)，日志中一般會(huì)包含 BinderProxy.transactNative 關(guān)鍵字，如下：
image.png
從堆?？梢钥闯?getActiveNetworkInfo 方法發(fā)生了 ANR。我們知道，系統(tǒng)的服務(wù)都是 Binder 機(jī)制，Binder 一共有16個(gè)線程，服務(wù)能力也是有限的，所以有可能系統(tǒng)服務(wù)長(zhǎng)時(shí)間不響應(yīng)導(dǎo)致ANR。
如果其他應(yīng)用占用了 Binder 線程，那么當(dāng)前應(yīng)用只能等待，可進(jìn)一步搜索 blockUntilThreadAvailable 關(guān)鍵字
at android.os.Binder.blockUntilThreadAvailable(Native method)
如果有發(fā)現(xiàn)某個(gè)線程的堆棧包含此字樣，可進(jìn)一步看其堆棧確定其調(diào)用了什么系統(tǒng)服務(wù)。
此類 ANR 屬于系統(tǒng)環(huán)境的問題，如果某類型機(jī)器上頻繁發(fā)生此問題，應(yīng)用層可以考慮規(guī)避策略。
7、案例七 - 內(nèi)存緊張
如果日志中 CPU 和堆棧都正常，仍舊發(fā)生了 ANR，那么可以進(jìn)一步考慮是否是內(nèi)存緊張導(dǎo)致的 anr。
在 bugreport.txt 文件中，我們還可以通過如下關(guān)鍵字 am_meminfo 搜索日志：
06-16 02:14:42.014 1000 1496 1575 I am_meminfo: [1163550720,172752896,7536640,272494592,512559104]
數(shù)組中的五個(gè)值分別指的是
- Cached
- Free
- Zram
- Kernel
- Native
其中Cached + Free代表當(dāng)前整個(gè)手機(jī)的可用內(nèi)存，如果值很小，那就意味著處于內(nèi)存緊張狀態(tài)。
一般低內(nèi)存的判定閾值為：4G 內(nèi)存手機(jī)以下閥值：350MB，以上閥值則為：450MB
另外，如果通過關(guān)鍵字 am_meminfo 搜索不出任何日志，那么我們可以通過 onTrimMemory 搜索，如：
10-31 22:37:33.458 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
它也可以作為內(nèi)存緊張的一個(gè)參考判斷，可見，這里的 level 為 80 ，我們看看 Android 中是怎么定義這個(gè) level 的：
/**
* 進(jìn)程接近后臺(tái) LRU 列表的末尾，如果沒有很快找到更多內(nèi)存，進(jìn)程將被殺死
*/
static final int TRIM_MEMORY_COMPLETE = 80;
/**
* 進(jìn)程在后臺(tái) LRU 列表的中間；釋放內(nèi)存可以幫助系統(tǒng)保持列表中稍后運(yùn)行的其他進(jìn)程，以獲得更好的整體性能
*/
static final int TRIM_MEMORY_MODERATE = 60;
/**
* 進(jìn)程已進(jìn)入 LRU 列表。這是一個(gè)清理資源的好機(jī)會(huì)，如果用戶返回應(yīng)用程序，這些資源可以高效快速地重新構(gòu)建
*/
static final int TRIM_MEMORY_BACKGROUND = 40;
/**
* 進(jìn)程已顯示用戶界面，現(xiàn)在不再顯示。此時(shí)應(yīng)釋放 UI 的大量分配，以便更好地管理內(nèi)存
*/
static final int TRIM_MEMORY_UI_HIDDEN = 20;
/**
* 該進(jìn)程不是可消耗的后臺(tái)進(jìn)程，但設(shè)備運(yùn)行的內(nèi)存極低，即將無法保持任何后臺(tái)進(jìn)程運(yùn)行。您正在運(yùn)行的進(jìn)程應(yīng)盡可能多地釋放非關(guān)鍵資源，以允許該內(nèi)存在其他地方使用。在此之后將發(fā)生的下一件事是調(diào)用 onLowMemory() 以報(bào)告在后臺(tái)根本無法保留任何內(nèi)容，這種情況可能會(huì)開始顯著影響用戶
*/
static final int TRIM_MEMORY_RUNNING_CRITICAL = 15;
/**
* 進(jìn)程不是可消耗的后臺(tái)進(jìn)程，但設(shè)備內(nèi)存不足。您正在運(yùn)行的進(jìn)程應(yīng)該釋放不需要的資源，以允許在其他地方使用該內(nèi)存
*/
static final int TRIM_MEMORY_RUNNING_LOW = 10;
/**
* 進(jìn)程不是可消耗的后臺(tái)進(jìn)程，但設(shè)備運(yùn)行的內(nèi)存適中。您正在運(yùn)行的進(jìn)程可能希望釋放一些不需要的資源以供其他地方使用
*/
static final int TRIM_MEMORY_RUNNING_MODERATE = 5;
由此可知，80 是一個(gè)很嚴(yán)重的級(jí)別，如果沒有很快找到更多內(nèi)存，進(jìn)程將被殺死，而且從日志中可以看到，這個(gè)進(jìn)程是 launcher 進(jìn)程，連桌面都快要被殺死，那普通應(yīng)用肯定也不會(huì)好到哪去。
一般來說，設(shè)備內(nèi)存緊張，會(huì)導(dǎo)致多個(gè)應(yīng)用發(fā)生 ANR。
