no focus ANR 初級(jí)分析

首先褒纲，no focus ANR報(bào)出是以統(tǒng)計(jì)焦點(diǎn)窗口為null的時(shí)間為準(zhǔn)准夷，只有窗口焦點(diǎn)為null的時(shí)間超時(shí)5秒才會(huì)報(bào)出；

ANR發(fā)生前莺掠，23:10:46.589 WMS把焦點(diǎn)窗口置為了null衫嵌；

01-01 23:10:46.589  2183 23336 D WindowManager: Input focus has changed to null

AMS把camera2 設(shè)為焦點(diǎn)應(yīng)用，開始啟動(dòng)(該句Log輸出有延遲)彻秆；

01-01 23:10:46.900  2183  4522 I am_focused_activity: [0,com.android.camera2/com.android.camera.CameraLauncher]

camera2 開始創(chuàng)建進(jìn)程楔绞，進(jìn)程創(chuàng)建完成结闸；

01-01 23:10:47.525  2183  2256 I am_proc_start: [0,20513,10040,com.android.camera2,activity,com.android.camera2/com.android.camera.CameraLauncher]
01-01 23:10:47.667  2183  2203 I am_proc_bound: [0,20513,com.android.camera2]

camera2 開始執(zhí)行自己的邏輯代碼，執(zhí)行onCreate,onResume等生命周期酒朵；

01-01 23:10:47.675  2183  2203 I am_restart_activity: [0,25833464,2298,com.android.camera2/com.android.camera.CameraLauncher]

camera2 生命周期走完onResume, WMS滿足轉(zhuǎn)換焦點(diǎn)窗口條件桦锄，可以開始轉(zhuǎn)移焦點(diǎn)窗口到CameraLauncher；

01-01 23:10:51.591 20513 20513 I am_on_resume_called: [0,com.android.camera.CameraLauncher]

從no focus ANR報(bào)出原理來說蔫耽，ANR發(fā)生的真正時(shí)間點(diǎn)應(yīng)該是23:10:51秒结耀，當(dāng)時(shí)系統(tǒng)負(fù)載比較高，下面Log輸出的時(shí)間出現(xiàn)延遲也是正吵渍。現(xiàn)象图甜；

01-01 23:10:52.450  2183  3086 I WindowManager: Input event dispatching timed out sending to application AppWindowToken{c86733c token=Token{4442cd1 ActivityRecord{18a2ff8 u0 com.android.camera2/com.android.camera.CameraLauncher t2298}}}.  Reason: Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.

焦點(diǎn)窗口轉(zhuǎn)移到CameraLauncher，ANR已發(fā)生了2秒多鳖眼，ANR發(fā)生后AMS需要dump 相關(guān)現(xiàn)場(chǎng)信息黑毅，dump過程中系統(tǒng)IO，性能短時(shí)間內(nèi)都是異常高具帮，會(huì)造成WMS轉(zhuǎn)移焦點(diǎn)的延遲博肋。

01-01 23:10:53.117  2183  2204 D WindowManager: Input focus has changed to Window{f9649b7 u0 com.android.camera2/com.android.camera.CameraLauncher}

過濾event.log

01-01 23:10:46.644  2183 23331 I am_proc_start: [0,20384,10008,com.android.browser,activity,com.android.browser/.BrowserActivity]
01-01 23:10:46.699  2183  3728 I am_proc_bound: [0,20384,com.android.browser]
01-01 23:10:46.706  2183  3728 I am_restart_activity: [0,145542536,2341,com.android.browser/.BrowserActivity]
>>01-01 23:10:46.900  2183  4522 I am_focused_activity: [0,com.android.camera2/com.android.camera.CameraLauncher]
>>01-01 23:10:46.985  2183  4522 I am_pause_activity: [0,145542536,com.android.browser/.BrowserActivity]
01-01 23:10:46.992  2183  4522 I am_task_to_front: [0,2298]
01-01 23:10:46.992  2183  4522 I am_new_intent: [0,107367927,2298,com.android.camera2/com.android.camera.CameraLauncher,android.intent.action.MAIN,NULL,NULL,274726912]
01-01 23:10:47.029   209   209 I sf_frame_dur: [com.android.calendar/com.android.calendar.PermissionsActivity,87,1,0,0,2,1,0]
01-01 23:10:47.473   209   209 I sf_frame_dur: [com.android.calendar/com.android.calendar.PermissionsActivity,0,0,0,0,1,0,0]
>>01-01 23:10:47.525  2183  2256 I am_proc_start: [0,20513,10040,com.android.camera2,activity,com.android.camera2/com.android.camera.CameraLauncher]
>>01-01 23:10:47.667  2183  2203 I am_proc_bound: [0,20513,com.android.camera2]
>>01-01 23:10:47.675  2183  2203 I am_restart_activity: [0,25833464,2298,com.android.camera2/com.android.camera.CameraLauncher]
01-01 23:10:48.288  2183  3725 I notification_cancel_all: [10040,20513,com.android.camera2,0,0,64,9,NULL]
01-01 23:10:49.424   208   208 I auditd  : avc:  denied  { find } for service=batteryproperties scontext=u:r:platform_app:s0:c512,c768 tcontext=u:object_r:healthd_service:s0 tclass=service_manager
>>01-01 23:10:49.639 20384 20384 I am_on_resume_called: [0,com.android.browser.BrowserActivity]
>>01-01 23:10:49.913 20384 20384 I am_on_paused_called: [0,com.android.browser.BrowserActivity]
01-01 23:10:49.913  2183  1802 I am_failed_to_pause: [0,145542536,com.android.browser/.BrowserActivity,(none)]
01-01 23:10:50.275 20384 20424 I dvm_lock_sample: [com.android.browser,0,pool-1-thread-1,670,SQLiteOpenHelper.java,162,SQLiteConnection.java,-2,100]
01-01 23:10:50.630  2183  2252 I am_pss  : [4526,10032,com.android.launcher3,12627968,9732096]
01-01 23:10:50.682  2183  2252 I am_pss  : [11686,10024,com.android.music,11090944,9793536]
01-01 23:10:50.728  2183  2252 I am_pss  : [11765,10022,android.process.media,4561920,3530752]
01-01 23:10:51.108  2183  4473 I am_proc_start: [0,20910,10070,com.android.gallery3d,service,com.android.gallery3d/com.sprd.gallery3d.app.FloatWindowAIDLService]
01-01 23:10:51.413 20384 20384 I browser_page_loaded: https://www.google.com/m?hl=zh-CN&q=%5B&source=android-launcher-search|535
>>01-01 23:10:51.591 20513 20513 I am_on_resume_called: [0,com.android.camera.CameraLauncher]

ANR發(fā)生時(shí)間段CPU整體負(fù)載是比較高的低斋；

01-01 23:10:54.032  2183  2256 D SprdRuntimeInfo: Cpu Core Count: 4
01-01 23:10:54.032  2183  2256 D SprdRuntimeInfo: Timer Circle: 2999ms.
01-01 23:10:54.032  2183  2256 D SprdRuntimeInfo:   From time 52761591ms(2012-01-01 15:10:47.488555908 UTC) to 52764591ms(2012-01-01 15:10:50.488525390 UTC).
01-01 23:10:54.032  2183  2256 D SprdRuntimeInfo:
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  * CPU USAGE:                                                                              | * OTHER COUNTS:
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  -1-          IDLE     USER   SYSTEM     NICE   IOWAIT      IRQ  SOFTIRQ    STEAL    TOTAL |     CTXT_SWITCH        FG_FAULT    FG_MAJ_FAULT
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  cpu0(1):   33.33%   20.33%   26.00%    0.66%   17.33%    0.00%    2.33%    0.00%  100.00% |           10933           20617              91
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  cpu1(1):   17.33%   24.66%   20.33%    0.33%   37.33%    0.00%    0.00%    0.00%  100.00% |            6222           24698             291
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  cpu2(1):   13.00%   24.33%   22.66%    1.66%   38.33%    0.00%    0.00%    0.00%  100.00% |            6418           20368             388
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  cpu3(1):   14.33%   23.66%   18.66%    0.33%   43.00%    0.00%    0.00%    0.00%  100.00% |            7198           21917             416
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  ------------------
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:  Total:     19.50%   23.25%   21.91%    0.75%   34.00%    0.00%    0.58%    0.00%  100.00% |           30771           87600            1186
01-01 23:10:54.033  2183  2256 D SprdRuntimeInfo:

01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo: Cpu Core Count: 4
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo: Timer Circle: 3000ms.
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:   From time 52764591ms(2012-01-01 15:10:50.488525390 UTC) to 52767591ms(2012-01-01 15:10:53.488525390 UTC).
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:  * CPU USAGE:                                                                              | * OTHER COUNTS:
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:  -2-          IDLE     USER   SYSTEM     NICE   IOWAIT      IRQ  SOFTIRQ    STEAL    TOTAL |     CTXT_SWITCH        FG_FAULT    FG_MAJ_FAULT
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:  cpu0(1):   31.66%   11.66%   24.66%    2.00%   26.66%    0.00%    3.33%    0.00%  100.00% |           11503           12711             125
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:  cpu1(1):   10.33%   14.00%   29.00%    2.00%   44.66%    0.00%    0.00%    0.00%  100.00% |            6184           20094             384
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:  cpu2(1):    5.00%   17.66%   19.33%    2.66%   55.33%    0.00%    0.00%    0.00%  100.00% |            5617           16617             468
01-01 23:10:54.034  2183  2256 D SprdRuntimeInfo:  cpu3(1):    6.33%   21.33%   20.33%    5.66%   46.33%    0.00%    0.00%    0.00%  100.00% |            5642           30951             427
01-01 23:10:54.035  2183  2256 D SprdRuntimeInfo:  ------------------
01-01 23:10:54.035  2183  2256 D SprdRuntimeInfo:  Total:     13.33%   16.16%   23.33%    3.08%   43.25%    0.00%    0.83%    0.00%  100.00% |           28946           80373            1404
01-01 23:10:54.035  2183  2256 D SprdRuntimeInfo:

AMS收到啟動(dòng)一個(gè)新Activity的消息后蜂厅，焦點(diǎn)窗口就會(huì)置為null，等到新Activity生命周期走完onResume膊畴，WMS才會(huì)再轉(zhuǎn)移焦點(diǎn)窗口掘猿，結(jié)束焦點(diǎn)窗口為null的狀態(tài)，從目前Log來看唇跨，從窗口焦點(diǎn)為null稠通，到CameraLauncher生命周期走完onResume,已經(jīng)超時(shí)了5秒，所以報(bào)出ANR买猖，應(yīng)用啟動(dòng)緩慢是ANR主要原因改橘，以下兩個(gè)原因?qū)е聭?yīng)用啟動(dòng)慢；

  1. 系統(tǒng)原因玉控，系統(tǒng)整體負(fù)載較高飞主，32v4版本本身硬件條件有限，測(cè)試期間很容易出現(xiàn)系統(tǒng)高負(fù)載高诺，CPU高負(fù)載及內(nèi)存緊張會(huì)影響應(yīng)用進(jìn)程的創(chuàng)建速度碌识、核心系統(tǒng)服務(wù)與應(yīng)用的交互速度等，從當(dāng)前Log中就可以看到camera2從啟動(dòng)到進(jìn)程創(chuàng)建完成花費(fèi)了1秒虱而。其中ANR期間筏餐，browser，gallery3d等應(yīng)用啟動(dòng)也增加了系統(tǒng)負(fù)載牡拇；

  2. Camera2 本身邏輯執(zhí)行花費(fèi)了3.916魁瞪；

該ANR是測(cè)試14.63 h后穆律，由于系統(tǒng)負(fù)載比較高，而Camera又是一個(gè)啟動(dòng)需要占用較多資源的應(yīng)用导俘，應(yīng)用偶然啟動(dòng)超時(shí)5秒報(bào)出的問題众旗；

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
  • 人面猴
    序言：七十年代末，一起剝皮案震驚了整個(gè)濱河市趟畏，隨后出現(xiàn)的幾起案子贡歧，更是在濱河造成了極大的恐慌，老刑警劉巖赋秀，帶你破解...
    沈念sama閱讀 219,188評(píng)論 6贊 508
  • 死咒
    序言：濱河連續(xù)發(fā)生了三起死亡事件利朵，死亡現(xiàn)場(chǎng)離奇詭異，居然都是意外死亡猎莲，警方通過查閱死者的電腦和手機(jī)绍弟，發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 93,464評(píng)論 3贊 395
  • 救了他兩次的神仙讓他今天三更去死
    文/潘曉璐 我一進(jìn)店門，熙熙樓的掌柜王于貴愁眉苦臉地迎上來著洼，“玉大人樟遣，你說我怎么就攤上這事∩眢裕” “怎么了豹悬？”我有些...
    開封第一講書人閱讀 165,562評(píng)論 0贊 356
  • 道士緝兇錄：失蹤的賣姜人
    文/不壞的土叔 我叫張陵，是天一觀的道長液荸。 經(jīng)常有香客問我瞻佛，道長，這世上最難降的妖魔是什么娇钱？ 我笑而不...
    開封第一講書人閱讀 58,893評(píng)論 1贊 295
  • ?港島之戀（遺憾婚禮）
    正文 為了忘掉前任伤柄，我火速辦了婚禮，結(jié)果婚禮上文搂，老公的妹妹穿的比我還像新娘适刀。我一直安慰自己，他們只是感情好煤蹭，可當(dāng)我...
    茶點(diǎn)故事閱讀 67,917評(píng)論 6贊 392
  • 惡毒庶女頂嫁案：這布局不是一般人想出來的
    文/花漫 我一把揭開白布笔喉。 她就那樣靜靜地躺著，像睡著了一般疯兼。 火紅的嫁衣襯著肌膚如雪然遏。 梳的紋絲不亂的頭發(fā)上，一...
    開封第一講書人閱讀 51,708評(píng)論 1贊 305
  • 城市分裂傳說
    那天吧彪，我揣著相機(jī)與錄音待侵，去河邊找鬼。 笑死姨裸，一個(gè)胖子當(dāng)著我的面吹牛秧倾，可吹牛的內(nèi)容都是我干的怨酝。 我是一名探鬼主播，決...
    沈念sama閱讀 40,430評(píng)論 3贊 420
  • 雙鴛鴦連環(huán)套：你想象不到人心有多黑
    文/蒼蘭香墨 我猛地睜開眼那先，長吁一口氣：“原來是場(chǎng)噩夢(mèng)啊……” “哼农猬！你這毒婦竟也來了？” 一聲冷哼從身側(cè)響起售淡，我...
    開封第一講書人閱讀 39,342評(píng)論 0贊 276
  • 萬榮殺人案實(shí)錄
    序言：老撾萬榮一對(duì)情侶失蹤斤葱，失蹤者是張志新（化名）和其女友劉穎，沒想到半個(gè)月后揖闸，有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體揍堕，經(jīng)...
    沈念sama閱讀 45,801評(píng)論 1贊 317
  • ?護(hù)林員之死
    正文 獨(dú)居荒郊野嶺守林人離奇死亡，尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 37,976評(píng)論 3贊 337
  • ?白月光啟示錄
    正文 我和宋清朗相戀三年汤纸，在試婚紗的時(shí)候發(fā)現(xiàn)自己被綠了衩茸。 大學(xué)時(shí)的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點(diǎn)故事閱讀 40,115評(píng)論 1贊 351
  • 活死人
    序言：一個(gè)原本活蹦亂跳的男人離奇死亡贮泞，死狀恐怖楞慈，靈堂內(nèi)的尸體忽然破棺而出，到底是詐尸還是另有隱情啃擦，我是刑警寧澤囊蓝，帶...
    沈念sama閱讀 35,804評(píng)論 5贊 346
  • ?日本核電站爆炸內(nèi)幕
    正文 年R本政府宣布，位于F島的核電站议惰，受9級(jí)特大地震影響慎颗，放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜言询，卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 41,458評(píng)論 3贊 331
  • 男人毒藥：我在死后第九天來索命
    文/蒙蒙 一、第九天 我趴在偏房一處隱蔽的房頂上張望傲宜。 院中可真熱鬧运杭，春花似錦、人聲如沸函卒。這莊子的主人今日做“春日...
    開封第一講書人閱讀 32,008評(píng)論 0贊 22
  • 一樁弒父案，背后竟有這般陰謀
    文/蒼蘭香墨 我抬頭看了看天上的太陽报嵌。三九已至虱咧，卻和暖如春，著一層夾襖步出監(jiān)牢的瞬間锚国，已是汗流浹背腕巡。 一陣腳步聲響...
    開封第一講書人閱讀 33,135評(píng)論 1贊 272
  • 情欲美人皮
    我被黑心中介騙來泰國打工， 沒想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留血筑，地道東北人绘沉。 一個(gè)月前我還...
    沈念sama閱讀 48,365評(píng)論 3贊 373
  • 代替公主和親
    正文 我出身青樓煎楣，卻偏偏與公主長得像，于是被迫代替她去往敵國和親车伞。 傳聞我的和親對(duì)象是個(gè)殘疾皇子择懂，可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 45,055評(píng)論 2贊 355

推薦閱讀更多精彩內(nèi)容