Android ANR日志分析進(jìn)行曲

定義
ANR(Application Not Responding)?應(yīng)用程序無(wú)響應(yīng)悦屏。如果你應(yīng)用程序在UI線程被阻塞太長(zhǎng)時(shí)間节沦,就會(huì)出現(xiàn)ANR键思,通常出現(xiàn)ANR,系統(tǒng)會(huì)彈出一個(gè)提示提示框甫贯,讓用戶知道吼鳞,該程序正在被阻塞,是否繼續(xù)等待還是關(guān)閉叫搁。

ANR出現(xiàn)的原因
1:主線程頻繁進(jìn)行耗時(shí)的IO操作:如數(shù)據(jù)庫(kù)讀寫(xiě)(UI線程等待其它線程釋放某個(gè)鎖赔桌,導(dǎo)致UI線程無(wú)法處理用戶輸入);
2:多線程操作的死鎖渴逻,主線程被block纬乍;
3:主線程被Binder 對(duì)端block;
4:System Server中WatchDog出現(xiàn)ANR裸卫;
5:service binder的連接達(dá)到上線無(wú)法和SystemServer通信
6:系統(tǒng)資源已耗盡(管道仿贬、CPU、IO)

ANR類型
出現(xiàn)ANR的一般有以下幾種類型:
1:KeyDispatchTimeout(常見(jiàn))
input事件在5S內(nèi)沒(méi)有處理完成發(fā)生了ANR墓贿。
logcat日志關(guān)鍵字:Input event dispatching timed out
2:BroadcastTimeout
前臺(tái)Broadcast:onReceiver在10S內(nèi)沒(méi)有處理完成發(fā)生ANR茧泪。
后臺(tái)Broadcast:onReceiver在60s內(nèi)沒(méi)有處理完成發(fā)生ANR。
logcat日志關(guān)鍵字:Timeout of broadcast BroadcastRecord
3:ServiceTimeout
前臺(tái)Service:onCreate聋袋,onStart队伟,onBind等生命周期在20s內(nèi)沒(méi)有處理完成發(fā)生ANR。
后臺(tái)Service:onCreate幽勒,onStart嗜侮,onBind等生命周期在200s內(nèi)沒(méi)有處理完成發(fā)生ANR
logcat日志關(guān)鍵字:Timeout executing service
4:ContentProviderTimeout
ContentProvider 在10S內(nèi)沒(méi)有處理完成發(fā)生ANR。 logcat日志關(guān)鍵字:timeout publishing content providers

ANR分析過(guò)程
1.查看events_log
在android stuido Terminal面板啥容,輸出events日志信息锈颗,命令如下:
adb logcat -b events

面板信息如下:

圖片2.png

其次Terminal面板找到關(guān)鍵字:am_anr,找到出現(xiàn)ANR的時(shí)間點(diǎn)咪惠、進(jìn)程PID击吱、ANR類型。

圖片3.png

從上面的log我們可以看出: 應(yīng)用com.example.myapplication在09-25 23:04:27.355時(shí)間遥昧,發(fā)生了一次KeyDispatchTimeout類型的ANR覆醇,它的進(jìn)程號(hào)是3724. 把關(guān)鍵的信息整理一下:
ANR時(shí)間:09-25 23:04:27.355
進(jìn)程pid:3879
進(jìn)程名:com.example.myapplication
ANR類型:KeyDispatchTimeout

通過(guò)上面關(guān)鍵信息,我們了解到炭臭,發(fā)生KeyDispatchTimeout的ANR是因?yàn)閕nput事件在5秒內(nèi)沒(méi)有處理完成永脓。那么在這個(gè)時(shí)間09-25 23:04:27.355的前5秒,也就是(23:04:22 ~23:04:23)時(shí)間段左右程序到底做了什么事情鞋仍?我們已經(jīng)知道pid了常摧,再搜索一下pid = 3879的日志.這些日志表示該進(jìn)程所運(yùn)行的軌跡,關(guān)鍵的日志如下:

圖片4.png

仔細(xì)看一下就會(huì)發(fā)現(xiàn):

圖片5.png

23:04:19時(shí)間點(diǎn)做了界面跳轉(zhuǎn)凿试,之后將近8秒后排宰,就出現(xiàn)ANR了,那么那婉,我們知道怎么開(kāi)始的板甘,但是具體原因還是沒(méi)有找到。
那么接下來(lái)详炬,是不是當(dāng)時(shí)CPU很緊張盐类、各路APP再搶占資源? 我們?cè)倏纯碈PU的信息,呛谜。搜索關(guān)鍵字關(guān)鍵字:ANR IN

2021-09-26 07:04:28.043 1597-1611/system_process E/ActivityManager: ANR in com.example.myapplication (com.example.myapplication/.activities.ANRTestActivity)
    PID: 3879
    Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length:  Wait queue head age: 5706.6ms.)
    Load: 0.23 / 0.09 / 0.07
    CPU usage from 507882ms to 0ms ago (2021-09-25 14:56:16.323 to 2021-09-25 23:04:27.351):
      0.9% 1597/system_server: 0.1% user + 0.7% kernel / faults: 26762 minor 1 major
      0.2% 1800/com.android.settings: 0% user + 0.2% kernel / faults: 8985 minor 8 major
      0.6% 1303/surfaceflinger: 0% user + 0.6% kernel / faults: 18 minor
      0.1% 2094/com.google.android.apps.nexuslauncher: 0% user + 0.1% kernel / faults: 1130 minor 2 major
      0% 1692/com.android.systemui: 0% user + 0% kernel / faults: 381 minor
      0% 1320/audioserver: 0% user + 0% kernel / faults: 38 minor
      0% 2214/com.google.android.googlequicksearchbox:search: 0% user + 0% kernel / faults: 4059 minor
      0% 2000/com.google.android.gms.persistent: 0% user + 0% kernel / faults: 947 minor
      0% 1779/com.android.phone: 0% user + 0% kernel / faults: 110 minor
      0% 2274/com.google.android.gms: 0% user + 0% kernel / faults: 542 minor 20 major
      0% 1307/adbd: 0% user + 0% kernel / faults: 2411 minor
      0% 1252/logd: 0% user + 0% kernel / faults: 40 minor
      0% 1329/netd: 0% user + 0% kernel / faults: 153 minor
      0% 4/kworker/0:0: 0% user + 0% kernel
      0% 2108/com.android.printspooler: 0% user + 0% kernel / faults: 878 minor
      0% 2141/com.google.process.gapps: 0% user + 0% kernel / faults: 448 minor
      0% 2873/com.google.android.gms.unstable: 0% user + 0% kernel / faults: 156 minor
      0% 1250/jbd2/vdc-8: 0% user + 0% kernel
      0% 3/ksoftirqd/0: 0% user + 0% kernel
      0% 8/rcu_preempt: 0% user + 0% kernel
      0% 1241/kworker/0:1H: 0% user + 0% kernel
      0% 1302/servicemanager: 0% user + 0% kernel
      0% 1319/zygote: 0% user + 0% kernel / faults: 560 minor
      0% 1330/rild: 0% user + 0% kernel
      0% 6/kworker/u8:0: 0% user + 0% kernel
      0% 679/kworker/1:1: 0% user + 0% kernel
      0% 680/kworker/2:1: 0% user + 0% kernel
      0% 681/kworker/3:1: 0% user + 0% kernel
      0% 1299/healthd: 0% user + 0% kernel
      0% 1301/lmkd: 0% user + 0% kernel
      0% 1331/fingerprintd: 0% user + 0% kernel
     +0% 3879/com.example.myapplication: 0% user + 0% kernel
     +0% 3926/com.android.calendar: 0% user + 0% kernel
     +0% 3939/com.android.providers.calendar: 0% user + 0% kernel
     +0% 3960/com.android.deskclock: 0% user + 0% kernel
     +0% 4019/logcat: 0% user + 0% kernel
    0.3% TOTAL: 0% user + 0.3% kernel + 0% iowait + 0% softirq
    CPU usage from 183ms to 689ms later (2021-09-25 23:04:27.534 to 2021-09-25 23:04:28.040):
0% TOTAL: 0% user + 0% kernel
圖片6.png

從上面可以看出在跳,各路進(jìn)程CPU占用基本低于1%,顯然不是CPU負(fù)載的原因了隐岛。那么到底是什么原因呢猫妙? 這時(shí)就要看我們的終極大殺器——traces.txt。

2.traces.txt日志分析
我們需要把traces.txt導(dǎo)出來(lái)聚凹,操作命令如下圖:

圖片8.png

通過(guò)traces文件,我們可以拿到線程名割坠、堆棧信息、線程當(dāng)前狀態(tài)妒牙、binder call等信息彼哼。通過(guò)adb命令拿到該文件:adb pull /data/anr/traces.txt

圖片9.png

接下來(lái),我們需要把traces.txt導(dǎo)入AS湘今,如下:

圖片10.png

traces.txt里面的一些字段敢朱,看看它到底能給我們提供什么信息.
main:main標(biāo)識(shí)是主線程,如果是線程摩瞎,那么命名成“Thread-X”的格式,x表示線程id,逐步遞增拴签。
prio:線程優(yōu)先級(jí),默認(rèn)是5
tid:tid不是線程的id,是線程唯一標(biāo)識(shí)ID
group:是線程組名稱
sCount:該線程被掛起的次數(shù)
dsCount:是線程被調(diào)試器掛起的次數(shù)
obj:對(duì)象地址
self:該線程N(yùn)ative的地址
sysTid:是線程號(hào)(主線程的線程號(hào)和進(jìn)程號(hào)相同)
nice:是線程的調(diào)度優(yōu)先級(jí)
sched:分別標(biāo)志了線程的調(diào)度策略和優(yōu)先級(jí)
cgrp:調(diào)度歸屬組
handle:線程處理函數(shù)的地址旗们。
state:是調(diào)度狀態(tài)
schedstat:從/proc/[pid]/task/[tid]/schedstat讀出篓吁,三個(gè)值分別表示線程在cpu上執(zhí)行的時(shí)間、線程的等待時(shí)間和線程執(zhí)行的時(shí)間片長(zhǎng)度蚪拦,不支持這項(xiàng)信息的三個(gè)值都是0杖剪;
utm:是線程用戶態(tài)下使用的時(shí)間值(單位是jiffies)
stm:是內(nèi)核態(tài)下的調(diào)度時(shí)間值
core:是最后執(zhí)行這個(gè)線程的cpu核的序號(hào)。

Java的堆棧信息是我們最關(guān)心的驰贷,它能夠定位到具體位置盛嘿。從上面的traces,我們可以判斷com.example.myapplication.activities.ANRTestActivity$1.onClick(ANRTestActivity.java:25)點(diǎn)擊之后導(dǎo)致了com.example.myapplication發(fā)生了ANR。在第25行代碼括袒,如下:


圖片11.png

從上面源碼可以看出次兆,點(diǎn)擊事件里面的方法休眠了15秒,導(dǎo)致Input不能及時(shí)處理引發(fā)ANR锹锰。

總結(jié)一下這分析流程:首先我們搜索am_anr芥炭,找到出現(xiàn)ANR的時(shí)間點(diǎn)漓库、進(jìn)程PID、ANR類型园蝠、然后再找搜索PID渺蒿,找前5秒左右的日志。過(guò)濾ANR IN 查看CPU信息彪薛,接著查看traces.txt茂装,找到j(luò)ava的堆棧信息定位代碼位置,最后查看源碼善延,分析與解決問(wèn)題少态。這個(gè)過(guò)程基本能找到發(fā)生ANR的來(lái)龍去脈。

小伙伴如果有興趣的話易遣,歡迎來(lái)閱讀Android ListView性能優(yōu)化案例這篇文章彼妻,搜索并關(guān)注公眾號(hào)“Android技術(shù)迷”關(guān)注后即可閱讀此文章,感謝關(guān)注豆茫。

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
  • 序言:七十年代末澳骤,一起剝皮案震驚了整個(gè)濱河市,隨后出現(xiàn)的幾起案子澜薄,更是在濱河造成了極大的恐慌为肮,老刑警劉巖,帶你破解...
    沈念sama閱讀 218,755評(píng)論 6 507
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件肤京,死亡現(xiàn)場(chǎng)離奇詭異颊艳,居然都是意外死亡,警方通過(guò)查閱死者的電腦和手機(jī)忘分,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 93,305評(píng)論 3 395
  • 文/潘曉璐 我一進(jìn)店門(mén)棋枕,熙熙樓的掌柜王于貴愁眉苦臉地迎上來(lái),“玉大人妒峦,你說(shuō)我怎么就攤上這事重斑。” “怎么了肯骇?”我有些...
    開(kāi)封第一講書(shū)人閱讀 165,138評(píng)論 0 355
  • 文/不壞的土叔 我叫張陵窥浪,是天一觀的道長(zhǎng)。 經(jīng)常有香客問(wèn)我笛丙,道長(zhǎng)漾脂,這世上最難降的妖魔是什么? 我笑而不...
    開(kāi)封第一講書(shū)人閱讀 58,791評(píng)論 1 295
  • 正文 為了忘掉前任胚鸯,我火速辦了婚禮骨稿,結(jié)果婚禮上兽泄,老公的妹妹穿的比我還像新娘败玉。我一直安慰自己谢鹊,他們只是感情好彻磁,可當(dāng)我...
    茶點(diǎn)故事閱讀 67,794評(píng)論 6 392
  • 文/花漫 我一把揭開(kāi)白布。 她就那樣靜靜地躺著辙浑,像睡著了一般激涤。 火紅的嫁衣襯著肌膚如雪。 梳的紋絲不亂的頭發(fā)上例衍,一...
    開(kāi)封第一講書(shū)人閱讀 51,631評(píng)論 1 305
  • 那天,我揣著相機(jī)與錄音已卸,去河邊找鬼佛玄。 笑死,一個(gè)胖子當(dāng)著我的面吹牛累澡,可吹牛的內(nèi)容都是我干的梦抢。 我是一名探鬼主播,決...
    沈念sama閱讀 40,362評(píng)論 3 418
  • 文/蒼蘭香墨 我猛地睜開(kāi)眼愧哟,長(zhǎng)吁一口氣:“原來(lái)是場(chǎng)噩夢(mèng)啊……” “哼奥吩!你這毒婦竟也來(lái)了?” 一聲冷哼從身側(cè)響起蕊梧,我...
    開(kāi)封第一講書(shū)人閱讀 39,264評(píng)論 0 276
  • 序言:老撾萬(wàn)榮一對(duì)情侶失蹤霞赫,失蹤者是張志新(化名)和其女友劉穎,沒(méi)想到半個(gè)月后肥矢,有當(dāng)?shù)厝嗽跇?shù)林里發(fā)現(xiàn)了一具尸體端衰,經(jīng)...
    沈念sama閱讀 45,724評(píng)論 1 315
  • 正文 獨(dú)居荒郊野嶺守林人離奇死亡,尸身上長(zhǎng)有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 37,900評(píng)論 3 336
  • 正文 我和宋清朗相戀三年甘改,在試婚紗的時(shí)候發(fā)現(xiàn)自己被綠了旅东。 大學(xué)時(shí)的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點(diǎn)故事閱讀 40,040評(píng)論 1 350
  • 序言:一個(gè)原本活蹦亂跳的男人離奇死亡十艾,死狀恐怖抵代,靈堂內(nèi)的尸體忽然破棺而出,到底是詐尸還是另有隱情忘嫉,我是刑警寧澤荤牍,帶...
    沈念sama閱讀 35,742評(píng)論 5 346
  • 正文 年R本政府宣布,位于F島的核電站庆冕,受9級(jí)特大地震影響参淫,放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜愧杯,卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 41,364評(píng)論 3 330
  • 文/蒙蒙 一涎才、第九天 我趴在偏房一處隱蔽的房頂上張望。 院中可真熱鬧,春花似錦耍铜、人聲如沸邑闺。這莊子的主人今日做“春日...
    開(kāi)封第一講書(shū)人閱讀 31,944評(píng)論 0 22
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽(yáng)陡舅。三九已至,卻和暖如春伴挚,著一層夾襖步出監(jiān)牢的瞬間靶衍,已是汗流浹背。 一陣腳步聲響...
    開(kāi)封第一講書(shū)人閱讀 33,060評(píng)論 1 270
  • 我被黑心中介騙來(lái)泰國(guó)打工茎芋, 沒(méi)想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留颅眶,地道東北人。 一個(gè)月前我還...
    沈念sama閱讀 48,247評(píng)論 3 371
  • 正文 我出身青樓田弥,卻偏偏與公主長(zhǎng)得像涛酗,于是被迫代替她去往敵國(guó)和親。 傳聞我的和親對(duì)象是個(gè)殘疾皇子偷厦,可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 44,979評(píng)論 2 355