Bug #113739
测试 Test-ST #113421: V4.0功能与专项测试
测试 Test-ST #113422: V4.0专项--AF专项--monkey测试
【AF】【EVT2】【Monkey】Monkey测试60小时,出现ANR:system
Status: | CLOSED | Start date: | 2022-11-07 | |
---|---|---|---|---|
Priority: | Normal | Due date: | ||
Assignee: | CD FW-鲁凯峰 | % Done: | 100% | |
Category: | CD-FW | |||
Target version: | VX1_MCE_FSE_V5.0_20221230 | |||
Need_Info: | -- | Found Version: | FlatBuild_HH_VX1_MCE_FSE.M.D.userdebug.01.00.X101.202211040244 | |
Resolution: | WONTFIX | Degrated: | -- | |
Severity: | Normal | Verified Version: | ||
Reproducibility: | Frequently | Fixed Version: | ||
Test Type: | Monkey Test | Root cause: |
Description
执行命令:
adb shell
monkey --pkg-blacklist-file /sdcard/blacklist.txt --ignore-crashes --ignore-timeouts --ignore-security-exceptions --monitor-native-crashes --ignore-native-crashes -s 20 --throttle 200 --pct-touch 30 --pct-motion 15 --pct-nav 15 --pct-majornav 15 --pct-syskeys 5 --pct-appswitch 10 --pct-anyevent 10 --ignore-crashes -v -v -v 1080000 2>/sdcard/error.txt 1>/sdcard/info.txt
错误日志:
// NOT RESPONDING: system (pid 1136) ANR in system PID: 1136 Reason: Input dispatching timed out (PointerEventDispatcher0 (server) is not responding. Waited 5005ms for MotionEvent(deviceId=-1, eventTime=72768085000000, source=0x00001002, displayId=0, action=DOWN, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, classification=NONE, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, xCursorPosition=nan, yCursorPosition=nan, pointers=[0: (2135.0, 538.0)]), policyFlags=0x6b000000) ErrorId: ee4a11fe-0824-464d-8ded-78064111246d Frozen: false Load: 6.74 / 9.73 / 10.48 ----- Output from /proc/pressure/memory ----- some avg10=0.00 avg60=0.00 avg300=0.00 total=6308181 full avg10=0.00 avg60=0.00 avg300=0.00 total=2723761 ----- End output from /proc/pressure/memory ----- CPU usage from 0ms to 24309ms later (2022-11-04 21:23:08.567 to 2022-11-04 21:23:32.877): 82% 24997/com.qualcomm.qti.usta: 80% user + 1.8% kernel / faults: 910 minor 74% 1247/tlog: 2.7% user + 71% kernel / faults: 4 minor 72% 7232/tlog: 2.7% user + 70% kernel / faults: 3 minor 72% 1053/sensors.qti: 15% user + 57% kernel 63% 2020/com.android.systemui: 48% user + 15% kernel / faults: 17427 minor 61% 1136/system_server: 19% user + 41% kernel / faults: 101976 minor 49% 1039/surfaceflinger: 23% user + 25% kernel / faults: 3230 minor 33% 960/vendor.qti.hardware.display.composer-service: 11% user + 22% kernel / faults: 796 minor 21% 1335/media.codec: 4.6% user + 17% kernel / faults: 8895 minor 20% 8463/com.microsoft.emmx: 7.7% user + 12% kernel / faults: 24236 minor 1 major 2.6% 1555/llkd: 0.2% user + 2.4% kernel ...
【日志】
Tlog和ANR日志见Bug #113491 附件
History
#2 Updated by CD Test赵飞 over 2 years ago
Log已传至FTP
ftp://cdiot@192.168.87.46/Pre_figure/Test_Log/Bug _113491/Tlog&ANR.zip
#3 Updated by CD FW-鲁凯峰 over 2 years ago
- Status changed from New to RESOLVED
- Assignee changed from CD FW-鲁凯峰 to CD Test赵飞
- Resolution changed from -- to WONTFIX
■ Current conclusion
在最新的monkey测试中,没有出现该anr了
■ My analysis
从日志看, system_server的anr发生在21:23:11,原因是Input事件没有在5s内响应.
----- pid 1136 at 2022-11-04 21:23:11.587288660+0800 -----
Cmd line: system_server
结合前后21:23:11的前后日志分析
在发生ANR之前是要启动QuickstepLauncher
11-04 21:23:02.755 7497 7497 I wm_on_restart_called: [211429863,com.android.launcher3.uioverrides.QuickstepLauncher,performRestartActivity]
11-04 21:23:02.755 7497 7497 I wm_on_start_called: [211429863,com.android.launcher3.uioverrides.QuickstepLauncher,handleStartActivity]
11-04 21:23:02.757 7497 7497 I wm_on_resume_called: [211429863,com.android.launcher3.uioverrides.QuickstepLauncher,RESUME_ACTIVITY]
QuickstepLauncher开始请求焦点
11-04 21:23:02.787 1136 1213 I input_focus: [Focus request 8795ff6 com.android.launcher3/com.android.launcher3.uioverrides.QuickstepLauncher,reason=UpdateInputWindows]
Monkey发生Touch事件
11-04 21:23:02.883 7301 7301 I Monkey : :Sending Touch (ACTION_UP): 0:(2137.013,523.9981)
11-04 21:23:02.881 7301 7301 I Monkey : :Sending Touch (ACTION_DOWN): 0:(2135.0,538.0)
但是这个时候QuickstepLauncher还没有获取到焦点
11-04 21:23:03.088 1136 1706 W InputDispatcher: Waiting because no window has focus but ActivityRecord{c9a29e7 u0 com.android.launcher3/.uioverrides.QuickstepLauncher t8} may eventually add a window when it finishes starting up. Will wait for 5000ms
QuickstepLauncher启动5s后还是没有获取焦点,所以Input event被废弃了
11-04 21:23:07.887 1136 1706 I InputDispatcher: Dropped event because of pending overdue app switch.
11-04 21:23:07.889 1136 1706 W InputDispatcher: Monitor PointerEventDispatcher0 (server) is unresponsive: PointerEventDispatcher0 (server) is not responding. Waited 5005ms for MotionEvent(deviceId=-1, eventTime=72768085000000, source=0x00001002, displayId=0, action=DOWN, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, classification=NONE, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, xCursorPosition=nan, yCursorPosition=nan, pointers=[0: (2135.0, 538.0)]), policyFlags=0x6b000000
11-04 21:23:07.889 1136 1706 W InputDispatcher: Canceling events for PointerEventDispatcher0 (server) because it is unresponsive
11-04 21:23:07.891 1136 1164 W InputManager: Input event injection from pid 7301 failed.
目前看起来有点像是QuickstepLauncher启动超时导致的,但是在最新的版本上跑monkey时,没有发生该anr了,所以建议先观察几个版本在看看
■ Next Action
在多观察3个版本,不复现后关闭
#4 Updated by CD Test赵飞 over 2 years ago
- % Done changed from 0 to 70
11月10号Release版本未复现此问题
Monkey问题,继续跟踪2个版本
#5 Updated by CD Test赵飞 over 2 years ago
- Status changed from RESOLVED to ASSIGNED
- Assignee changed from CD Test赵飞 to CD FW-鲁凯峰
- % Done changed from 70 to 40
11月11号DB版本执行Monkey测试60小时,复现此问题1次
错误信息:
// NOT RESPONDING: system (pid 1123) ANR in system PID: 1123 Reason: Input dispatching timed out (PointerEventDispatcher0 (server) is not responding. Waited 5895ms for KeyEvent(deviceId=-1, eventTime=25349485000000, source=0x00000101, displayId=-1, action=DOWN, flags=0x00000008, keyCode=24, scanCode=0, metaState=0x00000000, repeatCount=0), policyFlags=0x6b000000) ErrorId: db37c80d-cb7c-4a1b-b3c3-af80f29f03ec Frozen: false Load: 5.66 / 6.18 / 5.79 ----- Output from /proc/pressure/memory ----- some avg10=0.01 avg60=0.02 avg300=0.00 total=4063417 full avg10=0.00 avg60=0.00 avg300=0.00 total=1975442 ----- End output from /proc/pressure/memory ----- CPU usage from 235ms to -17055ms ago (2022-11-11 11:49:00.783 to 2022-11-11 11:49:18.074): 93% 1058/sensors.qti: 19% user + 73% kernel 48% 1123/system_server: 14% user + 34% kernel / faults: 63073 minor 45% 2004/com.android.systemui: 32% user + 13% kernel / faults: 9555 minor 37% 1232/tlog: 1.8% user + 35% kernel / faults: 1 minor 34% 4797/tlog: 1.6% user + 33% kernel / faults: 1 minor 25% 956/vendor.qti.hardware.display.composer-service: 7.7% user + 17% kernel / faults: 604 minor 22% 1047/surfaceflinger: 9.5% user + 12% kernel / faults: 2672 minor 3% 1329/media.codec: 1.2% user + 1.8% kernel / faults: 22526 minor 8.7% 1403/media.swcodec: 1.7% user + 6.9% kernel / faults: 11143 minor 7% 4090/com.thundercomm.gamemode: 3.5% user + 3.4% kernel / faults: 4105 minor 6.3% 2595/com.android.launcher3: 3% user + 3.2% kernel / faults: 2431 minor ...
日志已传至FTP:
ftp://cdiot@192.168.87.46/Pre_figure/Test_Log/Bug_113739/Tlog&ANR.zip
#6 Updated by CD FW 曹覃刚 over 2 years ago
UserDebug版本运行Monkey跑出的问题,将在user版本上跑三个版本观察,如果不再复现,我们将关闭这个问题
#7 Updated by CD Test赵飞 over 2 years ago
11月15号Release版本(user)未复现此问题
继续跟踪2个版本
#8 Updated by CDTS-TEST 周婷 over 2 years ago
- Due date deleted (
2022-11-14) - Target version changed from VX1_MCE_FSE_V3.0_update_20221130 to VX1_MCE_FSE_V5.0_20221230
#9 Updated by CD Test赵飞 over 2 years ago
- Status changed from ASSIGNED to RESOLVED
- % Done changed from 40 to 80
11月16号DB版本(user)和11月17号Release版本(user)均未复现此问题
暂时关闭此问题
#10 Updated by CD Test赵飞 over 2 years ago
- Status changed from RESOLVED to VERIFIED
#11 Updated by CD Test赵飞 over 2 years ago
- Status changed from VERIFIED to CLOSED
- % Done changed from 80 to 100