Bug #113739

测试 Test-ST #113421: V4.0功能与专项测试

测试 Test-ST #113422: V4.0专项--AF专项--monkey测试

【AF】【EVT2】【Monkey】Monkey测试60小时,出现ANR:system

Added by CD Test赵飞 over 2 years ago. Updated over 2 years ago.

Status:CLOSEDStart date:2022-11-07
Priority:NormalDue 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

#1 Updated by CD FW 曹覃刚 over 2 years ago

  • Assignee changed from CD FW 曹覃刚 to CD FW-鲁凯峰

请帮忙分析下这个问题

#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

Also available in: Atom PDF