AAA项目Monkey测试必现ANR问题分析

【摘要】ANR(Application Not responding)，是指应用程序未响应，Android系统对于一些事件需要在一定的时间范围内完成，如果超过预定时间能未能得到有效响应或者响应时间过长，比如输入事件5s内未执行完成、前台广播10s内未执行完成等都会造成ANR。一般地，这时往往会弹出一个提示框，告知用户当前xxx未响应，用户可选择继续等待或者Force Close。
【关键字】 ANR Monkey 输入事件 超时

一、问题背景

AAA项目进行Monkey测试过程中发生大量ANR，此类ANR大多非系统性能相关，与原生系统设计缺陷、应用缺陷较多。此类问题大多数从常规的system.log、main.log、anr.log日志上是看不出原因的。处理起来很棘手，比较难找到突破口。

二、解决思路

由于是Monkey自动化测试报出来的问题，没有录屏，并且测试也提供不了操作路径，只能通过anr发生时在event.log打印的焦点信息，手动复现、模型出操作路径，比对正常时调用所打印的event.log，进一步分析原因。下面主要介绍如何将ANR复现出来并解决

三、分析过程

3.1 SystemUI ANR

分析过程
从system.log上看系统整体负载不高，systemui进程id 2462
01-14 08:44:04.141931 1163 18333 I AnrManager: ANR in com.android.systemui, time=489072796
01-14 08:44:04.141931 1163 18333 I AnrManager: Reason: Input dispatching timed out (Application does not have a focused window)
01-14 08:44:04.141931 1163 18333 I AnrManager: Android time :[2024-01-14 08:44:04.13] [489077.156]
01-14 08:44:04.141931 1163 18333 I AnrManager: CPU usage from 201076ms to 0ms ago (2024-01-14 08:40:38.693 to 2024-01-14 08:43:59.769) with 99% awake:
01-14 08:44:04.141931 1163 18333 I AnrManager: 9.5% 731/surfaceflinger: 6.9% user + 2.6% kernel / faults: 2777 minor 5 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 9.2% 1163/system_server: 5.9% user + 3.3% kernel / faults: 68876 minor 291 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 5.4% 156/kswapd0: 0% user + 5.4% kernel
01-14 08:44:04.141931 1163 18333 I AnrManager: 5% 2800/com.android.launcher3: 3.2% user + 1.7% kernel / faults: 12788 minor 308 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 4.6% 2462/com.android.systemui: 2.9% user + 1.6% kernel / faults: 39280 minor 791 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 3.9% 9785/com.google.android.googlequicksearchbox:search: 2.4% user + 1.4% kernel / faults: 40695 minor 2196 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 3.5% 715/android.hardware.graphics.composer@2.1-service: 1.4% user + 2% kernel / faults: 483 minor 5 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 3.2% 442/logd: 1% user + 2.2% kernel / faults: 6387 minor 1 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 1.6% 31111/com.google.android.gms.persistent: 1% user + 0.6% kernel / faults: 14683 minor 102 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 1.3% 911/mobile_log_d: 0.7% user + 0.6% kernel / faults: 9657 minor 2 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 1.2% 945/vendor.mediatek.hardware.pq@2.2-service: 0.5% user + 0.7% kernel
01-14 08:44:04.141931 1163 18333 I AnrManager: 1.2% 3897/com.google.android.inputmethod.latin: 0.7% user + 0.4% kernel / faults: 13968 minor 359 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 0.9% 16084/com.google.android.apps.safetyhub: 0.6% user + 0.2% kernel / faults: 10282 minor 120 major
01-14 08:44:04.141931 1163 18333 I AnrManager: 0.8% 14662/kworker/u17:4-fpsgo_notifier_wq: 0% user + 0.8% kernel
…
01-14 08:44:04.143952 1163 18333 I AnrManager: 28% TOTAL: 10% user + 14% kernel + 0.9% iowait + 1.9% softirq
anr.log dump出了此时2462各线程信息，应用主线程并未处于阻塞状态，无locked关键字：

图1 anr.log systemui进程信息

anr发生前，应用销毁后、未见应用发起oncreate\onresume，frameworks也就没有relayout。

图2 main.log

因此，在01-14 08:43:49 input_focus: [Focus leaving 1b82ba8 NotificationShade (server),reason=NOT_VISIBLE]离开焦点后，也就没有收到新的Focus request。持续到08:43:59有key事件分发超时出现anr。此时可以大致确定和应用相关了

图3 system.log搜索input_focus

但是光看以上日志并不能看出问题所在。

操作路径复现：

在event.log中，搜索 am_anr | input_focus，然后基本往anr前看两个entering就可以了

图4 event.log中搜索 am_anr | input_focus

按此操作进入InternalGoogleAppActivityEntrypoint，如果不清楚是哪个应用哪个窗口，可以通过adb shell am start -n com.google.android.googlequicksearchbox/.InternalGoogleAppActivityEntrypoint
->
Line 13461: 01-14 08:42:55.879171 1163 1188 I input_focus: [Focus request 456c242 com.google.android.googlequicksearchbox/com.google.android.googlequicksearchbox.InternalGoogleAppActivityEntrypoint,reason=UpdateInputWindows]
Line 13463: 01-14 08:42:55.924227 1163 2074 I input_focus: [Focus entering 456c242 com.google.android.googlequicksearchbox/com.google.android.googlequicksearchbox.InternalGoogleAppActivityEntrypoint (server),reason=Window became focusable. Previous reason: NOT_VISIBLE]

然后再请求NotificationShade窗口，由于是系统窗口，没有启动命令，可以通过adb shell “logcat -b all | grep NotificationShade”，然后操作手机调试看打印的日志，确定入口，最后发现是息屏和下拉状态栏的时候，会打印Focus request这个窗口。
->
Line 13521: 01-14 08:43:16.799006 1163 1188 I input_focus: [Focus request 1b82ba8 NotificationShade,reason=UpdateInputWindows]
Line 13522: 01-14 08:43:16.829891 1163 2074 I input_focus: [Focus leaving 456c242 com.google.android.googlequicksearchbox/com.google.android.googlequicksearchbox.InternalGoogleAppActivityEntrypoint (server),reason=setFocusedWindow]
Line 13523: 01-14 08:43:16.830067 1163 2074 I input_focus: [Focus entering 1b82ba8 NotificationShade (server),reason=setFocusedWindow]

//出现问题在这里，从NotificationShade 离开后，一直没用新的焦点窗口请求
Line 13695: 01-14 08:43:49.207004 1163 2074 I input_focus: [Focus leaving 1b82ba8 NotificationShade (server),reason=NOT_VISIBLE]
Line 13702: 01-14 08:43:59.776010 1163 18333 I am_anr : [0,2462,com.android.systemui,818462221,Input dispatching timed out (Application does not have a focused window)]

Focus entering 1b82ba8 NotificationShade -》 Focus leaving 1b82ba8 NotificationShade 这个过程中发生了什么呢，从NotificationShade 离开了后一直没有新窗口请求，一般进入与退出窗口间隔很短。可以初步认为这个离开是因为某些异常导致的离开。后面发现这中间过程中启动了Settings应用

图5 event.log

总结起来就是四个步骤：

1.启动adb shell am start -n com.google.android.googlequicksearchbox/.InternalGoogleAppActivityEntrypoint（需要弹出输入法时才会触发anr，与输入法有关）

图6 点击桌面谷歌搜索框

2.下拉状态栏（熄屏场景测试过了，不会触发anr）

图7 下拉面板

3.执行adb shell am start -a android.intent.action.MAIN -n com.android.settings/.Settings ，模拟启动Settings执行后的结果，会看到Settings应用（启动的应用也必须是分栏应用，与分栏有关。其次从dump window的图层看，notificationshade是在settings图层上面的，但是在dump SurfaceFlinger来看确看不到notificationshade。又在他的下面，显然是盖不住Settings的图层。如果换做是其他应用，执行adb shell am start后，从windonw、SurfaceFlinger来看，保持在最上面的仍然是notificationshade）

图8 后台启动Settings

4.按导航栏返回键或者音量键，触发key事件分派，此时会没有任何反应，然后触发systemui anr

图9 按导航栏返回键或者音量键后触发anr

经过上面操作，此anr就能复现出来了。

解决方法

根据上面的条件，输入法与分栏应用，Settings自然是不可能改成单栏的了，最后是小勇协助，根据第一点与输入法有关，我们是找到了应用那边请求notificationshade窗口时，添加了属性mLpChanged.flags |= LayoutParams.FLAG_ALT_FOCUSABLE_IM导致，添加mLpChanged.flags &= ~LayoutParams.FLAG_ALT_FOCUSABLE_IM; 移除此flag问题就解决了，需要systemui模块在合适的地方加判断修改。
NotificationShadeWindowControllerImpl.java

图10 问题点代码

Systemui模块最终的修改方案：
在屏幕已经解锁、执行下拉面板场景下移除FLAG_ALT_FOCUSABLE_IM

图 11 systemui anr修改方案

3.2 System ANR

ANR时间点2024-01-14 14:18:26.03，整体系统负载并不高，系统主要的各进程号如下：
01-14 14:18:26.043270 1169 12313 I AnrManager: ANR in system, time=457736581
01-14 14:18:26.043270 1169 12313 I AnrManager: Reason: Input dispatching timed out (Application does not have a focused window)
01-14 14:18:26.043270 1169 12313 I AnrManager: Load: 19.95 / 20.0 / 20.31
01-14 14:18:26.043270 1169 12313 I AnrManager: Android time :[2024-01-14 14:18:26.03] [457740.969]
01-14 14:18:26.043270 1169 12313 I AnrManager: CPU usage from 91061ms to -1ms ago (2024-01-14 14:16:50.589 to 2024-01-14 14:18:21.651):
01-14 14:18:26.043270 1169 12313 I AnrManager: 99% 3064/kworker/u16:1-kverityd: 0% user + 99% kernel
01-14 14:18:26.043270 1169 12313 I AnrManager: 8.7% 743/surfaceflinger: 6.3% user + 2.4% kernel / faults: 2247 minor 3 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 8% 1169/system_server: 5.2% user + 2.8% kernel / faults: 39683 minor 316 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 2.6% 157/kswapd0: 0% user + 2.6% kernel
01-14 14:18:26.043270 1169 12313 I AnrManager: 2.5% 19076/com.google.android.googlequicksearchbox:search: 1.7% user + 0.8% kernel / faults: 3158 minor 155 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 2.4% 719/android.hardware.graphics.composer@2.1-service: 0.9% user + 1.4% kernel / faults: 37 minor
01-14 14:18:26.043270 1169 12313 I AnrManager: 2.1% 450/logd: 0.7% user + 1.4% kernel / faults: 2769 minor 1 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 2.1% 2469/com.android.systemui: 1.2% user + 0.8% kernel / faults: 25122 minor 560 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 1.5% 23019/com.google.android.inputmethod.latin: 1.1% user + 0.4% kernel / faults: 2487 minor 56 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 1% 736/audioserver: 0.7% user + 0.2% kernel / faults: 1008 minor 16 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 1% 20717/com.google.android.accessibility.switchaccess: 0.7% user + 0.2% kernel / faults: 7246 minor 15 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 0.9% 909/mobile_log_d: 0.5% user + 0.4% kernel / faults: 4500 minor 1 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 0.9% 5898/com.google.android.gms.persistent: 0.5% user + 0.4% kernel / faults: 5064 minor 18 major
01-14 14:18:26.043270 1169 12313 I AnrManager: 0.8% 907/mediaserver: 0.4% user + 0.3% kernel / faults: 1690 minor 15 major
…
01-14 14:18:26.043407 1169 12313 I AnrManager: 2.3% 157/kswapd0: 0% user + 2.3% kernel
01-14 14:18:26.043407 1169 12313 I AnrManager: 3.3% 5898/com.google.android.gms.persistent: 3.3% user + 0% kernel
01-14 14:18:26.043407 1169 12313 I AnrManager: 3.3% 6304/kworker/u16:7-kverityd: 0% user + 3.3% kernel
01-14 14:18:26.043407 1169 12313 I AnrManager: 3.5% 8765/kworker/u16:11-kverityd: 0% user + 3.5% kernel
01-14 14:18:26.043407 1169 12313 I AnrManager: 4.1% 21014/kworker/u16:4-kverityd: 0% user + 4.1% kernel
01-14 14:18:26.043407 1169 12313 I AnrManager: 54% TOTAL: 20% user + 29% kernel + 1.3% iowait + 2.2% softirq
在所有anr.log中检索pid，查找2024-01-14 14h附近dump出来的系统各进程异常情况，但该时间段，无dump到异常信息，无法进一步确认

图12 grep命令过滤日志

2024-01-14 15:03:29 dump出了system_server进程，该时间段，系统主线程未阻塞，但时间点比较晚了，参考作用不大


图13 anr.log system_server进程信息

操作路径复现：

在event.log中，搜索 am_anr | input_focus

图14 event.log过滤am_anr | input_focus

启动PayActivity，可通过adb shell am start -n om.google.android.gms/com.google.android.gms.pay.main.PayActivity启动，其实就是钱包应用
-》
Line 43257: 01-14 14:18:06.081949 1169 1192 I input_focus: [Focus request 46f3a8f com.google.android.gms/com.google.android.gms.pay.main.PayActivity,reason=UpdateInputWindows]
Line 43261: 01-14 14:18:06.121690 1169 2080 I input_focus: [Focus entering 46f3a8f com.google.android.gms/com.google.android.gms.pay.main.PayActivity (server),reason=Window became focusable. Previous reason: NOT_VISIBLE]
Line 43265: 01-14 14:18:07.297049 1169 2080 I input_focus: [Focus leaving 46f3a8f com.google.android.gms/com.google.android.gms.pay.main.PayActivity (server),reason=Waiting for window because NO_WINDOW]

进入输入法选择窗口，这个比较难找，可以用db shell "logcat -b all | grep NotificationShade"一边打印日志一边查看
-》
Line 43266: 01-14 14:18:07.329508 1169 2080 I input_focus: [Focus entering 2937c1e Select input method (server),reason=Window became focusable. Previous reason: NOT_VISIBLE]
Line 43284: 01-14 14:18:07.868308 1169 2080 I input_focus: [Focus leaving 2937c1e Select input method (server),reason=NO_WINDOW]

焦点进入input_focus: [Focus entering 2937c1e Select input method (server),reason=Window became focusable. Previous reason: NOT_VISIBLE]
后
离开input_focus: [Focus leaving 2937c1e Select input method (server),reason=NO_WINDOW]后，没有回到input_focus: [Focus entering 46f3a8f com.google.android.gms/com.google.android.gms.pay.main.PayActivity (server),reason=Window became focusable. Previous reason: NOT_VISIBLE]，此时系统是没有焦点窗口状态的。后续直接发生了anr。
所以需要看Focus entering 2937c1e Select input method 到 Focus leaving 2937c1e Select input method中间过程发生了什么（一般退出与进入间隔很短）：

图15 event.log

可以看到中间是gms.ui进程挂掉，然后PayActivity应用被结束了。

总结

1.启动PayActivity，应用内找到能调用出输入法的窗口（其他能调出输入法的应用都可）

图16 启动PayActivity

2.切换到选择输入法窗口

图17 切换到选择输入法窗口

3.后台杀死gms进程：adb shell am force-stop com.google.android.gms、间接移除PayActivity

图18 ADB命令杀死gms进程

4.然后再按音量键或者是导航栏的返回键，发生key事件派发，此时系统就会因为找不到焦点窗口，超过5秒，发生anr。
对应的界面是下面这个，点击返回键和音量键都没有反应：


图19 system anr

正常来说，应用被杀后，焦点会回到上一个应用，比如回到launcher中，是不会发生 system anr 的。而现在的特殊性在于，目前焦点所在的窗口不是在被杀应用中，而是在系统的select input method中，应用被杀导致退出这个select input method系统窗口后系统焦点无法回到上一个应用中（这个是原生问题、刷谷歌GSI机器也会）

而这里应用被杀也不是因为低内存等原因，是应用自身发生异常导致的，日志是：
可以看到下标越界，但是下标是gms服务com.google.android.gms.ui调用过来的，无法处理
01-14 14:18:07.702106 9294 9294 I DeviceDrDatabaseHelper: Cleaning stale data from database!
01-14 14:18:07.709448 9294 9294 W DeviceDoctorHandler: Crash Hash: 3faa6f5f1d9e4ad5f499f62d4fae0c1acc6eaed8
01-14 14:18:07.709889 9294 9294 W DeviceDoctorHandler: Shushing crash.
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: FATAL EXCEPTION: main
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: Process: com.google.android.gms.ui, PID: 9294
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: java.lang.IndexOutOfBoundsException: Index -1 out of bounds for length 0
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:64)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at jdk.internal.util.Preconditions.outOfBoundsCheckIndex(Preconditions.java:70)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at jdk.internal.util.Preconditions.checkIndex(Preconditions.java:266)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at java.util.Objects.checkIndex(Objects.java:359)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at java.util.ArrayList.get(ArrayList.java:434)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at java.util.Collections$UnmodifiableList.get(Collections.java:1394)01-1414:18:07.70999992949294EDeviceDoctorHandler:atlk.c(:com.google.android.gms@234914038@23.49.14(190400-590296185):5)01-1414:18:07.70999992949294EDeviceDoctorHandler:atbzvj.dz(:com.google.android.gms@234914038@23.49.14(190400-590296185):1)01-1414:18:07.70999992949294EDeviceDoctorHandler:atbzum.b(:com.google.android.gms@234914038@23.49.14(190400-590296185):77)01-1414:18:07.70999992949294EDeviceDoctorHandler:atandroid.support.v7.widget.RecyclerView.ap(:com.google.android.gms@234914038@23.49.14(190400-590296185):48)01-1414:18:07.70999992949294EDeviceDoctorHandler:atvd.run(:com.google.android.gms@234914038@23.49.14(190400-590296185):482)01-1414:18:07.70999992949294EDeviceDoctorHandler:atandroid.view.Choreographer$CallbackRecord.run(Choreographer.java:1473)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at android.view.Choreographer$CallbackRecord.run(Choreographer.java:1482)01-1414:18:07.70999992949294EDeviceDoctorHandler:atandroid.view.Choreographer.doCallbacks(Choreographer.java:1056)01-1414:18:07.70999992949294EDeviceDoctorHandler:atandroid.view.Choreographer.doFrame(Choreographer.java:946)01-1414:18:07.70999992949294EDeviceDoctorHandler:atandroid.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:1456)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at android.os.Handler.handleCallback(Handler.java:958)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at android.os.Handler.dispatchMessage(Handler.java:99)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at android.os.Looper.loopOnce(Looper.java:205)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at android.os.Looper.loop(Looper.java:294)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at android.app.ActivityThread.main(ActivityThread.java:8225)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at java.lang.reflect.Method.invoke(Native Method)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:573)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1049)
01-14 14:18:07.709999 9294 9294 E DeviceDoctorHandler:
01-14 14:18:07.735537 9294 9294 I Process : Sending signal. PID: 9294 SIG: 9

01-14 14:18:07.788411 1169 4310 I ImeTracker: com.google.android.gms:d7313c9d: onRequestHide at ORIGIN_SERVER_HIDE_INPUT reason HIDE_REMOVE_CLIENT

01-14 14:18:07.789308 1169 2884 W InputManager-JNI: Input channel object ‘46f3a8f com.google.android.gms/com.google.android.gms.pay.main.PayActivity (client)’ was disposed without first being removed with the input manager!
01-14 14:18:07.790767 1169 1203 I libprocessgroup: Successfully killed process cgroup uid 10095 pid 9294 in 1ms
01-14 14:18:07.790845 706 706 I Zygote : Process 9294 exited due to signal 9 (Killed)

解决方法

规避方案：可以在frameworks层进行规避。在弹出输入法的时候，隐藏系统提供的“选择输入法的弹窗”，应用入口提供的选择输入法不受影响

图20 规避方案修改代码

四、效果评价

通过上面的修改，继续按照之前的操作路径去复现，结果是不会出现对应的必现anr了。最后合入解决了Monkey测试中大量的systemui anr、system anr。并且修改经测试也不影响其他功能。

五、亮点提取与推广建议

提供了一个根据event.log日志恢复操作场景，复现anr的方法，此后处理ANR问题且无从下手时，可以通过这个方法寻找突破口去分析，如果能复现出来就很好解决了，通过在代码中加日志来找到原因，最后根据情况选择解决或者规避。

                                                                                                                       —— 完  ——