一一膨、概述
解決ANR一直是Android 開發(fā)者需要掌握的重要技巧,一般從三個方面著手洒沦。
開發(fā)階段:通過工具檢查各個方法的耗時豹绪,卡頓情況,發(fā)現(xiàn)一處修改一處申眼。
線上階段:這個階段主要依靠監(jiān)控工具發(fā)現(xiàn)ANR并上報瞒津,比如matrix。
分析階段:如果線上用戶發(fā)生ANR括尸,并且你獲取了一份日志巷蚪,這就涉及了本文要分享的內(nèi)容——ANR日志分析技巧。
二濒翻、ANR產(chǎn)生機(jī)制
網(wǎng)上通俗的一段面試答題
ANR——應(yīng)用無響應(yīng)屁柏,Activity是5秒,BroadCastReceiver是10秒有送,Service是20秒淌喻。
這句話說的很籠統(tǒng),要想深入分析定位ANR雀摘,需要知道更多知識點(diǎn)裸删,一般來說,ANR按產(chǎn)生機(jī)制阵赠,分為4類:
2.1 輸入事件超時(5s)
InputEvent Timeout
a.InputDispatcher發(fā)送key事件給 對應(yīng)的進(jìn)程的 Focused Window 涯塔,對應(yīng)的window不存在肌稻、處于暫停態(tài)、或通道(input channel)占滿匕荸、通道未注冊爹谭、通道異常、或5s內(nèi)沒有處理完一個事件榛搔,就會發(fā)生ANR
b.InputDispatcher發(fā)送MotionEvent事件有個例外之處:當(dāng)對應(yīng)Touched Window的 input waitQueue中有超過0.5s的事件旦棉,inputDispatcher會暫停該事件,并等待5s药薯,如果仍舊沒有收到window的‘finish’事件绑洛,則觸發(fā)ANR
c.下一個事件到達(dá),發(fā)現(xiàn)有一個超時事件才會觸發(fā)ANR
復(fù)制代碼
2.2 廣播類型超時(前臺15s童本,后臺60s)
BroadcastReceiver Timeout
a.靜態(tài)注冊的廣播和有序廣播會ANR真屯,動態(tài)注冊的非有序廣播并不會ANR
b.廣播發(fā)送時,會判斷該進(jìn)程是否存在穷娱,不存在則創(chuàng)建绑蔫,創(chuàng)建進(jìn)程的耗時也算在超時時間里
c.只有當(dāng)進(jìn)程存在前臺顯示的Activity才會彈出ANR對話框,否則會直接殺掉當(dāng)前進(jìn)程
d.當(dāng)onReceive執(zhí)行超過閾值(前臺15s泵额,后臺60s)配深,將產(chǎn)生ANR
e.如何發(fā)送前臺廣播:Intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)
復(fù)制代碼
2.3 服務(wù)超時(前臺20s,后臺200s)
Service Timeout
a.Service的以下方法都會觸發(fā)ANR:onCreate(),onStartCommand(), onStart(), onBind(), onRebind(), onTaskRemoved(), onUnbind(),
onDestroy().
b.前臺Service超時時間為20s嫁盲,后臺Service超時時間為200s
c.如何區(qū)分前臺篓叶、后臺執(zhí)行————當(dāng)前APP處于用戶態(tài),此時執(zhí)行的Service則為前臺執(zhí)行羞秤。
d.用戶態(tài):有前臺activity缸托、有前臺廣播在執(zhí)行、有foreground service執(zhí)行
復(fù)制代碼
2.4 ContentProvider 類型
a.ContentProvider創(chuàng)建發(fā)布超時并不會ANR
b.使用ContentProviderclient來訪問ContentProverder可以自主選擇觸發(fā)ANR瘾蛋,超時時間自己定
client.setDetectNotResponding(PROVIDER_ANR_TIMEOUT);
復(fù)制代碼
ps:Activity生命周期超時會不會ANR俐镐?——經(jīng)測試并不會。
override fun onCreate(savedInstanceState: Bundle?) {
Thread.sleep(60000)
super.onCreate(savedInstanceState)
setContentView(R.layout.activity_main)
}
復(fù)制代碼
三哺哼、導(dǎo)致ANR的原因
很多開發(fā)者認(rèn)為佩抹,那就是耗時操作導(dǎo)致ANR,全部是app應(yīng)用層的問題取董。實際上棍苹,線上環(huán)境大部分ANR由系統(tǒng)原因?qū)е隆?/p>
1.首先從main.log找到進(jìn)程出現(xiàn)anr對應(yīng)的大體時間,如在log中查詢"anr in"字段
2.根據(jù)出現(xiàn)anr的進(jìn)程名到anr文件夾中找出trance.txt文件,根據(jù)文件的信息首先判斷anr的類型甲葬,是app自身還是系統(tǒng)問題廊勃,如果是app應(yīng)用問題懈贺,則根據(jù)對用的調(diào)用解決問題
3.如不是app應(yīng)用問題经窖,則從main.log中判斷anr的類型坡垫,如是keydispatch time out,則應(yīng)該根據(jù)anr準(zhǔn)確的時間點(diǎn)上推5s鐘画侣,看看此時對用進(jìn)程正在進(jìn)程何操作(具體anr的準(zhǔn)確時間可以在event.log中搜索anr)
4.trace中無明顯異常冰悠,可以從下面的情況考慮
a.是否由于io,數(shù)據(jù)庫處理導(dǎo)致cpu使用率過高從而導(dǎo)致其他應(yīng)用進(jìn)程無法搶占cpu時間片
b.是否是低內(nèi)存導(dǎo)致anr(如低內(nèi)存配乱,可以從system.log中查看進(jìn)程被kill, 輸入某某進(jìn)程died)
c.是否由于輸入法交互處理不當(dāng)導(dǎo)致不能返回出現(xiàn)anr
d.是否由于進(jìn)程鎖等待溉卓,死鎖情況出現(xiàn)anr
3.1 應(yīng)用層導(dǎo)致ANR(耗時操作)
a. 函數(shù)阻塞:如死循環(huán)、主線程IO搬泥、處理大數(shù)據(jù)
b. 鎖出錯:主線程等待子線程的鎖
c. 內(nèi)存緊張:系統(tǒng)分配給一個應(yīng)用的內(nèi)存是有上限的桑寨,長期處于內(nèi)存緊張,會導(dǎo)致頻繁內(nèi)存交換忿檩,進(jìn)而導(dǎo)致應(yīng)用的一些操作超時
復(fù)制代碼
3.2 系統(tǒng)導(dǎo)致ANR
a. CPU被搶占:一般來說尉尾,前臺在玩游戲,可能會導(dǎo)致你的后臺廣播被搶占CPU
b. 系統(tǒng)服務(wù)無法及時響應(yīng):比如獲取系統(tǒng)聯(lián)系人等燥透,系統(tǒng)的服務(wù)都是Binder機(jī)制沙咏,服務(wù)能力也是有限的,有可能系統(tǒng)服務(wù)長時間不響應(yīng)導(dǎo)致ANR
c. 其他應(yīng)用占用的大量內(nèi)存
復(fù)制代碼
四班套、分析日志
發(fā)生ANR的時候肢藐,系統(tǒng)會產(chǎn)生一份anr日志文件(手機(jī)的/data/anr 目錄下,文件名稱可能各廠商不一樣吱韭,業(yè)內(nèi)大多稱呼為trace文件)吆豹,內(nèi)含如下幾項重要信息。
4.1 CPU 負(fù)載
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
復(fù)制代碼
如上所示:
第一行:1理盆、5瞻讽、15 分鐘內(nèi)正在使用和等待使用CPU 的活動進(jìn)程的平均數(shù)
第二行:表明負(fù)載信息抓取在ANR發(fā)生之后的0~1987ms阿逃。同時也指明了ANR的時間點(diǎn):2020-03-10 08:31:55.169
中間部分:各個進(jìn)程占用的CPU的詳細(xì)情況
最后一行:各個進(jìn)程合計占用的CPU信息蛋逾。
名詞解釋:
a. user:用戶態(tài),kernel:內(nèi)核態(tài)
b. faults:內(nèi)存缺頁,minor——輕微的凛捏,major——重度坎拐,需要從磁盤拿數(shù)據(jù)
c. iowait:IO使用(等待)占比
d. irq:硬中斷,softirq:軟中斷
復(fù)制代碼
注意:
iowait占比很高哼勇,意味著有很大可能都伪,是io耗時導(dǎo)致ANR陨晶,具體進(jìn)一步查看有沒有進(jìn)程faults major比較多铃芦。
單進(jìn)程CPU的負(fù)載并不是以100%為上限鳍鸵,而是有幾個核眠副,就有百分之幾百台丛,如4核上限為400%宁否。
4.2 內(nèi)存信息
Total number of allocations 476778 進(jìn)程創(chuàng)建到現(xiàn)在一共創(chuàng)建了多少對象
Total bytes allocated 52MB 進(jìn)程創(chuàng)建到現(xiàn)在一共申請了多少內(nèi)存
Total bytes freed 52MB 進(jìn)程創(chuàng)建到現(xiàn)在一共釋放了多少內(nèi)存
Free memory 777KB 不擴(kuò)展堆的情況下可用的內(nèi)存
Free memory until GC 777KB GC前的可用內(nèi)存
Free memory until OOME 383MB OOM之前的可用內(nèi)存
Total memory 當(dāng)前總內(nèi)存(已用+可用)
Max memory 384MB 進(jìn)程最多能申請的內(nèi)存
復(fù)制代碼
從含義可以得出結(jié)論:**Free memory until OOME **的值很小的時候屉凯,已經(jīng)處于內(nèi)存緊張狀態(tài)立帖。應(yīng)用可能是占用了過多內(nèi)存。
另外悠砚,除了trace文件中有內(nèi)存信息晓勇,普通的eventlog日志中,也有內(nèi)存信息(不一定打印)
04-02 22:00:08.195 1531 1544 I am_meminfo: [350937088,41086976,492830720,427937792,291887104]
復(fù)制代碼
以上四個值分別指的是:
Cached
Free,
Zram,
Kernel,Native
Cached+Free的內(nèi)存代表著當(dāng)前整個手機(jī)的可用內(nèi)存绑咱,如果值很小绰筛,意味著處于內(nèi)存緊張狀態(tài)。一般低內(nèi)存的判定閾值為:4G 內(nèi)存手機(jī)以下閥值:350MB描融,以上閥值則為:450MB
ps:如果ANR時間點(diǎn)前后铝噩,日志里有打印onTrimMemory,也可以作為內(nèi)存緊張的一個參考判斷
4.3 堆棧消息
堆棧信息是最重要的一個信息窿克,展示了ANR發(fā)生的進(jìn)程當(dāng)前所有線程的狀態(tài)骏庸。
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)
復(fù)制代碼
如上日志所示,本文截圖了兩個線程信息年叮,一個是主線程main具被,它的狀態(tài)是native。
另一個是OkHttp ConnectionPool只损,它的狀態(tài)是TimeWaiting一姿。眾所周知,教科書上說線程狀態(tài)有5種:新建跃惫、就緒叮叹、執(zhí)行、阻塞爆存、死亡衬横。而Java中的線程狀態(tài)有6種,6種狀態(tài)都定義在:java.lang.Thread.State中
狀態(tài) | 解釋 |
---|---|
NEW | 線程剛被創(chuàng)建终蒂,但是并未啟動蜂林。還沒調(diào)用start方法。 |
RUNNABLE | 線程可以在java虛擬機(jī)中運(yùn)行的狀態(tài)拇泣,可能正在運(yùn)行自己代碼噪叙,也可能沒有,這取決于操作系統(tǒng)處理器霉翔。 |
BLOCKED | 當(dāng)一個線程試圖獲取一個對象鎖睁蕾,而該對象鎖被其他的線程持有,則該線程進(jìn)入Blocked狀態(tài)债朵;當(dāng)該線程持有鎖時子眶,該線程將變成Runnable狀 |
WATING | 一個線程在等待另一個線程執(zhí)行一個(喚醒)動作時,該線程進(jìn)入Waiting狀態(tài)序芦。進(jìn)入這個狀態(tài)后是不能自動喚醒的臭杰,必須等待另一個線程調(diào)用notify或者notifyAll方法才能夠 |
TIMED_WAITING | 同waiting狀態(tài),有超時參數(shù)谚中,超時后自動喚醒渴杆,比如Thread.Sleep(1000) |
TERMINATED | 線程已經(jīng)執(zhí)行完畢寥枝。 |
問題來了,上述main線程的native是什么狀態(tài)磁奖,哪來的囊拜?其實trace文件中的狀態(tài)是是CPP代碼中定義的狀態(tài),下面是一張對應(yīng)關(guān)系表比搭。
由此可知冠跷,main函數(shù)的native狀態(tài)是正在執(zhí)行JNI函數(shù)。堆棧信息是我們分析ANR的第一個重要的信息身诺,一般來說:
main線程處于 BLOCK蜜托、WAITING、TIMEWAITING狀態(tài)戚长,那基本上是函數(shù)阻塞導(dǎo)致ANR盗冷;
如果main線程無異常怠苔,則應(yīng)該排查CPU負(fù)載和內(nèi)存環(huán)境同廉。
五、典型案例分析
5.1 主線程無卡頓柑司,處于正常狀態(tài)堆棧
"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)
復(fù)制代碼
上述主線程堆棧就是一個很正常的空閑堆棧迫肖,表明主線程正在等待新的消息。
如果ANR日志里主線程是這樣一個狀態(tài)攒驰,那可能有兩個原因:
該ANR是CPU搶占或內(nèi)存緊張等其他因素引起
這份ANR日志抓取的時候蟆湖,主線程已經(jīng)恢復(fù)正常 搜索關(guān)鍵子“failed for thread 3353: Thread has not responded to signal in time”部分關(guān)鍵字試試
遇到這種空閑堆棧,可以按照第3節(jié)的方法去分析CPU玻粪、內(nèi)存的情況隅津。其次可以關(guān)注抓取日志的時間和ANR發(fā)生的時間是否相隔過久,時間過久這個堆棧就沒有分析意義了劲室。
5.2 主線程執(zhí)行耗時操作
"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)——關(guān)鍵行B兹浴!很洋!
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)
復(fù)制代碼
上述日志表明充蓝,主線程正處于執(zhí)行狀態(tài),看堆棧信息可知不是處于空閑狀態(tài)喉磁,發(fā)生ANR是因為一處click監(jiān)聽函數(shù)里執(zhí)行了耗時操作谓苟。
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 ——————關(guān)鍵行!P涝焙!
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)————————————————————關(guān)鍵行!T邢尽纱皆!
at java.lang.Thread.run(Thread.java:919)
復(fù)制代碼
這是一個典型的主線程被鎖阻塞的例子湾趾;
waiting to lock <0x01aed1da> (a java.lang.Object) held by thread 3
復(fù)制代碼
其中等待的鎖是<0x01aed1da>,這個鎖的持有者是線程 3派草。進(jìn)一步搜索 “tid=3” 找到線程3搀缠, 發(fā)現(xiàn)它正在TimeWating。
那么ANR的原因找到了:線程3持有了一把鎖近迁,并且自身長時間不釋放艺普,主線程等待這把鎖發(fā)生超時。在線上環(huán)境中鉴竭,常見因鎖而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 ————關(guān)鍵行!2妗瑰步!
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行.....
復(fù)制代碼
如上日志,第二行是釘釘?shù)倪M(jìn)程璧眠,占據(jù)CPU高達(dá)543%缩焦,搶占了大部分CPU資源,因而導(dǎo)致發(fā)生ANR责静。
5.5 內(nèi)存緊張導(dǎo)致ANR
如果有一份日志袁滥,CPU和堆棧都很正常(不貼出來了),仍舊發(fā)生ANR灾螃,考慮是內(nèi)存緊張题翻。
從CPU第一行信息可以發(fā)現(xiàn),ANR的時間點(diǎn)是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)
接著去系統(tǒng)日志里搜索am_meminfo腰鬼, 這個沒有搜索到嵌赠。再次搜索onTrimMemory,果然發(fā)現(xiàn)了很多條記錄熄赡;
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
復(fù)制代碼
可以看出姜挺,在發(fā)生ANR的時間點(diǎn)前后,內(nèi)存都處于緊張狀態(tài)本谜,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;
復(fù)制代碼
可知80這個等級是很嚴(yán)重的乌助,應(yīng)用馬上就要被殺死溜在,被殺死的這個應(yīng)用從名字可以看出來是桌面,連桌面都快要被殺死他托,那普通應(yīng)用能好到哪里去呢掖肋?
一般來說,發(fā)生內(nèi)存緊張赏参,會導(dǎo)致多個應(yīng)用發(fā)生ANR志笼,所以在日志中如果發(fā)現(xiàn)有多個應(yīng)用一起ANR了沿盅,可以初步判定,此ANR與你的應(yīng)用無關(guān)纫溃。
5.6 系統(tǒng)服務(wù)超時導(dǎo)致ANR
系統(tǒng)服務(wù)超時一般會包含BinderProxy.transactNative關(guān)鍵字腰涧,請看如下日志:
"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) ————————————————關(guān)鍵行!N珊啤窖铡!
at android.os.BinderProxy.transact(Binder.java:804)
at android.net.IConnectivityManager$Stub$Proxy.getActiveNetworkInfo(IConnectivityManager.java:1204)—關(guān)鍵行!
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)
復(fù)制代碼
從堆椃凰可以看出獲取網(wǎng)絡(luò)信息發(fā)生了ANR:getActiveNetworkInfo费彼。
前文有講過:系統(tǒng)的服務(wù)都是Binder機(jī)制(16個線程),服務(wù)能力也是有限的口芍,有可能系統(tǒng)服務(wù)長時間不響應(yīng)導(dǎo)致ANR箍铲。如果其他應(yīng)用占用了所有Binder線程,那么當(dāng)前應(yīng)用只能等待鬓椭。
可進(jìn)一步搜索:blockUntilThreadAvailable關(guān)鍵字:
at android.os.Binder.blockUntilThreadAvailable(Native method)
復(fù)制代碼
如果有發(fā)現(xiàn)某個線程的堆棧颠猴,包含此字樣,可進(jìn)一步看其堆棧膘融,確定是調(diào)用了什么系統(tǒng)服務(wù)芙粱。此類ANR也是屬于系統(tǒng)環(huán)境的問題祭玉,如果某類型機(jī)器上頻繁發(fā)生此問題氧映,應(yīng)用層可以考慮規(guī)避策略。
六脱货、結(jié)語
本文總結(jié)的技巧來自筆者工作中的大量ANR日志分析經(jīng)驗岛都,如有錯漏請留言指出,交流促使進(jìn)步振峻!