no focus ANR 初级分析

首先,no focus ANR报出是以统计焦点窗口为null的时间为准,只有窗口焦点为null的时间超时5秒才会报出;

ANR发生前,23:10:46.589 WMS把焦点窗口置为了null;

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

AMS把camera2 设为焦点应用,开始启动(该句Log输出有延迟);

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

camera2 开始创建进程,进程创建完成;

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 开始执行自己的逻辑代码,执行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满足转换焦点窗口条件,可以开始转移焦点窗口到CameraLauncher;

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

从no focus ANR报出原理来说,ANR发生的真正时间点应该是23:10:51秒,当时系统负载比较高,下面Log输出的时间出现延迟也是正常现象;

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.

焦点窗口转移到CameraLauncher,ANR已发生了2秒多,ANR发生后AMS需要dump 相关现场信息,dump过程中系统IO,性能短时间内都是异常高,会造成WMS转移焦点的延迟。

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发生时间段CPU整体负载是比较高的;

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收到启动一个新Activity的消息后,焦点窗口就会置为null,等到新Activity生命周期走完onResume,WMS才会再转移焦点窗口,结束焦点窗口为null的状态,从目前Log来看,从窗口焦点为null,到CameraLauncher生命周期走完onResume,已经超时了5秒,所以报出ANR,应用启动缓慢是ANR主要原因,以下两个原因导致应用启动慢;

  1. 系统原因,系统整体负载较高,32v4版本本身硬件条件有限,测试期间很容易出现系统高负载,CPU高负载及内存紧张会影响应用进程的创建速度、核心系统服务与应用的交互速度等,从当前Log中就可以看到camera2从启动到进程创建完成花费了1秒。其中ANR期间,browser,gallery3d等应用启动也增加了系统负载;

  2. Camera2 本身逻辑执行花费了3.916;

该ANR是测试14.63 h后,由于系统负载比较高,而Camera又是一个启动需要占用较多资源的应用,应用偶然启动超时5秒报出的问题;

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,968评论 6 482
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,601评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 153,220评论 0 344
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,416评论 1 279
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,425评论 5 374
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,144评论 1 285
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,432评论 3 401
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,088评论 0 261
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,586评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,028评论 2 325
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,137评论 1 334
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,783评论 4 324
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,343评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,333评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,559评论 1 262
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,595评论 2 355
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,901评论 2 345

推荐阅读更多精彩内容