Bug #116438

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

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

【AF】【EVT3】【Monkey】Monkey测试12小时，出现ANR: com.android.systemui（1）

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

Status:CLOSEDStart date:2023-02-22
Priority:NormalDue date:
Assignee:CD TEST-方永红% Done:

0%

Category:BSP
Target version:VC1_FSE_0082_20230314
Need_Info:-- Found Version:FlatBuild_HH_VX1_MCE_FSE.M.D.user.01.00.X101.202302180012
Resolution:INVALID Degrated:--
Severity:Normal Verified Version:FlatBuild_HH_MCE_FSE.M.R.user.01.00.0083.C101(X101)
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 500 --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 86400 2>/sdcard/error.txt 1>/sdcard/info.txt

【错误信息】

// NOT RESPONDING: com.android.systemui (pid 1979)
ANR in com.android.systemui
PID: 1979
Reason: Input dispatching timed out (f52c3ef NavigationBar0 (server) is not responding. Waited 5001ms for MotionEvent)
Frozen: false
Load: 1.6 / 1.76 / 1.76
----- Output from /proc/pressure/memory -----
some avg10=0.00 avg60=0.00 avg300=0.00 total=610604
full avg10=0.00 avg60=0.00 avg300=0.00 total=229412
----- End output from /proc/pressure/memory -----

CPU usage from 131218ms to 0ms ago (2023-02-18 19:19:35.217 to 2023-02-18 19:21:46.436):
  20% 990/surfaceflinger: 15% user + 5.4% kernel / faults: 1354 minor
  14% 861/vendor.qti.hardware.display.composer-service: 9.4% user + 5.2% kernel / faults: 449 minor
  10% 1514/system_server: 6.7% user + 3.5% kernel / faults: 261929 minor
  8.1% 1979/com.android.systemui: 6.8% user + 1.2% kernel / faults: 20437 minor
  7.6% 1209/media.codec: 2.8% user + 4.7% kernel / faults: 88 minor
  4.7% 22878/com.android.settings: 3.7% user + 1% kernel / faults: 31631 minor
  3.5% 17314/app_process: 2% user + 1.4% kernel / faults: 203 minor
  2.3% 2553/com.android.launcher3: 1.6% user + 0.7% kernel / faults: 7667 minor
  2% 2699/adbd: 0.7% user + 1.3% kernel
  1.4% 287/kgsl_worker_thr: 0% user + 1.4% kernel
  1.3% 28509/kworker/u16:2-kgsl-mementry: 0% user + 1.3% kernel
  1.2% 504/logd: 0.2% user + 0.9% kernel / faults: 645 minor
  1.1% 715/crtc_commit:125: 0% user + 1.1% kernel
  1% 23561/kworker/u16:18-adb: 0% user + 1% kernel
...

【日志】
ftp://cdiot@192.168.87.46/Pre_figure/Test_Log/Bug_116416/Tlog.zip

Related issues

Related to Figure - Bug #116439: 【AF】【EVT3】【Monkey】Monkey测试12小时，出现ANR: com.android.systemu... CLOSED 2023-02-22 2023-03-14

History

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

  • Category changed from CD-FW to AUDIO-FW
  • Status changed from New to ASSIGNED
  • Assignee changed from CD FW 曹覃刚 to CD BSP何伟

Hi 何伟
■ 我的分析
通过检查问题发生时的日志, 在ANR发生前几秒，都存在下列异常
02-18 19:21:44.100 6429 6429 F DEBUG : *
02-18 19:21:44.100 6429 6429 F DEBUG : Build fingerprint: 'TC/figure_CN/figure:12/SKQ1.220201.001/2134:user/test-keys'
02-18 19:21:44.100 6429 6429 F DEBUG : Revision: '0'
02-18 19:21:44.100 6429 6429 F DEBUG : ABI: 'arm'
02-18 19:21:44.100 6429 6429 F DEBUG : Timestamp: 2023-02-18 19:21:44.057191101+0800
02-18 19:21:44.100 6429 6429 F DEBUG : Process uptime: 0s
02-18 19:21:44.100 6429 6429 F DEBUG : Cmdline: /vendor/bin/hw/android.hardware.audio.service
02-18 19:21:44.100 6429 6429 F DEBUG : pid: 675, tid: 675, name: audio.service >>> /vendor/bin/hw/android.hardware.audio.service <<<
02-18 19:21:44.100 6429 6429 F DEBUG : uid: 1041
02-18 19:21:44.100 6429 6429 F DEBUG : signal 35 (<debuggerd signal>), code 1 (SI_QUEUE from pid 814, uid 1041), fault addr -------
02-18 19:21:44.100 6429 6429 F DEBUG : r0 00000004 r1 c0306201 r2 ff8c26a8 r3 ff8c25fc
02-18 19:21:44.100 6429 6429 F DEBUG : r4 ddc61a53 r5 ef85a138 r6 ff8c26a8 r7 00000036
02-18 19:21:44.100 6429 6429 F DEBUG : r8 00000000 r9 ef001b64 r10 ff8c26b8 r11 ff8c26a8
02-18 19:21:44.100 6429 6429 F DEBUG : ip 00000100 sp ff8c25e0 lr ef8082cb pc ef83a5a8
02-18 19:21:44.100 6429 6429 F DEBUG : backtrace:
02-18 19:21:44.100 6429 6429 F DEBUG : #00 pc 000715a8 /apex/com.android.runtime/lib/bionic/libc.so (_ioctl+8) (BuildId: cc194ef76ee932851b23cc2e4f46d55f)
02-18 19:21:44.100 6429 6429 F DEBUG : #01 pc 0003f2c7 /apex/com.android.runtime/lib/bionic/libc.so (ioctl+26) (BuildId: cc194ef76ee932851b23cc2e4f46d55f)
02-18 19:21:44.100 6429 6429 F DEBUG : #02 pc 0005ff09 /apex/com.android.vndk.v30/lib/libhidlbase.so (android::hardware::IPCThreadState::getAndExecuteCommand()+160) (BuildId: ae84f31d0a55afdbe06ed13729dae8a2)
02-18 19:21:44.100 6429 6429 F DEBUG : #03 pc 0006100d /apex/com.android.vndk.v30/lib/libhidlbase.so (android::hardware::IPCThreadState::joinThreadPool(bool)+56) (BuildId: ae84f31d0a55afdbe06ed13729dae8a2)
02-18 19:21:44.100 6429 6429 F DEBUG : #04 pc 000026b5 /vendor/bin/hw/android.hardware.audio.service (main+2564) (BuildId: b5ba2845ffd2ad1c80c85239344b8c71)
02-18 19:21:44.101 6429 6429 F DEBUG : #05 pc 0003248b /apex/com.android.runtime/lib/bionic/libc.so (_libc_init+54) (BuildId: cc194ef76ee932851b23cc2e4f46d55f)
02-18 19:21:44.959 6435 6435 F DEBUG :
02-18 19:21:44.959 6435 6435 F DEBUG : Build fingerprint: 'TC/figure_CN/figure:12/SKQ1.220201.001/2134:user/test-keys'
02-18 19:21:44.959 6435 6435 F DEBUG : Revision: '0'
02-18 19:21:44.959 6435 6435 F DEBUG : ABI: 'arm64'
02-18 19:21:44.959 6435 6435 F DEBUG : Timestamp: 2023-02-18 19:21:44.885273288+0800
02-18 19:21:44.959 6435 6435 F DEBUG : Process uptime: 0s
02-18 19:21:44.959 6435 6435 F DEBUG : Cmdline: /system/bin/audioserver
02-18 19:21:44.959 6435 6435 F DEBUG : pid: 814, tid: 837, name: TimeCheckThread >>> /system/bin/audioserver <<<
02-18 19:21:44.959 6435 6435 F DEBUG : uid: 1041
02-18 19:21:44.960 6435 6435 F DEBUG : signal 6 (SIGABRT), code 1 (SI_QUEUE), fault addr -------
02-18 19:21:44.960 6435 6435 F DEBUG : Abort message: 'TimeCheck timeout for IAudioFlinger command 37'
02-18 19:21:44.960 6435 6435 F DEBUG : x0 0000000000000000 x1 0000000000000345 x2 0000000000000006 x3 000000706b121530
02-18 19:21:44.960 6435 6435 F DEBUG : x4 6d686b456e686374 x5 6d686b456e686374 x6 6d686b456e686374 x7 7f7f7f7f7f7f7f7f
02-18 19:21:44.960 6435 6435 F DEBUG : x8 00000000000000f0 x9 6f435ef1c1655d16 x10 0000000000000000 x11 ffffff80ffffffdf
02-18 19:21:44.960 6435 6435 F DEBUG : x12 0000000000000001 x13 000000000000002f x14 000000706b1216c0 x15 0000000034155555
02-18 19:21:44.960 6435 6435 F DEBUG : x16 00000073aaed3060 x17 00000073aaeaf560 x18 000000706a588000 x19 000000000000032e
02-18 19:21:44.960 6435 6435 F DEBUG : x20 0000000000000345 x21 00000000ffffffff x22 b4000070b59eead0 x23 b4000070959e44b4
02-18 19:21:44.960 6435 6435 F DEBUG : x24 b4000070959e44b4 x25 000000706b121cb0 x26 000000706b121ff8 x27 00000000000fc000
02-18 19:21:44.960 6435 6435 F DEBUG : x28 000000706b029000 x29 000000706b1215b0
02-18 19:21:44.960 6435 6435 F DEBUG : lr 00000073aae5f95c sp 000000706b121510 pc 00000073aae5f988 pst 0000000000001000
02-18 19:21:44.960 6435 6435 F DEBUG : backtrace:
02-18 19:21:44.960 6435 6435 F DEBUG : #00 pc 0000000000051988 /apex/com.android.runtime/lib64/bionic/libc.so (abort+168) (BuildId: 369edc656806aeaf384cbeb8f7a347af)
02-18 19:21:44.960 6435 6435 F DEBUG : #01 pc 00000000000063b8 /system/lib64/liblog.so (_android_log_default_aborter+16) (BuildId: 467c2038cdfa767245f9280e657fdb85)
02-18 19:21:44.960 6435 6435 F DEBUG : #02 pc 0000000000006f14 /system/lib64/liblog.so (_android_log_assert+312) (BuildId: 467c2038cdfa767245f9280e657fdb85)
02-18 19:21:44.960 6435 6435 F DEBUG : #03 pc 0000000000035294 /system/lib64/libmediautils.so (android::TimeCheck::TimeCheckThread::threadLoop()+908) (BuildId: d1ac2ddd5dabaddcca37691821970832)
02-18 19:21:44.960 6435 6435 F DEBUG : #04 pc 0000000000013654 /system/lib64/libutils.so (android::Thread::_threadLoop(void)+464) (BuildId: b940f836006eead456c936e97e64d2d4)
02-18 19:21:44.960 6435 6435 F DEBUG : #05 pc 0000000000012de8 /system/lib64/libutils.so (thread_data_t::trampoline(thread_data_t const*)+408) (BuildId: b940f836006eead456c936e97e64d2d4)
02-18 19:21:44.960 6435 6435 F DEBUG : #06 pc 00000000000b6a24 /apex/com.android.runtime/lib64/bionic/libc.so (_pthread_start(void*)+264) (BuildId: 369edc656806aeaf384cbeb8f7a347af)
02-18 19:21:44.960 6435 6435 F DEBUG : #07 pc 00000000000532bc /apex/com.android.runtime/lib64/bionic/libc.so (_start_thread+68) (BuildId: 369edc656806aeaf384cbeb8f7a347af)
02-18 19:21:44.993 1195 3379 W AudioSystem: AudioPolicyService server died!
02-18 19:21:44.993 1979 2601 W AudioSystem: AudioPolicyService server died!
02-18 19:21:44.993 1195 3379 W AudioSystem: AudioFlinger server died!
02-18 19:21:44.993 1979 2601 E AudioSystem-JNI: Command failed for android_media_AudioSystem_error_callback: -32
02-18 19:21:44.993 1979 2601 W AudioSystem: AudioFlinger server died!
02-18 19:21:44.993 1514 5504 W AudioSystem: AudioPolicyService server died!
02-18 19:21:44.993 22952 29375 W AudioSystem: AudioPolicyService server died!
02-18 19:21:44.993 1514 5504 W CaptureStateTracker: Audio policy service died
02-18 19:21:44.994 1514 5504 W AudioSystem: AudioPolicyService server died!
02-18 19:21:44.994 22878 28148 W AudioSystem: AudioPolicyService server died!
02-18 19:21:44.994 1514 5504 W AudioSystem: AudioPolicyService server died!
02-18 19:21:44.994 22952 29375 E AudioSystem-JNI: Command failed for android_media_AudioSystem_error_callback: -32
02-18 19:21:44.994 22952 29375 W AudioSystem: AudioFlinger server died!
02-18 19:21:44.994 22878 28148 E AudioSystem-JNI: Command failed for android_media_AudioSystem_error_callback: -32
02-18 19:21:44.994 1514 4746 E AudioSystem-JNI: Command failed for android_media_AudioSystem_error_callback: -32
02-18 19:21:44.994 22878 28148 W AudioSystem: AudioFlinger server died!
02-18 19:21:44.994 1514 4746 W AudioSystem: AudioFlinger server died!
02-18 19:21:44.994 6017 6164 E AudioSystem-JNI: Command failed for android_media_AudioSystem_error_callback: -32
01-01 16:02:30.405 0 0 I binder : release 814:836 transaction 8581901 in, still active
02-18 19:21:44.994 1514 1795 E AudioSystem-JNI: Command failed for android_media_AudioSystem_setStreamVolumeIndex: -32

发生ANR前五秒均存在"android.hardware.audio.service"异常
02-18 19:21:44.100 发生"android.hardware.audio.service"异常
02-18 19:21:50.070 1514 6448 E ActivityManager: ANR in com.android.systemui
02-18 19:21:50.070 1514 6448 E ActivityManager: Reason: Input dispatching timed out (f52c3ef NavigationBar0 (server) is not responding. Waited 5001ms for MotionEvent)
02-18 21:10:16.948 发生"android.hardware.audio.service"异常
02-18 21:10:21.506 1514 4000 E ActivityManager: ANR in com.android.systemui:screenshot
02-18 21:10:21.506 1514 4000 E ActivityManager: Reason: Input dispatching timed out (a5ca2d6 ScreenshotAnimation (server) is not responding. Waited 5000ms for FocusEvent(hasFocus=true))

ANR原因都是超时未响应，且等待响应的时间为5秒，与发生"android.hardware.audio.service"异常的时间相呼应
发生ANR的原因似乎是由该异常引起

■ 下一步解析计划
请Audio的同学帮忙分析一下，"android.hardware.audio.service"异常发生的原因, 非常感谢

#2 Updated by CD TPM-王祥林 over 2 years ago

  • Assignee changed from CD BSP何伟 to CD MM唐驭俊

#3 Updated by CD TPM-王祥林 over 2 years ago

  • Target version set to VC1_FSE_0082_20230314

#4 Updated by CD TPM-王祥林 over 2 years ago

  • Assignee changed from CD MM唐驭俊 to Multimedia组-RD3_TSCD 梁卿山

#5 Updated by Multimedia组-RD3_TSCD 梁卿山 over 2 years ago

  • Assignee changed from Multimedia组-RD3_TSCD 梁卿山 to CD BSP何伟

Hi ALL,
■ 我的分析
当前分析到在ANR出现前，android.hardware.audio.service出现了异常，根据以下日志判断，问题可能和驱动层有关。
//19：21
310:02-18 19:21:33.316 675 1228 E audio_hw_primary: out_write: error -5, cannot write stream data: I/O error ★★★
312:02-18 19:21:33.316 675 1228 D audio_hw_primary: out_standby: enter: stream (0xeb804330) usecase(1: low-latency-playback)
...
1668:02-18 19:21:43.812 675 1228 E audio_hw_primary: out_write: error -5, cannot write stream data: I/O error ★★★
1669:02-18 19:21:43.812 675 1228 D audio_hw_primary: out_standby: enter: stream (0xeb804330) usecase(1: low-latency-playback)
...
1671:02-18 19:21:43.827 675 675 I libc : Requested dump for tid 675 (audio.service)
1688:02-18 19:21:44.045 6429 6429 I crash_dump32: performing dump of process 675 (target tid = 675)
1929:01-01 16:02:30.417 0 0 I libprocessgroup: Successfully killed process cgroup uid 1041 pid 675 in 6ms

//21:10
226:02-18 21:10:00.068 30308 30400 E audio_hw_primary: out_write: error -5, cannot write stream data: I/O error ★★★
227:02-18 21:10:00.068 30308 30400 D audio_hw_primary: out_standby: enter: stream (0xe94464c0) usecase(1: low-latency-playback)
...
820:02-18 21:10:10.564 30308 30400 E audio_hw_primary: out_write: error -5, cannot write stream data: I/O error ★★★
821:02-18 21:10:10.564 30308 30400 D audio_hw_primary: out_standby: enter: stream (0xe94464c0) usecase(1: low-latency-playback)
...
1130:02-18 21:10:16.836 30319 30329 I TimeCheck: requesting tombstone for pid: 30308
1131:02-18 21:10:16.837 30308 30308 I libc : Requested dump for tid 30308 (audio.service)
1138:02-18 21:10:16.890 3997 3997 I crash_dump32: performing dump of process 30308 (target tid = 30308)

在这部分日志输出后，就出现了audio相关服务died的信息。所以推测和驱动层相关。

■ 下一步解析计划
请Audio-BSP的同学帮忙分析一下，以上的错误日志出现的原因，谢谢

#6 Updated by CD TPM-王祥林 over 2 years ago

  • Assignee changed from CD BSP何伟 to CD BSP-唐金泽

#7 Updated by CD TPM-王祥林 over 2 years ago

  • Category changed from AUDIO-FW to BSP

#8 Updated by CD BSP-唐金泽 over 2 years ago

  • Status changed from ASSIGNED to NEED_INFO
  • Assignee changed from CD BSP-唐金泽 to CD TEST-方永红

Hi 永红，
应该和底层没有外接音频时钟有关系。
可以连接上中控台架再试一下吗？

#9 Updated by CD BSP-唐金泽 over 2 years ago

  • Status changed from NEED_INFO to RESOLVED
  • Assignee changed from CD TEST-方永红 to CDTS_TEST 王成
  • Resolution changed from -- to INVALID
  • Root cause set to 音频问题根本原因是底层没有音频时钟。 需要台架提供外部时钟源，底层音频数据才正常输出，不会造成数据阻塞

3.11版本Monkey测试结果如图，无新增Bug
Bug #116438 在连接中控的设备上暂未复现，在未连接中控的设备上复现

#10 Updated by CDTS_TEST 王成 over 2 years ago

  • Assignee changed from CDTS_TEST 王成 to CD TEST-方永红

#11 Updated by CD TEST-方永红 over 2 years ago

  • Status changed from RESOLVED to VERIFIED
  • Verified Version set to FlatBuild_HH_MCE_FSE.M.R.user.01.00.0083.C101(X101)

3.17
连接中控后测试
3个版本未复现
先关闭

#12 Updated by CD TEST-方永红 over 2 years ago

  • Status changed from VERIFIED to CLOSED

Also available in: Atom PDF