上一篇中也介绍了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发生。

关键信息:

WindowManagerInputDispatchertimeout, Looper