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

一、概述

解決ANR一直是Android 開發者需要掌握的重要技巧,一般從三個方面著手。

開發階段:通過工具檢查各個方法的耗時,卡頓情況,發現一處修改一處。

線上階段:這個階段主要依靠監控工具發現ANR並上報,比如matrix。

分析階段:如果線上用戶發生ANR,並且你獲取了一份日誌,這就涉及了本文要分享的內容——ANR日誌分析技巧。

二、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)
   }

三、導致ANR的原因

很多開發者認為,那就是耗時操作導致ANR,全部是app應用層的問題。實際上,線上環境大部分ANR由系統原因導致。

3.1 應用層導致ANR(耗時操作)

a. 函數阻塞:如死循環、主執行緒IO、處理大數據
​
b. 鎖出錯:主執行緒等待子執行緒的鎖
​
c. 記憶體緊張:系統分配給一個應用的記憶體是有上限的,長期處於記憶體緊張,會導致頻繁記憶體交換,進而導致應用的一些操作超時

3.2 系統導致ANR

a. CPU被搶佔:一般來說,前台在玩遊戲,可能會導致你的後台廣播被搶佔CPU
​
b. 系統服務無法及時響應:比如獲取系統聯繫人等,系統的服務都是Binder機制,服務能力也是有限的,有可能系統服務長時間不響應導致ANR
​
c. 其他應用佔用的大量記憶體

四、分析日誌

發生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

如上所示:

  • 第一行: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%。

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.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/[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。

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也是屬於系統環境的問題,如果某類型機器上頻繁發生此問題,應用層可以考慮規避策略。

六、結語

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

作者:vivo互聯網客戶端團隊—Wang Qinwei