一、概述
解決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/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也是屬於系統環境的問題,如果某型別機器上頻繁發生此問題,應用層可以考慮規避策略。
六、結語
本文總結的技巧來自筆者工作中的大量ANR日誌分析經驗,如有錯漏請留言指出,交流促使進步!
作者:vivo網際網路客戶端團隊—Wang Qinwei