一躲雅、前言：
前兩天兵扬，我已經(jīng)寫了一篇文章對 ANR 的產(chǎn)生原理進行了簡單的探討而账，鏈接如下：
感興趣的大佬可以前去觀摩觀摩酌儒，今天這篇文章刻诊，將寫寫如何進行 ANR 日志的分析驻襟。
注意：導(dǎo)致 ANR 的原因如下:
1憨募、應(yīng)用層導(dǎo)致的ANR（耗時操作）
- 主線程耗時長
- 主線程方法執(zhí)行了死循環(huán)
- 主線程等待子線程釋放鎖時間過長
- 應(yīng)用內(nèi)存緊張薯鳍，當一個應(yīng)用長期處于內(nèi)存緊張狀態(tài)涕烧，會導(dǎo)致頻繁內(nèi)存交換月而，進而導(dǎo)致應(yīng)用的一些操作超時
2、系統(tǒng)層導(dǎo)致的ANR
- CPU被搶占：一般來說议纯，前臺在玩游戲父款，可能會導(dǎo)致你的后臺廣播被搶占CPU
- 系統(tǒng)服務(wù)無法及時響應(yīng)：比如獲取系統(tǒng)聯(lián)系人等，系統(tǒng)的服務(wù)都是Binder機制瞻凤，服務(wù)能力也是有限的憨攒，有可能系統(tǒng)服務(wù)長時間不響應(yīng)導(dǎo)致ANR
- 其他應(yīng)用占用的大量內(nèi)存
3、導(dǎo)出并查看 ANR 日志
當系統(tǒng)出現(xiàn) ANR 時阀参，設(shè)備會自動將 ANR 日志輸出到 /data/anr/ 目錄下肝集，如下所示：
image.png
可以導(dǎo)出設(shè)備所有 bug 日志，執(zhí)行命令后蛛壳，在指定文件夾內(nèi)得到一個 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 日志
一個 ANR 日志砌函，會包含當前設(shè)備中所有進程的使用情況，每個進程開頭都會
以----- pid 16808 at date ----- 來開頭溜族，
以----- end 16808 -----來結(jié)尾胸嘴，
如下所示：
----- pid 16808 at 2022-06-16 16:56:04 -----
Cmd line: com.example.demoproject
...
...
...
----- end 16808 -----
另外，每個進程日志中都會有一些進程內(nèi)存相關(guān)的信息斩祭，如：
----- pid 16808 at 2022-06-16 16:56:04 -----
Cmd line: com.example.demoproject
...
...
Total number of allocations 59378 // 進程創(chuàng)建到現(xiàn)在一共創(chuàng)建了多少對象
Total bytes allocated 8815KB // 進程創(chuàng)建到現(xiàn)在一共申請了多少內(nèi)存
Total bytes freed 6847KB // 進程創(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)存，當這個值很小的時候乡话，已經(jīng)處于內(nèi)存緊張狀態(tài)摧玫，應(yīng)用可能占用了過多的內(nèi)存
Total memory 25MB // 當前總內(nèi)存（已用+可用）
Max memory 192MB // 進程最多能申請的內(nèi)存
...
----- end 16808 -----
另外，每個進程日志中都會有進程堆棧信息，堆棧信息非常重要诬像，它展示了發(fā)生 ANR 的進程當前的所有線程狀態(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 -----
如上截圖中，有三個線程坏挠，一個是 Signal Catcher 線程芍躏，一個是 main 線程，一個是 Jit thread pool worker thread 0降狠，他們的線程狀態(tài)分別是 Runnable 对竣、 blocked 和 native 狀態(tài)。
而在 Java 中榜配，線程狀態(tài)有6種（具體可參考我之前寫的文章否纬，了解更詳細的多線程和并發(fā)知識：一文搞懂多線程和并發(fā)編程
），如下所示：
- NEW - 創(chuàng)建狀態(tài)
- RUNNABLE - 就緒或運行狀態(tài)
- BLOCKED - 阻塞狀態(tài)
- WATING - 等待狀態(tài)
- TIMED_WAITING - 定時等待狀態(tài)
- TERMINATED - 終止狀態(tài)
那么蛋褥，上述日志中的 native 狀態(tài)是什么呢临燃？
其實該狀態(tài)是 cpp 代碼中定義的線程狀態(tài)，他跟 java 定義的線程狀態(tài)關(guān)系如下：
image.png
由上可知烙心，native 狀態(tài)對應(yīng)的 java 線程狀態(tài)是 runnable 狀態(tài)膜廊。
堆棧信息是我們分析ANR的第一個重要的信息，一般來說：
- 主線程處于 BLOCK / WAITING / TIMEWAITING 狀態(tài)淫茵，基本上是函數(shù)阻塞導(dǎo)致的 anr
- 若主線程無異常爪瓜，則應(yīng)該排查 CPU 負載和內(nèi)存環(huán)境等其他因素
另外，在 anr 日志中痘昌，還有一些常見參數(shù)钥勋，他們的含義如下：
- group：線程所處的線程組
- sCount：線程被正常掛起的次數(shù)
- dsCount：線程因調(diào)試而掛起次數(shù)
- nice：線程的調(diào)度優(yōu)先級
- utm：線程在用戶態(tài)中調(diào)度時間值
- stm：線程在內(nèi)核態(tài)中的調(diào)度時間值
- core：最后執(zhí)行這個線程的CPU核序號
三、ANR 案例分析
1辆苔、案例一 - Slepping anr
MainActivity 代碼如下：
class MainActivity : AppCompatActivity() {
override fun onCreate(savedInstanceState: Bundle?) {
super.onCreate(savedInstanceState)
setContentView(R.layout.activity_main)
}
/**
* 點擊睡眠 10s
*/
fun clickToSleep(view: View) {
Thread.sleep(10_000)
}
}
當點擊按鈕睡眠 10s 后算灸，我們左滑或者點擊返回鍵退出 MainActivity（由于主線程正在睡眠，所以此時是無法退出成功的）驻啤，等待一段時間菲驴，系統(tǒng)將會彈出 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 方法時赊瞬，線程進行了睡眠，最終導(dǎo)致 anr贼涩。
2巧涧、案例二 - Blocked anr
MainActivity 代碼如下：
class MainActivity : AppCompatActivity() {
override fun onCreate(savedInstanceState: Bundle?) {
super.onCreate(savedInstanceState)
setContentView(R.layout.activity_main)
}
/**
* 點擊按鈕1 - 創(chuàng)建一個子線程并持有當前 Activity 對象鎖然后開始睡眠 10s
*/
fun click1(view: View) {
testBlockThread()
}
/**
* 點擊按鈕2 - 在主線程中嘗試獲取 Activity 對象鎖并打印 log
*/
fun click2(view: View) {
doSomething()
}
private fun testBlockThread() {
val thread = Thread {
synchronized(this) {
Log.i("testLog", "開始睡眠 10s.. 當前線程名稱=${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.. 當前線程名稱=${Thread.currentThread().name} 線程id=${Thread.currentThread().id}")
}
}
當首先點擊按鈕1時，會創(chuàng)建一個子線程 MyTestBlockThread 并持有當前 Activity 對象鎖然后開始睡眠 10s遥倦，然后繼續(xù)點擊按鈕2谤绳，此時主線程將會嘗試獲取 Activity 對象鎖并執(zhí)行，由于鎖正在被子線程 MyTestBlockThread持有，因此缩筛，主線程將會一直被 block直到子線程釋放鎖消略。
在主線程被 block 期間，我們左滑或者點擊返回鍵退出 MainActivity（由于主線程正在被 block瞎抛，所以此時是無法退出成功的）艺演，等待一段時間，系統(tǒng)將會彈出 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。
那么懒浮，這個 線程18 是誰呢飘弧？我們繼續(xù)看 anr 日志：
image.png
在這里，發(fā)現(xiàn)這一行日志：
"MyTestBlockThread" prio=5 tid=18 Sleeping
其含義就是：線程 MyTestBlockThread 正在 Sleeping次伶，它的 prio=5 tid=18。
3稽穆、案例三 - 耗時或死循環(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.. 當前線程名稱=${Thread.currentThread().name} 線程id=${Thread.currentThread().id}")
}
}
}
當我們點擊按鈕時，會在主線程通過一個死循環(huán)不斷打印 log哟楷，因此 doSomething() 方法我們可以認為是一個耗時方法，點擊按鈕后否灾，我們左滑或者點擊返回鍵退出 MainActivity（由于主線程正在忙碌中卖擅，所以此時是無法退出成功的），等待一段時間墨技，系統(tǒng)將會彈出 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 這個方法導(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)
上述主線程堆棧就是一個很正常的空閑堆棧崭别，表明主線程正在等待新的消息脐嫂。如果ANR日志里主線程是這樣一個狀態(tài)统刮，那可能有兩個原因?qū)е?anr：
- 該 anr 是 cpu 資源搶占或內(nèi)存緊張等其他因素引起
- 這份 anr 日志抓取的時候，主線程已經(jīng)恢復(fù)正常
5账千、案例五 - CPU 被其他應(yīng)用搶占
當 anr 日志中找不到有效的信息，這種情況我們就得看 cpu 信息了暗膜，
這個日志一般在 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
-------------------------------------------------------------------------------
這個日志怎么分析呢学搜？它的這個部分的含義如下：
1娃善、Load: 5.28 / 5.71 / 5.58 // 代表了設(shè)備在 1、5瑞佩、15 分鐘內(nèi) 正在使用和等待使用CPU 的活動進程的平均數(shù)
2聚磺、CPU usage from 275243ms to 190078ms ago (2022-06-16 15:25:36.158 to 2022-06-16 15:27:01.323) // 表明負載信息抓取是在 275243ms ~ 190078ms之間的，且時間點是從 2022-06-16 15:25:36.158 開始
3炬丸、中間打印百分比的部分 // 各個進程占用的CPU的詳細情況
4瘫寝、最后一行 // 各個進程合計占用的CPU信息。
還有一些名詞和含義如下：
1稠炬、user: 用戶態(tài)
2焕阿、kernel: 內(nèi)核態(tài)
3、faults: 內(nèi)存缺頁首启，minor —— 輕微的暮屡，major —— 重度，需要從磁盤拿數(shù)據(jù)
4毅桃、iowait: IO 等待占比褒纲，如果占比很高，意味著有很大可能是io耗時導(dǎo)致ANR
5钥飞、irq: 硬中斷莺掠，
6、softirq: 軟中斷
注意以下兩點：
- 如果 owait 占比很高代承，意味著有很大可能是 io 耗時導(dǎo)致的 ANR汁蝶，具體進一步查看有沒有進程 faults major 比較多
- 單進程 CPU 的負載并不是以100%為上限，而是有幾個核就有百分之幾百论悴，如 4 核掖棉，那么上限為400%
了解了如何看 cpu 日志后，我們再回到具體的日志中查看膀估，
發(fā)現(xiàn)如上排在第一位的進程 audioserver 即為系統(tǒng)中占用 cpu 最高的進程幔亥，達到 51%，這屬于正常的 cpu 占用范圍察纯，因此帕棉，此日志中并沒有發(fā)現(xiàn)導(dǎo)致 anr 的有效日志针肥。
如果發(fā)現(xiàn)排在第一位的進程占用了極高的 cpu 資源，那么就極有可能是這個進程導(dǎo)致的 anr 香伴。
6慰枕、案例六 - 系統(tǒng)服務(wù)超時
如果系統(tǒng)服務(wù)超時，日志中一般會包含 BinderProxy.transactNative 關(guān)鍵字即纲，如下：
image.png
從堆椌甙铮可以看出 getActiveNetworkInfo 方法發(fā)生了 ANR。我們知道低斋，系統(tǒng)的服務(wù)都是 Binder 機制蜂厅，Binder 一共有16個線程，服務(wù)能力也是有限的膊畴，所以有可能系統(tǒng)服務(wù)長時間不響應(yīng)導(dǎo)致ANR掘猿。
如果其他應(yīng)用占用了 Binder 線程，那么當前應(yīng)用只能等待唇跨，可進一步搜索 blockUntilThreadAvailable 關(guān)鍵字
at android.os.Binder.blockUntilThreadAvailable(Native method)
如果有發(fā)現(xiàn)某個線程的堆棧包含此字樣稠通，可進一步看其堆棧確定其調(diào)用了什么系統(tǒng)服務(wù)。
此類 ANR 屬于系統(tǒng)環(huán)境的問題轻绞，如果某類型機器上頻繁發(fā)生此問題采记，應(yīng)用層可以考慮規(guī)避策略。
7政勃、案例七 - 內(nèi)存緊張
如果日志中 CPU 和堆棧都正常唧龄，仍舊發(fā)生了 ANR，那么可以進一步考慮是否是內(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ù)組中的五個值分別指的是
- Cached
- Free
- Zram
- Kernel
- Native
其中Cached + Free代表當前整個手機的可用內(nèi)存，如果值很小懒叛，那就意味著處于內(nèi)存緊張狀態(tài)丸冕。
一般低內(nèi)存的判定閾值為：4G 內(nèi)存手機以下閥值：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)存緊張的一個參考判斷诅迷，可見佩番，這里的 level 為 80 ，我們看看 Android 中是怎么定義這個 level 的：
/**
* 進程接近后臺 LRU 列表的末尾罢杉，如果沒有很快找到更多內(nèi)存趟畏，進程將被殺死
*/
static final int TRIM_MEMORY_COMPLETE = 80;
/**
* 進程在后臺 LRU 列表的中間；釋放內(nèi)存可以幫助系統(tǒng)保持列表中稍后運行的其他進程滩租，以獲得更好的整體性能
*/
static final int TRIM_MEMORY_MODERATE = 60;
/**
* 進程已進入 LRU 列表赋秀。這是一個清理資源的好機會利朵，如果用戶返回應(yīng)用程序，這些資源可以高效快速地重新構(gòu)建
*/
static final int TRIM_MEMORY_BACKGROUND = 40;
/**
* 進程已顯示用戶界面猎莲，現(xiàn)在不再顯示绍弟。此時應(yīng)釋放 UI 的大量分配，以便更好地管理內(nèi)存
*/
static final int TRIM_MEMORY_UI_HIDDEN = 20;
/**
* 該進程不是可消耗的后臺進程著洼，但設(shè)備運行的內(nèi)存極低晌柬，即將無法保持任何后臺進程運行。您正在運行的進程應(yīng)盡可能多地釋放非關(guān)鍵資源郭脂，以允許該內(nèi)存在其他地方使用。在此之后將發(fā)生的下一件事是調(diào)用 onLowMemory() 以報告在后臺根本無法保留任何內(nèi)容澈歉，這種情況可能會開始顯著影響用戶
*/
static final int TRIM_MEMORY_RUNNING_CRITICAL = 15;
/**
* 進程不是可消耗的后臺進程展鸡，但設(shè)備內(nèi)存不足。您正在運行的進程應(yīng)該釋放不需要的資源埃难，以允許在其他地方使用該內(nèi)存
*/
static final int TRIM_MEMORY_RUNNING_LOW = 10;
/**
* 進程不是可消耗的后臺進程莹弊，但設(shè)備運行的內(nèi)存適中。您正在運行的進程可能希望釋放一些不需要的資源以供其他地方使用
*/
static final int TRIM_MEMORY_RUNNING_MODERATE = 5;
由此可知涡尘，80 是一個很嚴重的級別忍弛，如果沒有很快找到更多內(nèi)存，進程將被殺死考抄，而且從日志中可以看到细疚，這個進程是 launcher 進程，連桌面都快要被殺死川梅，那普通應(yīng)用肯定也不會好到哪去疯兼。
一般來說，設(shè)備內(nèi)存緊張贫途，會導(dǎo)致多個應(yīng)用發(fā)生 ANR吧彪。
