上一篇中也介绍了Input dispatching timed out的ANR,不过和这篇不同,这篇介绍另外一种情况。
其实Input dispatching timed out有两种类型,
Input dispatching timed out (Application does not have a focused window)
Input dispatching timed out((server) is not responding. Waited 5002ms for FocusEvent(hasFocus=false))
一个是没有焦点窗口类型的ANR,一个是server没有相应的ANR,这两个类型是不一样的。
第一步:看trace
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 ----- pid 3450 at 2024-07-20 15:00:45.488171976+0800 ----- Cmd line: com.android.launcher Build fingerprint: ... ABI: 'arm64' Build type: optimized suspend all histogram: Sum: 115.145ms 99% C.I. 4us-2627.839us Avg: 104.867us Max: 16982us DALVIK THREADS (54): "main" prio=5 tid=1 Native | group="main" sCount=1 ucsCount=0 flags=1 obj=0x7350ccc8 self=0xb40000769ac3bc00 | sysTid=3450 nice=0 cgrp=foreground sched=1073741824/0 handle=0x774754bd20 | state=S schedstat=( 101214367947 65037795077 427377 ) utm=5880 stm=4241 core=7 HZ=100 | stack=0x7fdd469000-0x7fdd46b000 stackSize=8188KB | held mutexes= native: #00 pc 00103948 /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8) (BuildId: cfb29c0416191d0feb982f339b1db790) native: #01 pc 00013b64 /system/lib64/libutils.so (android::Looper::pollOnce+212) (BuildId: 3aebfffd3ac50a5226f05c433859cfec) native: #02 pc 0018a9fc /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce+44) (BuildId: 654cc93af0922f402e82c0c71ac0c77d) at android.os.MessageQueue.nativePollOnce(Native method) at android.os.MessageQueue.next(MessageQueue.java:346) at android.os.Looper.loopOnce(Looper.java:189) at android.os.Looper.loop(Looper.java:317) at android.app.ActivityThread.main(ActivityThread.java:8825) at java.lang.reflect.Method.invoke(Native method) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:617) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1002)
根据上篇的分析,该线程状态为Native,另外通过堆栈信息可知,主线程阻塞,处于等待消息状态
第二步:anr类型
1 2 // input dispatching timed out 类型ANR 07-20 15:01:37.293 1385 20230 I am_anr : [0,3450,com.android.launcher,751550021,Input dispatching timed out ([Gesture Monitor] swipe-up (server) is not responding. Waited 5001ms for MotionEvent).]
根据Event Log中的am_anr信息可知,该ANR类型为Input dispatching timed out中的(server) is not responding
第三步:AnrManager看负载
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 // 负载正常 07-20 15:01:37.295 1385 20230 I AnrManager: startAnrDump 07-20 15:01:37.295 1385 20230 I AnrManager: isANRFlowSkipped() AnrFlow = 0 07-20 15:01:37.295 1385 20230 I AnrManager: enableTraceLog: false 07-20 15:01:37.313 1385 20230 I AnrManager: dumpAnrDebugInfo begin: AnrDumpRecord{ Input dispatching timed out ([Gesture Monitor] swipe-up (server) is not responding. Waited 5001ms for MotionEvent). ProcessRecord{de1551 3450:com.android.launcher/u0a71} IsCompleted:false IsCancelled:false }, onlyDumpSelf = false, isSilentANR = true 07-20 15:01:37.313 1385 20230 I AnrManager: dumpAnrDebugInfoLocked: AnrDumpRecord{ Input dispatching timed out ([Gesture Monitor] swipe-up (server) is not responding. Waited 5001ms for MotionEvent). ProcessRecord{de1551 3450:com.android.launcher/u0a71} IsCompleted:false IsCancelled:false }, onlyDumpSelf = false, isSilentANR = true 07-20 15:01:37.318 1385 20230 I AnrManager: dumpStackTraces begin! 07-20 15:01:37.339 1385 20230 I AnrManager: dumpStackTraces end! 07-20 15:01:37.340 1385 20230 I AnrManager: ANR in com.android.launcher, time=35798802 07-20 15:01:37.340 1385 20230 I AnrManager: Reason: Input dispatching timed out ([Gesture Monitor] swipe-up (server) is not responding. Waited 5001ms for MotionEvent). 07-20 15:01:37.340 1385 20230 I AnrManager: Load: 0.0 / 0.0 / 0.0 07-20 15:01:37.340 1385 20230 I AnrManager: ----- Output from /proc/pressure/memory ----- 07-20 15:01:37.340 1385 20230 I AnrManager: some avg10=5.78 avg60=7.18 avg300=5.23 total=1849848689 07-20 15:01:37.340 1385 20230 I AnrManager: full avg10=3.34 avg60=4.27 avg300=3.61 total=1414753582 07-20 15:01:37.340 1385 20230 I AnrManager: ----- End output from /proc/pressure/memory ----- 07-20 15:01:37.340 1385 20230 I AnrManager: ----- Output from /proc/pressure/cpu ----- 07-20 15:01:37.340 1385 20230 I AnrManager: some avg10=17.69 avg60=17.16 avg300=10.98 total=3819815231 07-20 15:01:37.340 1385 20230 I AnrManager: full avg10=0.00 avg60=0.00 avg300=0.00 total=0 07-20 15:01:37.340 1385 20230 I AnrManager: ----- End output from /proc/pressure/cpu ----- 07-20 15:01:37.340 1385 20230 I AnrManager: ----- Output from /proc/pressure/io ----- 07-20 15:01:37.340 1385 20230 I AnrManager: some avg10=6.50 avg60=8.17 avg300=5.41 total=1788313432 07-20 15:01:37.340 1385 20230 I AnrManager: full avg10=1.22 avg60=1.82 avg300=1.98 total=924602791 07-20 15:01:37.340 1385 20230 I AnrManager: ----- End output from /proc/pressure/io ----- 07-20 15:01:37.340 1385 20230 I AnrManager: 07-20 15:01:37.340 1385 20230 I AnrManager: Android time :[2024-07-20 15:01:37.33] [35798.848] 07-20 15:01:37.340 1385 20230 I AnrManager: CPU usage from 9610ms to 59ms ago (2024-07-20 15:01:27.683 to 2024-07-20 15:01:37.233): 07-20 15:01:37.340 1385 20230 I AnrManager: 215% 1385/system_server: 172% user + 43% kernel / faults: 18676 minor 1206 major 07-20 15:01:37.340 1385 20230 I AnrManager: 54% 20857/com.taobao.taobao: 31% user + 22% kernel / faults: 7243 minor 733 major 07-20 15:01:37.340 1385 20230 I AnrManager: 25% 21570/com.taobao.taobao:channel: 15% user + 9.6% kernel / faults: 2519 minor 2043 major 07-20 15:01:37.340 1385 20230 I AnrManager: 14% 835/surfaceflinger: 8.8% user + 5.4% kernel / faults: 1678 minor 230 major 07-20 15:01:37.340 1385 20230 I AnrManager: 13% 92/kswapd0: 0% user + 13% kernel 07-20 15:01:37.340 1385 20230 I AnrManager: 8.3% 24987/com.android.systemui: 4.2% user + 4% kernel / faults: 1097 minor 2425 major 07-20 15:01:37.340 1385 20230 I AnrManager: 6.3% 3712/com.android.providers.media.module: 2.9% user + 3.4% kernel / faults: 13 minor 25 major 07-20 15:01:37.340 1385 20230 I AnrManager: 5.6% 935/adbd: 1.3% user + 4.2% kernel / faults: 106 minor 47 major 07-20 15:01:37.340 1385 20230 I AnrManager: 4.6% 14487/com.google.android.gms: 2.1% user + 2.4% kernel / faults: 5179 minor 3976 major 07-20 15:01:37.340 1385 20230 I AnrManager: 3.9% 785/android.hardware.graphics.composer@3.1-service: 1.6% user + 2.3% kernel / faults: 42 minor 16 major 07-20 15:01:37.340 1385 20230 I AnrManager: 3.5% 404/logd: 1.2% user + 2.3% kernel / faults: 1031 minor 138 major 07-20 15:01:37.340 1385 20230 I AnrManager: 3.5% 19470/com.google.android.apps.nbu.files: 2.1% user + 1.3% kernel / faults: 3576 minor 3443 major 07-20 15:01:37.340 1385 20230 I AnrManager: 3.2% 591/kssbd: 0% user + 3.2% kernel ... 07-20 15:01:37.340 1385 20230 I AnrManager: 64% TOTAL: 36% user + 22% kernel + 1.5% iowait + 2.8% irq + 0.7% softirq 07-20 15:01:37.340 1385 20230 I AnrManager: CPU usage from 35798802ms to 35798802ms ago (1970-01-01 08:00:00.000 to 1970-01-01 08:00:00.000) with 0% awake: 07-20 15:01:37.340 1385 20230 I AnrManager: 0% TOTAL: 0% user + 0% kernel 07-20 15:01:37.340 1385 20230 I AnrManager: dumpAnrDebugInfo end: AnrDumpRecord{ Input dispatching timed out ([Gesture Monitor] swipe-up (server) is not responding. Waited 5001ms for MotionEvent). ProcessRecord{de1551 3450:com.android.launcher/u0a71} IsCompleted:true IsCancelled:false }, onlyDumpSelf = false , isSilentANR = true 07-20 15:01:37.341 1385 20230 I AnrManager: addErrorToDropBox app = ProcessRecord{de1551 3450:com.android.launcher/u0a71} processName = com.android.launcher activityShortComponentName = null parentShortComponentName = null parentProcess = null annotation = Input dispatching timed out ([Gesture Monitor] swipe-up (server) is not responding. Waited 5001ms for MotionEvent). mTracesFile = /data/anr/anr_2024-07-20-15-01-37-318 07-20 15:01:37.341 1385 20230 I AnrManager: controller = android.app.IActivityController$Stub$Proxy@54e68af
通过负载来看,负载并不高,因此还需要查看其他原因。
这样的话我们按照上篇还要再分析Event log 和logcat信息,
从Logcat中我们得到如下信息,
1 2 // 主线程耗时太久导致 07-20 15:00:45.316 1385 1385 W Looper : Slow dispatch took 10578ms main h=com.android.server.power.Notifier$NotifierHandler c=null m=1
com.android.server.power.Notifier$NotifierHandler 这个里面主线程耗时太久,用了10578ms,从时间看正好在ANR发生(trace:2024-07-20 15:00:45.488)之前,那么可以断定,是由于该耗时操作导致Input
事件未及时处理出现了分发超时,导致了ANR发生。
关键信息:
WindowManager
,InputDispatcher
,timeout
, Looper