解決ANR一直是Android 開發者須要掌握的重要技巧,通常從三個方面着手。java
開發階段:經過工具檢查各個方法的耗時,卡頓狀況,發現一處修改一處。android
線上階段:這個階段主要依靠監控工具發現ANR並上報,好比matrix。面試
分析階段:若是線上用戶發生ANR,而且你獲取了一份日誌,這就涉及了本文要分享的內容——ANR日誌分析技巧。網絡
網上通俗的一段面試答題app
ANR——應用無響應,Activity是5秒,BroadCastReceiver是10秒,Service是20秒。
這句話說的很籠統,要想深刻分析定位ANR,須要知道更多知識點,通常來講,ANR按產生機制,分爲4類:ide
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
BroadcastReceiver Timeout工具
a.靜態註冊的廣播和有序廣播會ANR,動態註冊的非有序廣播並不會ANR b.廣播發送時,會判斷該進程是否存在,不存在則建立,建立進程的耗時也算在超時時間裏 c.只有當進程存在前臺顯示的Activity纔會彈出ANR對話框,不然會直接殺掉當前進程 d.當onReceive執行超過閾值(前臺15s,後臺60s),將產生ANR e.如何發送前臺廣播:Intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)
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執行
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,所有是app應用層的問題。實際上,線上環境大部分ANR由系統緣由致使。
a. 函數阻塞:如死循環、主線程IO、處理大數據 b. 鎖出錯:主線程等待子線程的鎖 c. 內存緊張:系統分配給一個應用的內存是有上限的,長期處於內存緊張,會致使頻繁內存交換,進而致使應用的一些操做超時
a. CPU被搶佔:通常來講,前臺在玩遊戲,可能會致使你的後臺廣播被搶佔CPU b. 系統服務沒法及時響應:好比獲取系統聯繫人等,系統的服務都是Binder機制,服務能力也是有限的,有可能系統服務長時間不響應致使ANR c. 其餘應用佔用的大量內存
發生ANR的時候,系統會產生一份anr日誌文件(手機的/data/anr 目錄下,文件名稱可能各廠商不同,業內大多稱呼爲trace文件),內含以下幾項重要信息。
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
如上所示:
名詞解釋:
a. user:用戶態,kernel:內核態 b. faults:內存缺頁,minor——輕微的,major——重度,須要從磁盤拿數據 c. iowait:IO使用(等待)佔比 d. irq:硬中斷,softirq:軟中斷
注意:
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的內存表明着當前整個手機的可用內存,若是值很小,意味着處於內存緊張狀態。通常低內存的斷定閾值爲:4G 內存手機如下閥值:350MB,以上閥值則爲:450MB
ps:若是ANR時間點先後,日誌裏有打印onTrimMemory,也能夠做爲內存緊張的一個參考判斷
堆棧信息是最重要的一個信息,展現了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負載和內存環境。
"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發生的時間是否相隔太久,時間太久這個堆棧就沒有分析意義了。
"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監聽函數裏執行了耗時操做。
"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寫入。
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。
若是有一份日誌,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與你的應用無關。
系統服務超時通常會包含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