Bug #117821
【VC1】【内部】【0094】【台架】【EE环境】【副屏】系统无响应自动重启
| Status: | CLOSED | Start date: | 2023-05-18 | |
|---|---|---|---|---|
| Priority: | Normal | Due date: | ||
| Assignee: | CDTS_Test 吴诗雨 | % Done: | 100% | |
| Category: | AUDIO-FW | |||
| Target version: | - | |||
| Need_Info: | -- | Found Version: |
中控屏版本：03.02.0078.C101 副屏版本：01.00.0094.C103 |
|
| Resolution: | FIXED | Degrated: | No | |
| Severity: | Critical | Verified Version: | ||
| Reproducibility: | Every time | Fixed Version: | ||
| Test Type: | ST | Root cause: | 解决焦点更新时死锁问题 |
Description
【台架号】：
HRYTTESTVINMGM441
【环境信息】：EE环境
【测试时间】：2023.5.8 10:59
【前提条件】：1、网络正常
2、副屏上电
【操作步骤】
1、进入副屏
【实际结果】
1、系统无响应自动重启
【期待结果】
1、系统有响应
【备注】：
中控屏版本：03.02.0078.C101
副屏版本：01.00.0094.C103
日志链接：https://ofs.human-horizons.com/#/download/index/VKtZ21Xxkqo%3D
image-2023-05-08-13-29-56-540.png (626 KB)
Subtasks
History
#1 Updated by CDTS_Test 吴诗雨 about 2 years ago
tlog由于比较大，直接私发了
#2 Updated by CD FW 曹覃刚 about 2 years ago
- Category changed from CD-FW to AUDIO-FW
- Status changed from New to ASSIGNED
- Assignee changed from CD FW 曹覃刚 to Multimedia组-RD3_TSCD 梁卿山
Hi 卿山
■ 我的分析
从测试同学提供的日志中，有如下信息
1-11 00:15:04.420 1209 1550 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.Watchdog$BinderThreadMonitor on foreground thread (android.fg)
->这个时间点系统重启了，问题发生时，设备的整体负载情况良好
在发生问题的时间点前
有很多ANR, 与已知的monkey跑出来的audio相关anr相同，应该是连续的无响应异常导致的重启问题
在anr的文件中，检查到下面内容
-----------------------
主线程卡在abandonAudioFocus，与AudioService服务端通信
"main" prio=5 tid=1 Native
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x727f2978 self=0xb400007328b08be0
| sysTid=6461 nice=-10 cgrp=default sched=0/0 handle=0x74ee5094f8
| state=S schedstat=( 50026772211 15040668163 136093 ) utm=3803 stm=1199 core=6 HZ=100
| stack=0x7fed22c000-0x7fed22e000 stackSize=8188KB
| held mutexes=
native: #00 pc 00000000000a1c88 /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+8)
native: #01 pc 000000000005b8d4 /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
native: #02 pc 0000000000053070 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+292)
native: #03 pc 00000000000542ac /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+64)
native: #04 pc 0000000000053ff0 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+224)
native: #05 pc 000000000004bafc /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+196)
native: #06 pc 0000000000167664 /system/lib64/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+156)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(BinderProxy.java:571)
at android.media.IAudioService$Stub$Proxy.abandonAudioFocus(IAudioService.java:4412)
at android.media.AudioManager.abandonAudioFocus(AudioManager.java:4521)
at android.media.AudioManager.abandonAudioFocus(AudioManager.java:4502)
at com.tencent.qqlive.ona.player.c.a(unavailable:4)
at com.tencent.qqlive.ona.player.y2.abandonAudioFocus(unavailable:1)
at com.tencent.qqlive.ona.player.PlayerManager.onPageOutEvent(unavailable:4)
at java.lang.reflect.Method.invoke(Native method)
at cn4.d.invokeSubscriber(unavailable:7)
at cn4.d.postToSubscription(unavailable:10)
at cn4.d.postSingleEventForEventType(unavailable:15)
at cn4.d.postSingleEvent(unavailable:9)
at cn4.d.post(unavailable:15)
at com.tencent.qqlive.ona.player.PlayerManager.callPlayEvent(unavailable:6)
at com.tencent.qqlive.ona.player.PlayerManager.lambda$onError$14(unavailable:18)
at com.tencent.qqlive.ona.player.PlayerManager.a4(unavailable:-1)
at com.tencent.qqlive.ona.player.z0.run(R8$$SyntheticClass:-1)
at com.tencent.qqlive.apputils.AppUtils.postMain(unavailable:2)
然后在下面的通信线程中发生了死锁，看调用信息，都是在处理audio焦点相关
"Binder:1527_4" prio=5 tid=121 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x15086ae8 self=0xb400007328c1d210
| sysTid=1905 nice=-10 cgrp=default sched=0/0 handle=0x70afc71cb0
| state=S schedstat=( 811914740 750129709 6209 ) utm=52 stm=29 core=4 HZ=100
| stack=0x70afb7a000-0x70afb7c000 stackSize=991KB
| held mutexes=
at com.android.server.audio.MediaFocusControl.abandonAudioFocus(MediaFocusControl.java:1096)
- waiting to lock <0x0be017a1> (a java.lang.Object) held by thread 154
at com.android.server.audio.AudioService.abandonAudioFocus(AudioService.java:8424)
at android.media.IAudioService$Stub.onTransact(IAudioService.java:1899)
at android.os.Binder.execTransactInternal(Binder.java:1179)
at android.os.Binder.execTransact(Binder.java:1143)
"Binder:1527_2" prio=5 tid=10 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x15080418 self=0xb400007328b30b90
| sysTid=1564 nice=0 cgrp=default sched=0/0 handle=0x719bd76cb0
| state=S schedstat=( 1389229308 796836186 7957 ) utm=101 stm=37 core=2 HZ=100
| stack=0x719bc7f000-0x719bc81000 stackSize=991KB
| held mutexes=
at com.android.server.audio.AudioIDCMicroNegotiator$IDCMicroAudioFocusHandler.notifyFocusState(AudioIDCMicroNegotiator.java:484)
- waiting to lock <0x02898140> (a java.lang.Object) held by thread 98
at com.android.server.audio.AudioIDCMicroNegotiator$IDCMicroAudioFocusHandler.obtainFocusState(AudioIDCMicroNegotiator.java:474)
at com.android.server.audio.AudioIDCMicroNegotiator.requestIDCMicroAudioFocus(AudioIDCMicroNegotiator.java:621)
- locked <0x0ed255ab> (a java.lang.Object)
at com.android.server.audio.PlaybackActivityMonitor.requestAudioFocusToIDCM(PlaybackActivityMonitor.java:1227)
at com.android.server.audio.PlaybackActivityMonitor.playerEvent(PlaybackActivityMonitor.java:276)
- locked <0x02eac408> (a java.lang.Object)
at com.android.server.audio.AudioService.playerEvent(AudioService.java:9999)
at android.media.IAudioService$Stub.onTransact(IAudioService.java:1268)
at android.os.Binder.execTransactInternal(Binder.java:1184)
at android.os.Binder.execTransact(Binder.java:1143)
"Binder:1527_16" prio=5 tid=154 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x15088cb0 self=0xb400007328bee320
| sysTid=8226 nice=0 cgrp=default sched=0/0 handle=0x7109bb3cb0
| state=S schedstat=( 3449183777 604215017 7007 ) utm=235 stm=109 core=4 HZ=100
| stack=0x7109abc000-0x7109abe000 stackSize=991KB
| held mutexes=
at com.android.server.audio.PlaybackActivityMonitor.restoreVShapedPlayers(PlaybackActivityMonitor.java:629)
- waiting to lock <0x02eac408> (a java.lang.Object) held by thread 10
at com.android.server.audio.MediaFocusControl.restoreVShapedPlayers(MediaFocusControl.java:134)
at com.android.server.audio.FocusRequester.handleFocusGainFromRequest(FocusRequester.java:364)
at com.android.server.audio.MediaFocusControl.requestAudioFocus(MediaFocusControl.java:1048)
- locked <0x0be017a1> (a java.lang.Object)
at com.android.server.audio.AudioService.requestAudioFocus(AudioService.java:8388)
at android.media.IAudioService$Stub.onTransact(IAudioService.java:1878)
at android.os.Binder.execTransactInternal(Binder.java:1179)
at android.os.Binder.execTransact(Binder.java:1143)
"Thread-12" prio=5 tid=98 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x150857f0 self=0xb400007328bf5260
| sysTid=1801 nice=0 cgrp=default sched=0/0 handle=0x70c643fcb0
| state=S schedstat=( 23011156 16402650 145 ) utm=1 stm=1 core=2 HZ=100
| stack=0x70c633c000-0x70c633e000 stackSize=1039KB
| held mutexes=
at com.android.server.audio.MediaFocusControl.updateCurrentAudioFocus(MediaFocusControl.java:1309)
- waiting to lock <0x0be017a1> (a java.lang.Object) held by thread 154
at com.android.server.audio.AudioService$IDCMciroFeedback.onAudioFocusIDCMicroChanged(AudioService.java:10860)
at com.android.server.audio.PlaybackActivityMonitor$AudioIDCMicroRequestCallback.onAudioFocusRemoteChanged(PlaybackActivityMonitor.java:1156)
at com.android.server.audio.AudioIDCMicroNegotiator$IDCMicroAudioFocusHandler.run(AudioIDCMicroNegotiator.java:507)
- locked <0x02898140> (a java.lang.Object)
-----------------------
■ 下一步解析计划
audio的同学分析发生大量ANR的原因，应该与焦点的处理有关
#3 Updated by CDTS-TEST 周婷 about 2 years ago
- Severity changed from Normal to Critical
#4 Updated by CD SYSTEM-夏旭 about 2 years ago
初步分析是system_server死锁造成此问题，请 AF继续分析，死锁链分析如下
- [tid151-阻塞]---> [tid137阻塞]---->[98阻塞]--->[151-阻塞]
1.DeviceStorageMonitorService ConditionProviders.ECP 等线程都被thread 151给阻塞了
- waiting to lock <0x0cc89a1c> (a java.lang.Object) held by thread 151
- waiting to lock <0x0cc89a1c> (a java.lang.Object) held by thread 151
- waiting to lock <0x0cc89a1c> (a java.lang.Object) held by thread 151
- waiting to lock <0x0cc89a1c> (a java.lang.Object) held by thread 1512. 151 线程被98线程阻塞
"Binder:1209_F" prio=5 tid=151 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x139c9b58 self=0xb400007720f50260
| sysTid=7532 nice=0 cgrp=default sched=0/0 handle=0x74f7cf9cb0
| state=S schedstat=( 1362880693 648507301 18377 ) utm=71 stm=64 core=1 HZ=100
| stack=0x74f7c02000-0x74f7c04000 stackSize=991KB
| held mutexes=
at com.android.server.audio.AudioIDCMicroNegotiator$IDCMicroAudioFocusHandler.notifyFocusState(AudioIDCMicroNegotiator.java:484)
- waiting to lock <0x067d5c69> (a java.lang.Object) held by thread 983.98线程被137线程阻塞
"Thread-12" prio=5 tid=98 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x139c5ee8 self=0xb400007720f4aef0
| sysTid=1827 nice=0 cgrp=default sched=0/0 handle=0x74b6083cb0
| state=S schedstat=( 20335577 22557340 170 ) utm=0 stm=1 core=7 HZ=100
| stack=0x74b5f80000-0x74b5f82000 stackSize=1039KB
| held mutexes=
at com.android.server.audio.MediaFocusControl.updateCurrentAudioFocus(MediaFocusControl.java:1309)
- waiting to lock <0x0a3dc66d> (a java.lang.Object) held by thread 1374 137线线程被151线程阻塞，故死锁导致此问题发生
"Binder:1209_7" prio=5 tid=137 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x139c7e90 self=0xb400007720fa7100
| sysTid=2392 nice=0 cgrp=default sched=0/0 handle=0x7493116cb0
| state=S schedstat=( 1637324812 761089759 26416 ) utm=94 stm=69 core=4 HZ=100
| stack=0x749301f000-0x7493021000 stackSize=991KB
| held mutexes=
at com.android.server.audio.PlaybackActivityMonitor.restoreVShapedPlayers(PlaybackActivityMonitor.java:629)
- waiting to lock <0x0cc89a1c> (a java.lang.Object) held by thread 1515. 具体请下看附件中的anr_2022-11-11-00-14-57-323的文件#5 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
HI ALL
根据当前日志分析，确实发生了死锁，
Cmd line: com.microsoft.emmx
at android.media.IAudioService$Stub$Proxy.requestAudioFocus(IAudioService.java:4380)
↓
Cmd line: com.microsoft.emmx
at android.media.IAudioService$Stub$Proxy.requestAudioFocus(IAudioService.java:4380)
at android.media.AudioManager.requestAudioFocus(AudioManager.java:4280)
at android.media.AudioManager.requestAudioFocus(AudioManager.java:4165)
at android.media.AudioManager.requestAudioFocus(AudioManager.java:4091)
at android.media.AudioManager.requestAudioFocus(AudioManager.java:3958)
at org.chromium.content.browser.AudioFocusDelegate.requestAudioFocus(chromium-ChromePublic.apk-stable-134305015:80)
↓ーーーーーーーーーーーーー
"Binder:1527_2" prio=5 tid=10 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x15080418 self=0xb400007328b30b90
| sysTid=1564 nice=0 cgrp=default sched=0/0 handle=0x719bd76cb0
| state=S schedstat=( 1389229308 796836186 7957 ) utm=101 stm=37 core=2 HZ=100
| stack=0x719bc7f000-0x719bc81000 stackSize=991KB
| held mutexes=
at com.android.server.audio.AudioIDCMicroNegotiator$IDCMicroAudioFocusHandler.notifyFocusState(AudioIDCMicroNegotiator.java:484)
- waiting to lock <0x02898140> (a java.lang.Object) held by thread 98
at com.android.server.audio.AudioIDCMicroNegotiator$IDCMicroAudioFocusHandler.obtainFocusState(AudioIDCMicroNegotiator.java:474)
at com.android.server.audio.AudioIDCMicroNegotiator.requestIDCMicroAudioFocus(AudioIDCMicroNegotiator.java:621)
- locked <0x0ed255ab> (a java.lang.Object)
at com.android.server.audio.PlaybackActivityMonitor.requestAudioFocusToIDCM(PlaybackActivityMonitor.java:1227)
at com.android.server.audio.PlaybackActivityMonitor.playerEvent(PlaybackActivityMonitor.java:276)
- locked <0x02eac408> (a java.lang.Object)
at com.android.server.audio.AudioService.playerEvent(AudioService.java:9999)
at android.media.IAudioService$Stub.onTransact(IAudioService.java:1268)
at android.os.Binder.execTransactInternal(Binder.java:1184)
at android.os.Binder.execTransact(Binder.java:1143)
↓
"Thread-12" prio=5 tid=98 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x150857f0 self=0xb400007328bf5260
| sysTid=1801 nice=0 cgrp=default sched=0/0 handle=0x70c643fcb0
| state=S schedstat=( 23011156 16402650 145 ) utm=1 stm=1 core=2 HZ=100
| stack=0x70c633c000-0x70c633e000 stackSize=1039KB
| held mutexes=
at com.android.server.audio.MediaFocusControl.updateCurrentAudioFocus(MediaFocusControl.java:1309)
- waiting to lock <0x0be017a1> (a java.lang.Object) held by thread 154
at com.android.server.audio.AudioService$IDCMciroFeedback.onAudioFocusIDCMicroChanged(AudioService.java:10860)
at com.android.server.audio.PlaybackActivityMonitor$AudioIDCMicroRequestCallback.onAudioFocusRemoteChanged(PlaybackActivityMonitor.java:1156)
at com.android.server.audio.AudioIDCMicroNegotiator$IDCMicroAudioFocusHandler.run(AudioIDCMicroNegotiator.java:507)
- locked <0x02898140> (a java.lang.Object)
↓
"Binder:1527_16" prio=5 tid=154 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x15088cb0 self=0xb400007328bee320
| sysTid=8226 nice=0 cgrp=default sched=0/0 handle=0x7109bb3cb0
| state=S schedstat=( 3449183777 604215017 7007 ) utm=235 stm=109 core=4 HZ=100
| stack=0x7109abc000-0x7109abe000 stackSize=991KB
| held mutexes=
at com.android.server.audio.PlaybackActivityMonitor.restoreVShapedPlayers(PlaybackActivityMonitor.java:629)
- waiting to lock <0x02eac408> (a java.lang.Object) held by thread 10
at com.android.server.audio.MediaFocusControl.restoreVShapedPlayers(MediaFocusControl.java:134)
at com.android.server.audio.FocusRequester.handleFocusGainFromRequest(FocusRequester.java:364)
at com.android.server.audio.MediaFocusControl.requestAudioFocus(MediaFocusControl.java:1048)
- locked <0x0be017a1> (a java.lang.Object)
at com.android.server.audio.AudioService.requestAudioFocus(AudioService.java:8388)
at android.media.IAudioService$Stub.onTransact(IAudioService.java:1878)
at android.os.Binder.execTransactInternal(Binder.java:1179)
at android.os.Binder.execTransact(Binder.java:1143)
尝试方案来解决死锁问题。
#6 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
HI ALL
我们提交了新的patch来修复该问题，当前没有再复现问题，需要测试帮忙使用该VB进行压测。
VB如下：
http://192.168.87.26:8080/view/Projects/view/Project-IOT/job/VerifyBuild_for_IOT_6490/683/console
#7 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
- Status changed from ASSIGNED to NEED_INFO
- Assignee changed from Multimedia组-RD3_TSCD 梁卿山 to CDTS_Test 吴诗雨
HI 诗雨
请使用上面的VB进行压测验证，谢谢！
具体场景，从日志来看似乎在使用腾讯视频播放视频。
#8 Updated by CDTS-TEST 周婷 about 2 years ago
- Priority changed from Normal to High
#9 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
HI 诗雨
请进行压测该问题，该提交需要及时投入，谢谢！
#10 Updated by CDTS-TEST 周婷 about 2 years ago
- Status changed from NEED_INFO to ASSIGNED
- Assignee changed from CDTS_Test 吴诗雨 to Multimedia组-RD3_TSCD 梁卿山
请先用VB 自测OK后转给测试验证
#11 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
HI 诗雨
新的VB地址，该问题需要压测。
播放腾讯视频。
Figure/VerifyBuild/Pre_figure_turbox-c2130c-la1.1-qssi12-dev/20230523/202305231359-802
#12 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
- Assignee changed from Multimedia组-RD3_TSCD 梁卿山 to CDTS_Test 吴诗雨
HI 诗雨
该问题，我们自己测试了基础场景，没问题。
请使用该VB进行压测验证；
压测场景，
腾讯视频的播放；
#13 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
HI ALL
环境：
1.安装了腾讯视频，
2.push了一些音频和视频文件
3.跑monkey，命令如下：
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 4320000 2>/sdcard/error.txt 1>/sdcard/info.txt
早上的结果：
monkey依然在进行，停止后焦点正常，未出现ANR。
下一步，今晚继续测试。
#14 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
HI ALL
环境：
1.安装了腾讯视频，
2.push了一些音频和视频文件
3.跑monkey，命令如下：
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 4320000 2>/sdcard/error.txt 1>/sdcard/info.txt
早上的结果：
monkey依然在进行，停止后焦点正常，未出现ANR。
测试结果OK，将会投入该提交。
#15 Updated by IoT scm about 2 years ago
| ID | Project | Branch | Uploader |
| 199764 | general/platform/frameworks/base | Pre_figure_turbox-c2130c-la1.1-qssi12-dev | tangyj0127@thundersoft.com |
| MM: Audio: Fix focus deadlock issue Fix focus deadlock issue TC-RID: 0301-0900116 IssueID: TS-R-DF-117821 Change-Id: I23ee53aa7bdf823ae8319a979920fdefd9285d8a |
|||
#16 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
- Status changed from ASSIGNED to RESOLVED
- Resolution changed from -- to FIXED
- Degrated changed from -- to No
- Root cause set to 解决焦点更新时死锁问题
HI 诗雨
代码已经投入，请关闭该问题，谢谢！
#17 Updated by CDTS_Test 吴诗雨 about 2 years ago
- Status changed from RESOLVED to VERIFIED
#18 Updated by CDTS_Test 吴诗雨 about 2 years ago
- Status changed from VERIFIED to CLOSED