文章目錄

一、導緻ANR的原因
- 1.1 應用層導緻ANR（耗時操作）
- 1.2 系統導緻ANR
二、分析日志
- 2.1 CPU 負載
- 2.2 記憶體資訊
- 2.3 堆棧消息
三、典型案例分析
- 3.1 主線程無卡頓，處于正常狀态堆棧
- 3.2 主線程執行耗時操作
- 3.3 主線程被鎖阻塞
- 3.4 CPU被搶占
- 3.5 記憶體緊張導緻ANR
- 3.6 系統服務逾時導緻ANR

https://zhuanlan.zhihu.com/p/378902923

一、導緻ANR的原因

1.1 應用層導緻ANR（耗時操作）

a. 函數阻塞：如死循環、主線程IO、處理大資料

b. 鎖出錯：主線程等待子線程的鎖

c. 記憶體緊張：系統配置設定給一個應用的記憶體是有上限的，長期處于記憶體緊張，會導緻頻繁記憶體交換，進而導緻應用的一些操作逾時

1.2 系統導緻ANR

a. CPU被搶占：一般來說，前台在玩遊戲，可能會導緻你的背景廣播被搶占CPU

b. 系統服務無法及時響應：比如擷取系統聯系人等，系統的服務都是Binder機制，服務能力也是有限的，有可能系統服務長時間不響應導緻ANR

c. 其他應用占用的大量記憶體

二、分析日志

發生ANR的時候，系統會産生一份anr日志檔案（手機的/data/anr 目錄下，檔案名稱可能各廠商不一樣，業内大多稱呼為trace檔案），内含如下幾項重要資訊。

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

2.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日志中，也有記憶體資訊（不一定列印）

以上四個值分别指的是：

Cached
Free,
Zram,
Kernel,Native

Cached+Free的記憶體代表着目前整個手機的可用記憶體，如果值很小，意味着處于記憶體緊張狀态。一般低記憶體的判定門檻值為：4G 記憶體手機以下閥值：350MB，以上閥值則為：450MB

ps:如果ANR時間點前後，日志裡有列印onTrimMemory，也可以作為記憶體緊張的一個參考判斷

2.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中

ANR日志分析彙總一、導緻ANR的原因二、分析日志三、典型案例分析

**問題來了，上述main線程的native是什麼狀态，哪來的？**其實trace檔案中的狀态是是CPP代碼中定義的狀态，下面是一張對應關系表。

ANR日志分析彙總一、導緻ANR的原因二、分析日志三、典型案例分析

由此可知，main函數的native狀态是正在執行JNI函數。堆棧資訊是我們分析ANR的第一個重要的資訊，一般來說：

main線程處于 BLOCK、WAITING、TIMEWAITING狀态，那基本上是函數阻塞導緻ANR；

如果main線程無異常，則應該排查CPU負載和記憶體環境。

三、典型案例分析

3.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發生的時間是否相隔過久，時間過久這個堆棧就沒有分析意義了。

3.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監聽函數裡執行了耗時操作。

3.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)

這是一個典型的主線程被鎖阻塞的例子；

其中等待的鎖是<0x01aed1da>，這個鎖的持有者是線程 3。進一步搜尋 “tid=3” 找到線程3，發現它正在TimeWating。

那麼ANR的原因找到了：線程3持有了一把鎖，并且自身長時間不釋放，主線程等待這把鎖發生逾時。線上上環境中，常見因鎖而ANR的場景是SharePreference寫入。

3.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/[email protected]: 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。

3.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與你的應用無關。

3.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關鍵字：

如果有發現某個線程的堆棧，包含此字樣，可進一步看其堆棧，确定是調用了什麼系統服務。此類ANR也是屬于系統環境的問題，如果某類型機器上頻繁發生此問題，應用層可以考慮規避政策。

ANR日志分析彙總一、導緻ANR的原因二、分析日志三、典型案例分析

文章目錄

一、導緻ANR的原因

1.1 應用層導緻ANR（耗時操作）

1.2 系統導緻ANR

二、分析日志

2.1 CPU 負載

2.2 記憶體資訊

2.3 堆棧消息

三、典型案例分析

3.1 主線程無卡頓，處于正常狀态堆棧

3.2 主線程執行耗時操作

3.3 主線程被鎖阻塞

3.4 CPU被搶占

3.5 記憶體緊張導緻ANR

3.6 系統服務逾時導緻ANR

繼續閱讀

Android使用RecyclerViewHeader遇到的那些坑

RecyclerView無法按鍵控制移動的解決辦法--給view添加焦點

Android中圖檔的三級緩存政策一、簡介二、網絡緩存三、本地緩存四、記憶體緩存

混淆第三方jar包(Gson, greenDao,sharesdk,UIL,高德地圖, unity,pinyin4j,async http,JPush,EventBus等)

如何讓自已在GitHub的開源庫給第三方App依賴調用

addView導緻子布局“match_parent”屬性失效詳解

連結url自動拼接appinstall參數導緻其在ios QQ分享時亂碼

關于android版本相容的一些問題

TableLayout不能占滿螢幕問題解決

Mac使用Bundletool工具遇到的問題

Android Studio添加assets檔案夾

Android 8.0出現的java.lang.IndexOutOfBoundsException: setSpan (-1 … -1) starts before 0

Android無法連接配接裝置調試

SimpleDateFormat:日期格式化産生奇怪的日期資料

Android MVPPlugin插件例子說明