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

1、概述

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

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

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

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

2、ANR產生機制

網上通俗的一段面試答題app

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

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

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 Timeoutoop

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
相關文章
相關標籤/搜索