乾貨：ANR日誌分析全面解析

1、概述

解決ANR一直是Android 開發者須要掌握的重要技巧，通常從三個方面着手。

開發階段：經過工具檢查各個方法的耗時，卡頓狀況，發現一處修改一處。

線上階段：這個階段主要依靠監控工具發現ANR並上報，好比matrix。

分析階段：若是線上用戶發生ANR，而且你獲取了一份日誌，這就涉及了本文要分享的內容——ANR日誌分析技巧。

2、ANR產生機制

網上通俗的一段面試答題

ANR——應用無響應，Activity是5秒，BroadCastReceiver是10秒，Service是20秒。

這句話說的很籠統，要想深刻分析定位ANR，須要知道更多知識點，通常來講，ANR按產生機制，分爲4類：

2.1 輸入事件超時(5s)

InputEvent Timeout

a.InputDispatcher發送key事件給 對應的進程的 Focused Window ，對應的window不存在、處於暫停態、或通道(input channel)佔滿、通道未註冊、通道異常、或5s內沒有處理完一個事件，就會發生ANR
​
b.InputDispatcher發送MotionEvent事件有個例外之處：當對應Touched Window的 input waitQueue中有超過0.5s的事件，inputDispatcher會暫停該事件，並等待5s，若是仍舊沒有收到window的‘finish’事件，則觸發ANR
​
c.下一個事件到達，發現有一個超時事件纔會觸發ANR

2.2 廣播類型超時（前臺15s，後臺60s）

BroadcastReceiver Timeout

a.靜態註冊的廣播和有序廣播會ANR，動態註冊的非有序廣播並不會ANR
​
b.廣播發送時，會判斷該進程是否存在，不存在則建立，建立進程的耗時也算在超時時間裏
​
c.只有當進程存在前臺顯示的Activity纔會彈出ANR對話框，不然會直接殺掉當前進程
​
d.當onReceive執行超過閾值（前臺15s，後臺60s），將產生ANR
​
e.如何發送前臺廣播：Intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)

2.3 服務超時（前臺20s，後臺200s）

Service Timeout

a.Service的如下方法都會觸發ANR：onCreate(),onStartCommand(), onStart(), onBind(), onRebind(), onTaskRemoved(), onUnbind(),
onDestroy().
​
b.前臺Service超時時間爲20s，後臺Service超時時間爲200s
​
c.如何區分前臺、後臺執行————當前APP處於用戶態，此時執行的Service則爲前臺執行。
​
d.用戶態：有前臺activity、有前臺廣播在執行、有foreground service執行

2.4 ContentProvider 類型

a.ContentProvider建立發佈超時並不會ANR
​
b.使用ContentProviderclient來訪問ContentProverder能夠自主選擇觸發ANR，超時時間本身定
client.setDetectNotResponding(PROVIDER_ANR_TIMEOUT);

ps：Activity生命週期超時會不會ANR？——經測試並不會。

override fun onCreate(savedInstanceState: Bundle?) {
       Thread.sleep(60000)
       super.onCreate(savedInstanceState)
       setContentView(R.layout.activity_main)
   }

3、致使ANR的緣由

不少開發者認爲，那就是耗時操做致使ANR，所有是app應用層的問題。實際上，線上環境大部分ANR由系統緣由致使。

3.1 應用層致使ANR（耗時操做）

a. 函數阻塞：如死循環、主線程IO、處理大數據
​
b. 鎖出錯：主線程等待子線程的鎖
​
c. 內存緊張：系統分配給一個應用的內存是有上限的，長期處於內存緊張，會致使頻繁內存交換，進而致使應用的一些操做超時

3.2 系統致使ANR

a. CPU被搶佔：通常來講，前臺在玩遊戲，可能會致使你的後臺廣播被搶佔CPU
​
b. 系統服務沒法及時響應：好比獲取系統聯繫人等，系統的服務都是Binder機制，服務能力也是有限的，有可能系統服務長時間不響應致使ANR
​
c. 其餘應用佔用的大量內存

4、分析日誌

發生ANR的時候，系統會產生一份anr日誌文件（手機的/data/anr 目錄下，文件名稱可能各廠商不同，業內大多稱呼爲trace文件），內含以下幾項重要信息。

4.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

如上所示：

• 第一行：一、五、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%。

4.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日誌中，也有內存信息（不必定打印）

04-02 22:00:08.195  1531  1544 I am_meminfo: [350937088,41086976,492830720,427937792,291887104]

以上四個值分別指的是：

• Cached
• Free,
• Zram,
• Kernel,Native

Cached+Free的內存表明着當前整個手機的可用內存，若是值很小，意味着處於內存緊張狀態。通常低內存的斷定閾值爲：4G 內存手機如下閥值：350MB，以上閥值則爲：450MB

ps:若是ANR時間點先後，日誌裏有打印onTrimMemory，也能夠做爲內存緊張的一個參考判斷

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

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

由此可知，main函數的native狀態是正在執行JNI函數。堆棧信息是咱們分析ANR的第一個重要的信息，通常來講：

main線程處於 BLOCK、WAITING、TIMEWAITING狀態，那基本上是函數阻塞致使ANR；

若是main線程無異常，則應該排查CPU負載和內存環境。

5、典型案例分析

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

5.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監聽函數裏執行了耗時操做。

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

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

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

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

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

5.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/android.hardware.camera.provider@2.4-service: 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。

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

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

at android.os.Binder.blockUntilThreadAvailable(Native method)

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

6、結語

本文總結的技巧來自筆者工做中的大量ANR日誌分析經驗，若有錯漏請留言指出，交流促使進步！

做者：vivo互聯網客戶端團隊—Wang Qinwei