Bug #118056
IOVDEV-28916 【内部】【VC1】【0095】【台架】【EE环境】【副屏】monkey测试第二天查看副屏黑屏不可操作
| Status: | CLOSED | Start date: | 2023-05-23 | |
|---|---|---|---|---|
| Priority: | Urgent | Due date: | 2023-05-26 | |
| Assignee: | CD TEST-方永红 | % Done: | 100% | |
| Category: | 黑屏 | |||
| Target version: | - | |||
| Need_Info: | -- | Found Version: | 01.00.0095.c103 | |
| Resolution: | -- | Degrated: | -- | |
| Severity: | Critical | Verified Version: | ||
| Reproducibility: | Frequently | Fixed Version: | 2023-05-26 | |
| Test Type: | Free Test | Root cause: |
Description
【环境信息】EE环境
【问题出现时间】：20230518 8点28分
【前提条件】：车机上电（KL30ON ，KL15 ON，已连接中控和功放，可正常输出声音）
1.5月17日第144次开机晚上8点20左右开始运行monkey测试
2.5月18日早上8点28分发现副屏黑屏（中控和仪表是亮屏的）
【实际结果】
点击副屏没有亮屏（屏幕没有背光），电脑与副屏控制器进行adb连接发现是正常连接，可以读取副屏数据（此时副屏黑屏无法停止收集实时log）。之后只是断开副屏屏幕的电源再上电，副屏屏幕显示黑屏有背光，不响应任何操作。8点42分拉取adb的log到电脑，约8点46分手动让副屏控制器KL15 OFF再立即ON，副屏重启亮屏，实时日志还在收集，停止收集将实时log和历史log以及monkey log 拉取到电脑。
【期望结果】
副屏正常运行monkey测试，无黑屏或重启等严重异常问题。
【备注】：
车架号VIN：HRYTTESTVINMGM400
副屏第144次开机运行monkey，由于黑屏无法停止收集log，手动重启副屏第145次开机截取log到电脑。
log地址：实时log：https://ofs.human-horizons.com/#/download/index/6RdBnSrNe5g%3D
历史输出log：https://ofs.human-horizons.com/#/download/index/MdMvFX1Vmac%3D
monkey的log已添加到附件中
视频地址：https://ofs.human-horizons.com/#/download/index/JjQ%2FwoLLrvU%3D
【影响版本】：副屏：01.00.0095.c103
【硬件版本号】：/
【是否能恢复】：
Subtasks
History
#1 Updated by CD SYSTEM-夏旭 about 2 years ago
- Status changed from New to ASSIGNED
#2 Updated by CD SYSTEM-夏旭 about 2 years ago
- % Done changed from 0 to 20
#3 Updated by CD SYSTEM-夏旭 about 2 years ago
- File a.log added
1. 发生时间在8点28，如果要排查5月17日昨晚上8点20到18日8点28之间的log，这个log太多了，需要时间
2.8点48分有看到MCU导致的系统关机
000144_manual_00021_230518_084709.log:1294:05-18 08:48:27.986 9138 9272 D ProtectUartService: received uart notiy mpu to shutdown
000144_manual_00021_230518_084709.log:1305:05-18 08:48:28.007 8523 8931 V ShutdownCheckPoints: Binder shutdown checkpoint recorded with pid=9138
000144_manual_00021_230518_084709.log:1306:05-18 08:48:28.008 8523 8540 V ShutdownCheckPoints: System server shutdown checkpoint recorded
/000144_manual_00021_230518_084709.log:1307:05-18 08:48:28.008 8523 8540 D ShutdownThread: Notifying thread to start shutdown longPressBehavior=5
000144_manual_00021_230518_084709.log:1309:05-18 08:48:28.009 8523 8540 D ShutdownThread: Attempting to use SysUI shutdown UI
000144_manual_00021_230518_084709.log:1310:05-18 08:48:28.010 8523 8540 D ShutdownThread: SysUI handling shutdown UI
000144_manual_00021_230518_084709.log:1317:05-18 08:48:28.016 8523 12366 I ShutdownThread: Sending shutdown broadcast...
000144_manual_00021_230518_084709.log:1318:05-18 08:48:28.022 8523 8523 W SyncManager: Writing sync state before shutdown...
#4 Updated by CD SYSTEM-夏旭 about 2 years ago
- Status changed from ASSIGNED to NEED_INFO
1. 5月17日第144次开机晚上8点20左右开始运行monkey测试,
在提供的log里面没有monkey的log输出，初步怀疑没有抓到现场的log
正常如果monkey会有下面，类似的输出
05-17 05:01:00.125 30029 30029 I Monkey : Sleeping for 500 milliseconds
2.测试复现一下
#5 Updated by CD SYSTEM-夏旭 about 2 years ago
- File 000144_persist_00675_230518_072259.log added
#6 Updated by CD SYSTEM-夏旭 about 2 years ago
- File 000144_persist_00675_230518_072259.log added
- File anr_2023-05-18-07-01-09-881 added
#7 Updated by CD SYSTEM-夏旭 about 2 years ago
- File 000144_persist_00675_230518_072259.log added
- File system_audio.7z added
- File vendor_audio.7z added
1. 从历史输出log中查看，问题发生时间:20230518 8点28分
monkey 在05-18 07:22:59.992时，系统已经发行了异常
000144_persist_00675_230518_072259.log:2651:05-18 07:22:59.992 17163 17163 W Monkey : ** Error: A RuntimeException occurred:
000144_persist_00675_230518_072259.log:2652:05-18 07:22:59.992 17163 17163 W Monkey : java.lang.RuntimeException: android.os.DeadSystemException
000144_persist_00675_230518_072259.log:2653:05-18 07:22:59.992 17163 17163 W Monkey : at android.hardware.input.InputManager.injectInputEvent(InputManager.java:1093)
000144_persist_00675_230518_072259.log:2654:05-18 07:22:59.992 17163 17163 W Monkey : at com.android.commands.monkey.MonkeyMotionEvent.injectEvent(MonkeyMotionEvent.java:188)
000144_persist_00675_230518_072259.log:2655:05-18 07:22:59.992 17163 17163 W Monkey : at com.android.commands.monkey.Monkey.runMonkeyCycles(Monkey.java:1217)
000144_persist_00675_230518_072259.log:2656:05-18 07:22:59.992 17163 17163 W Monkey : at com.android.commands.monkey.Monkey.run(Monkey.java:708)
000144_persist_00675_230518_072259.log:2657:05-18 07:22:59.992 17163 17163 W Monkey : at com.android.commands.monkey.Monkey.main(Monkey.java:568)
000144_persist_00675_230518_072259.log:2658:05-18 07:22:59.992 17163 17163 W Monkey : at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method)
000144_persist_00675_230518_072259.log:2659:05-18 07:22:59.992 17163 17163 W Monkey : at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:355)
2.查看000144_persist_00675_230518_072259.log发现SurfaceFlinger出错
05-18 07:22:59.509 1003 1646 E SurfaceFlinger: layer (Surface(name=Task=71068)/@0x6d7ceca - animation-leash of app_transition#33) :: parent (DefaultTaskDisplayArea#0).
05-18 07:22:59.509 1003 1646 E SurfaceFlinger: layer (Surface(name=Task=76384)/@0x4c2216a - animation-leash of app_transition#5) :: parent (DefaultTaskDisplayArea#0).
在同一份同时抓取的log中kernel（但是时间戳不对）的log中发现，SurfaceFlinger会通过binder分配内存，但是失败，有可能是此原因导致的SurfaceFlinger异常的原因
01-02 04:35:32.581 0 0 I binder_alloc: 1003: binder_alloc_buf size 1212696 failed, no address space
说明此时内存严重不足3./vendor/bin/hw/android.hardware.audio.service 程序crash
请查看system_audio.7z文件
4./system/bin/audioserver 程序crash
请查看 vendor_audio.7z文件
5.请将此问题建立子票，分别跟踪，并分发给相关ownner进行处理
#8 Updated by CDTS_Test 吴诗雨 about 2 years ago
- Fixed Version set to 2023-05-26
#9 Updated by CDTS-TEST 周婷 about 2 years ago
- Status changed from NEED_INFO to ASSIGNED
#10 Updated by CDTS-TEST 周婷 about 2 years ago
- Category changed from BSP to 黑屏
#11 Updated by CD SYSTEM-夏旭 about 2 years ago
1. 初步分析，应该是内存不足
#12 Updated by CD SYSTEM-夏旭 about 2 years ago
1. 初步分析，应该是内存不足
查看000144_persist_00675_230518_072259.log发现SurfaceFlinger出错
05-18 07:22:59.509 1003 1646 E SurfaceFlinger: layer (Surface(name=Task=71068)/@0x6d7ceca - animation-leash of app_transition#33) :: parent (DefaultTaskDisplayArea#0).
05-18 07:22:59.509 1003 1646 E SurfaceFlinger: layer (Surface(name=Task=76384)/@0x4c2216a - animation-leash of app_transition#5) :: parent (DefaultTaskDisplayArea#0).
在同一份同时抓取的log中kernel（但是时间戳不对）的log中发现，SurfaceFlinger会通过binder分配内存，但是失败，有可能是此原因导致的SurfaceFlinger异常的原因
01-02 04:35:32.581 0 0 I binder_alloc: 1003（这里打印的PID与SurfaceFlinger相同）: binder_alloc_buf size 1212696 failed, no address space
说明此时内存严重不足
2. createSurface error Out of memory
05-18 07:22:59.209 1535 16789 E SurfaceComposerClient: SurfaceComposerClient::createSurface error Out of memory
05-18 07:22:59.210 1535 16789 E WindowManager: Unhandled exception in Window Manager
05-18 07:22:59.210 1535 16789 E WindowManager: android.view.Surface$OutOfResourcesException
05-18 07:22:59.210 1535 16789 E WindowManager: at android.view.SurfaceControl.nativeCreate(Native Method)
05-18 07:22:59.210 1535 16789 E WindowManager: at android.view.SurfaceControl.<init>(SurfaceControl.java:1435)
05-18 07:22:59.210 1535 16789 E WindowManager: at android.view.SurfaceControl.<init>(SurfaceControl.java:87)
05-18 07:22:59.210 1535 16789 E WindowManager: at android.view.SurfaceControl$Builder.build(SurfaceControl.java:1108)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.SurfaceAnimator.createAnimationLeash(SurfaceAnimator.java:424)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.SurfaceAnimator.startAnimation(SurfaceAnimator.java:173)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.WindowContainer.startAnimation(WindowContainer.java:2526)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.WindowContainer.startAnimation(WindowContainer.java:2533)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.WindowContainer.startAnimation(WindowContainer.java:2539)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.InsetsSourceProvider.updateControlForTarget(InsetsSourceProvider.java:339)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.InsetsStateController.onControlChanged(InsetsStateController.java:467)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.InsetsStateController.onBarControlTargetChanged(InsetsStateController.java:438)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.InsetsPolicy.updateBarControlTarget(InsetsPolicy.java:146)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.DisplayPolicy.updateSystemUiVisibilityLw(DisplayPolicy.java:2658)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.DisplayPolicy.finishPostLayoutPolicyLw(DisplayPolicy.java:2047)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.DisplayContent.applySurfaceChangesTransaction(DisplayContent.java:4318)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.RootWindowContainer.applySurfaceChangesTransaction(RootWindowContainer.java:1076)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.RootWindowContainer.performSurfacePlacementNoTrace(RootWindowContainer.java:852)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.RootWindowContainer.performSurfacePlacement(RootWindowContainer.java:805)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.WindowSurfacePlacer.performSurfacePlacementLoop(WindowSurfacePlacer.java:177)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.WindowSurfacePlacer.performSurfacePlacement(WindowSurfacePlacer.java:126)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.WindowSurfacePlacer.performSurfacePlacement(WindowSurfacePlacer.java:115)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.WindowSurfacePlacer.continueLayout(WindowSurfacePlacer.java:97)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.ActivityTaskManagerService.continueWindowLayout(ActivityTaskManagerService.java:4299)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.ActivityRecord.activityPaused(ActivityRecord.java:5598)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.ActivityClientController.activityPaused(ActivityClientController.java:201)
05-18 07:22:59.210 1535 16789 E WindowManager: at android.app.IActivityClientController$Stub.onTransact(IActivityClientController.java:571)
05-18 07:22:59.210 1535 16789 E WindowManager: at com.android.server.wm.ActivityClientController.onTransact(ActivityClientController.java:134)
05-18 07:22:59.210 1535 16789 E WindowManager: at android.os.Binder.execTransactInternal(Binder.java:1184)
05-18 07:22:59.210 1535 16789 E WindowManager: at android.os.Binder.execTransact(Binder.java:1143)
3. 这里是第一次 创建surface出现out of memory
000144_persist_00655_230518_072210.log:1515:05-18 07:22:18.535 1535 1616 I sysui_multi_action: [757,803,799,window_time_0,802,1]
000144_persist_00655_230518_072210.log:1526:05-18 07:22:18.547 1535 2019 W FreeFormWindowHelper: Current Display FreeFormTask is null
000144_persist_00655_230518_072210.log:1599:05-18 07:22:18.558 1535 10080 I MediaFocusControl: abandonAudioFocus() from uid/pid 10066/16497 clientId=android.media.AudioManager@75dea9acom.android.gallery3d.app.MoviePlayer$6@d93ffcb
000144_persist_00657_230518_072218.log:1540:05-18 07:22:18.580 1535 2027 E SurfaceComposerClient: SurfaceComposerClient::createSurface error Out of memory
000144_persist_00657_230518_072218.log:1541:05-18 07:22:18.580 1535 2027 E WindowManager: Window Session Crash
000144_persist_00657_230518_072218.log:1542:05-18 07:22:18.580 1535 2027 E WindowManager: android.view.Surface$OutOfResourcesException
4. 创建surface出现out of memory
000144_persist_00660_230518_072222.log:1773:05-18 07:22:22.165 1535 1626 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
000144_persist_00660_230518_072222.log:1775:05-18 07:22:22.232 1535 1613 I sysui_multi_action: [319,197,322,0,325,74251,757,761,758,9,759,2,806,com.android.settings,871,com.android.settings.Settings,904,com.android.shell,905,0,1320,21,1321,5]
000144_persist_00661_230518_072222.log:1572:05-18 07:22:22.298 1535 2019 E SurfaceComposerClient: SurfaceComposerClient::createSurface error Out of memory
000144_persist_00661_230518_072222.log:1573:05-18 07:22:22.299 1535 2019 E WindowManager: Unhandled exception in Window Manager
000144_persist_00661_230518_072222.log:1574:05-18 07:22:22.299 1535 2019 E WindowManager: android.view.Surface$OutOfResourcesException
6.创建surface出现out of memory
000144_persist_00672_230518_072256.log:291:05-18 07:22:59.167 1535 16789 I wm_resume_activity: [0,218662391,77662,com.android.settings/.Settings]
000144_persist_00672_230518_072256.log:1869:05-18 07:22:59.209 1535 16789 E SurfaceComposerClient: SurfaceComposerClient::createSurface error Out of memory
000144_persist_00672_230518_072256.log:1870:05-18 07:22:59.210 1535 16789 E WindowManager: Unhandled exception in Window Manager
000144_persist_00672_230518_072256.log:1871:05-18 07:22:59.210 1535 16789 E WindowManager: android.view.Surface$OutOfResourcesException
7.第一次出现binder died
000144_persist_00674_230518_072259.log:740:05-18 07:22:59.432 1535 12721 D DisplayAreaOrganizerController: Organizer died before sending onDisplayAreaVanished
000144_persist_00674_230518_072259.log:741:05-18 07:22:59.432 1535 26441 D ConnectivityService: ConnectivityService NetworkRequestInfo binderDied(uid/pid:10079/1864, android.os.BinderProxy@cfe9b2f)
000144_persist_00674_230518_072259.log:742:05-18 07:22:59.432 1535 1535 W MediaSessionService: Dead ActiveSessionsListener in pushSessionsChanged, removing
000144_persist_00674_230518_072259.log:743:05-18 07:22:59.432 1535 1535 W MediaSessionService: android.os.DeadObjectException
8.出现system_server_wtf
./000144_persist_00675_230518_072259.log:1934:05-18 07:22:59.795 1535 1626 I am_wtf : [0,1535,system_server,-1,WindowManager,Invalid Surface(name=Task=77674)/@0xa724da0, mNativeObject is null. Have you called release() already?]
./000144_persist_00675_230518_072259.log:1935:05-18 07:22:59.795 1535 1626 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
./000144_persist_00675_230518_072259.log:1970:05-18 07:22:59.796 1535 1626 I am_wtf : [0,1535,system_server,-1,WindowManager,Invalid Surface(name=Task=77674)/@0xa724da0, mNativeObject is null. Have you called release() already?]
./000144_persist_00675_230518_072259.log:1971:05-18 07:22:59.796 1535 1626 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
./000144_persist_00675_230518_072259.log:2006:05-18 07:22:59.797 1535 1626 I am_wtf : [0,1535,system_server,-1,WindowManager,Invalid Surface(name=Task=77674)/@0xa724da0, mNativeObject is null. Have you called release() already?]
./000144_persist_00675_230518_072259.log:2007:05-18 07:22:59.797 1535 1626 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
./000144_persist_00675_230518_072259.log:2042:05-18 07:22:59.798 1535 1626 I am_wtf : [0,1535,system_server,-1,WindowManager,Invalid Surface(name=Task=77674)/@0xa724da0, mNativeObject is null. Have you called release() already?]
./000144_persist_00675_230518_072259.log:2077:05-18 07:22:59.799 1535 1626 I am_wtf : [0,1535,system_server,-1,WindowManager,Invalid Surface(name=Task=77674)/@0xa724da0, mNativeObject is null. Have you called release() already?]
./000144_persist_00675_230518_072259.log:2112:05-18 07:22:59.800 1535 1626 I am_wtf : [0,1535,system_server,-1,WindowManager,Invalid Surface(name=Task=77674)/@0xa724da0, mNativeObject is null. Have you called release() already?]
./000144_persist_00675_230518_072259.log:2148:05-18 07:22:59.801 1535 1617 I am_crash: [1535,0,system_server,-1,java.lang.NullPointerException,Invalid Surface(name=Task=77674)/@0xa724da0, mNativeObject is null. Have you called release() already?,SurfaceControl.java,1594]
9. 出现system crash，system_server被kill
./000144_persist_00675_230518_072259.log:2154:05-18 07:22:59.802 1535 1617 I DropBoxManagerService: add tag=system_server_crash isTagEnabled=true flags=0x2
000144_persist_00675_230518_072259.log:2401:05-18 07:22:59.815 1535 1617 I Process : Sending signal. PID: 1535 SIG: 9
000144_persist_00675_230518_072259.log:2411:05-18 07:22:59.874 681 681 I Zygote : Process 1535 exited due to signal 9 (Killed)
./000144_persist_00675_230518_072259.log:2564:05-18 07:22:59.929 682 682 E Zygote : Zygote failed to write to system_server FD: Connection refused
#13 Updated by CD SYSTEM-夏旭 about 2 years ago
1.从上午复现的日志看，初步定位到内存泄露(tlog)的进程，正在debug中...
#14 Updated by CD SYSTEM-夏旭 about 2 years ago
1.正在抓取数据 ，进行分析
:loop
set /a count+=1
for /f "tokens=1-3 delims=: " %%a in ('time /t') do (
set "hour=%%a"
set "minute=%%b"
set "second=%%c"
)
set "timestamp=%date% %hour%:%minute%:%second%"
echo ===============================================Loop count: %count%, Timestamp: %timestamp%=======================================
echo ===================================================Loop count: %count%, Timestamp: %timestamp%============================================== >> meminfo.txt
echo ========================================================dumpsys meminfo========================================= >> meminfo.txt
adb shell dumpsys meminfo >> meminfo.txt
echo ========================================================dumpsys meminfo tlog======================================= >> meminfo.txt
adb shell dumpsys meminfo tlog >> meminfo.txt
echo ========================================================proc_meminfo========================================================= >> meminfo.txt
adb shell cat /proc/meminfo >> meminfo.txt
echo ========================================================procrank=================================================== >> meminfo.txt
adb shell procrank >> meminfo.txt
timeout /t 15 /nobreak >nul
goto loop
#15 Updated by CD SYSTEM-胡兵 about 2 years ago
当前状态：
已定位到具体代码段问题，容器存储对象未释放导致，修改代码逻辑后，本地压力测试24小时(3s生成一个256k日志文件)，Tlog内存几乎没有变化，同样压测手法，修改前内存有明显增长。
下一步计划：
优化文件写入逻辑，本周合入优化方案
#16 Updated by CD SYSTEM-胡兵 about 2 years ago
- Status changed from ASSIGNED to RESOLVED
- Assignee changed from CD SYSTEM-夏旭 to CDTS_TEST 王成
正式方案已合入，请测试同学使用DB跑monkey验证
bug：tlog内存泄露导致副屏重启
提交：https://dev.thundercomm.com/gerrit/c/general/platform/vendor/thundercomm/apps/LogSystem/+/203640
验证：其他的功能正常
user版本的VB：安装apk，monkey跑了5个小时，tlog的RSS内存一直是10M以内，tlog进程号没有改变也没有被杀掉
userdebug版本的VB：修改文件大小为10K，tlog的RSS内存一直是10M以内，tlog进程号没有改变也没有被杀掉
#17 Updated by CD TEST-方永红 about 2 years ago
6.19
五台设备未复现黑屏
#18 Updated by CDTS_TEST 王成 about 2 years ago
- Assignee changed from CDTS_TEST 王成 to CD TEST-方永红
持续跟踪验证，客户在110版本暂未复现
#19 Updated by CD TEST-方永红 almost 2 years ago
- Status changed from RESOLVED to VERIFIED
7.10
客户验证通过，同步关闭
#20 Updated by CD TEST-方永红 almost 2 years ago
- Status changed from VERIFIED to CLOSED