首先,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主要原因,以下两个原因导致应用启动慢;
系统原因,系统整体负载较高,32v4版本本身硬件条件有限,测试期间很容易出现系统高负载,CPU高负载及内存紧张会影响应用进程的创建速度、核心系统服务与应用的交互速度等,从当前Log中就可以看到camera2从启动到进程创建完成花费了1秒。其中ANR期间,browser,gallery3d等应用启动也增加了系统负载;
Camera2 本身逻辑执行花费了3.916;
该ANR是测试14.63 h后,由于系统负载比较高,而Camera又是一个启动需要占用较多资源的应用,应用偶然启动超时5秒报出的问题;