Figure

1.问题描述发生是在20:00左右。现有日志中最晚的时间为19:55左右。请确认问题发生时间是否正确。如果不正确请提供正确时间点的日志。
2.从现有的日志发现，有报屏幕端的DTC错误，疑似屏幕端出现了异常。需要和屏厂进一步确认。
01-01 12:42:04.205 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:10.133 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:16.277 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:22.517 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:28.454 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:34.385 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:40.645 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:46.901 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)
01-01 12:42:53.145 0 0 E DTC_Display: screen not ready(0), bl_sta(1), lvl(20)

等待客户确认DTC

1.从测试的说明来看场景看问题应该发生在05-17 19:44:03.537，此时com.android.documentsui APP被杀了
-->（文件管理-右上角菜单栏-放大镜）

/logcat/000023_manual_00018_230517_194740.log:656:05-17 19:47:45.270  1499  1619 I am_pss  : [9656,10020,com.android.documentsui,108872704,102871040,780288,183529472,0,2,10]
  ./logcat/000023_manual_00024_230517_194920.log:1010:05-17 19:49:34.073  1499  1619 I am_pss  : [9656,10020,com.android.documentsui,102824960,98639872,814080,175476736,0,2,9]
  ./logcat/000023_manual_00032_230517_194009.log:1517:05-17 19:40:21.771  2503  2503 V GameTypeUtils: judge isGame:com.android.documentsui
  ./logcat/000023_manual_00046_230517_194402.log:471:05-17 19:44:03.533  1499  1738 D ActivityManager: freezing 3669 com.android.documentsui
  ./logcat/000023_manual_00046_230517_194402.log:472:05-17 19:44:03.533  1499  1738 E ActivityManager: Unable to freeze binder for 3669 com.android.documentsui
  ./logcat/000023_manual_00046_230517_194402.log:475:05-17 19:44:03.535  1499  1738 D ActivityManager: froze 3669 com.android.documentsui
  ./logcat/000023_manual_00046_230517_194402.log:476:05-17 19:44:03.535  1499  1738 I am_freeze: [3669,com.android.documentsui]
  ./logcat/000023_manual_00046_230517_194402.log:477:05-17 19:44:03.535  1499  1738 E ActivityManager: Unable to freeze binder for 3669 com.android.documentsui
  ./logcat/000023_manual_00046_230517_194402.log:478:05-17 19:44:03.537  1499  1738 I ActivityManager: Killing 3669:com.android.documentsui/u0a20 (adj 940): Unable to freeze binder interface
  ./logcat/000023_manual_00046_230517_194402.log:479:05-17 19:44:03.537  1499  1738 I am_kill : [0,3669,com.android.documentsui,940,Unable to freeze binder interface]
  ./logcat/000023_manual_00046_230517_194402.log:500:05-17 19:44:03.599  1499 29056 I WindowManager: WIN DEATH: Window{9b8c62c u0 
  com.android.documentsui/com.android.documentsui.files.FilesActivity}

导致该问题的原因是内存占用过高，com.android.documentsui被杀之前的日志暂未找到冻屏的log；下一步：将内存刷至剩余117M左右，再次验证。

物联网测试组_CDTS 唐霞 wrote:

【环境信息】：EE环境
【问题出现时间】：20230517 20:00,第23次开机

https://ofs.human-horizons.com/#/download/index/%2BihslvJu4tk%3D
【前提条件】：
【操作步骤】：1.文件管理-右上角菜单栏-放大镜
2、输入Ca，搜索，等待几分钟
【实际结果】
冻屏，输入框光标不再闪动，下滑上滑左右滑手势均无效，等待约5-10分钟后自动恢复
【期望结果】
正常搜索文件
【备注】：卡顿界面见图
【应用版本】：不涉及
【硬件版本号】：/
【副屏版本号】：01.00.0095.C103
【中控版本号】：03.02.0080.C101.03_userdebug_2305121121

----------------------------------------------------------------
客户最新bug 描述更新：
【环境信息】EE环境
【问题出现时间】：20230518 9点58分（ 第145次开机）
【前提条件】：车机上电（KL30ON ，KL15 ON）
1.副屏在使用应用宝下载多个应用

2.进入文件界面

【实际结果】

文件管理界面冻屏，不响应任何操作。

【期望结果】
副屏文件管理界面正常响应操作。
【备注】：

此问题出现一次，约15分钟后自行恢复。

车架号VIN：HRYTTESTVINMGM400

log地址：https://ofs.human-horizons.com/#/download/index/sSmI9%2FemHK8%3D

视频地址：https://ofs.human-horizons.com/#/download/index/c6%2B%2FTqCb474%3D

【影响版本】：副屏：01.00.0095.c103
【硬件版本号】：/
【是否能恢复】：可恢复

■ 我的分析
----------------
anr_2023-05-17-19-54-58-215

"main" prio=5 tid=1 Blocked | group="main" sCount=1 ucsCount=0 flags=1 obj=0x71866308 self=0xb400007361b9e7b0 | sysTid=1499 nice=-2 cgrp=default sched=0/0 handle=0x7531f2f4f8 | state=S schedstat=( 45270251427 41114985817 175996 ) utm=3285 stm=1241 core=6 HZ=100 | stack=0x7feeae7000-0x7feeae9000 stackSize=8188KB | held mutexes=
at com.android.server.am.ActivityManagerService.getMemoryTrimLevel(ActivityManagerService.java:8688)
- waiting to lock <0x0ab8b4c8> (a com.android.server.am.ActivityManagerService) held by thread 164
at com.android.server.job.JobConcurrencyManager.refreshSystemStateLocked(JobConcurrencyManager.java:493)
at com.android.server.job.JobConcurrencyManager.updateCounterConfigLocked(JobConcurrencyManager.java:503)
at com.android.server.job.JobConcurrencyManager.assignJobsToContextsInternalLocked(JobConcurrencyManager.java:561)
at com.android.server.job.JobConcurrencyManager.assignJobsToContextsLocked(JobConcurrencyManager.java:538)
at com.android.server.job.JobSchedulerService.maybeRunPendingJobsLocked(JobSchedulerService.java:2487)
at com.android.server.job.JobSchedulerService$JobHandler.handleMessage(JobSchedulerService.java:2071)
- locked <0x09cf8bb1> (a java.lang.Object)
at android.os.Handler.dispatchMessage(Handler.java:106)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at com.android.server.SystemServer.run(SystemServer.java:909)
at com.android.server.SystemServer.main(SystemServer.java:616)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:987)

"Binder:1499_1F" prio=5 tid=164 Blocked | group="main" sCount=1 ucsCount=0 flags=1 obj=0x133c9ae0 self=0xb400007361cf6a90 | sysTid=32704 nice=-2 cgrp=default sched=0/0 handle=0x713ea3fcb0 | state=S schedstat=( 18927190680 14770598272 89474 ) utm=1298 stm=593 core=6 HZ=100 | stack=0x713e948000-0x713e94a000 stackSize=991KB | held mutexes=
at com.android.server.power.PowerManagerService.updateUidProcStateInternal(PowerManagerService.java:3751)
- waiting to lock <0x0c0384ee> (a java.lang.Object) held by thread 36
at com.android.server.power.PowerManagerService$LocalService.updateUidProcState(PowerManagerService.java:6118)
at com.android.server.am.ActivityManagerService.enqueueUidChangeLocked(ActivityManagerService.java:14555)
at com.android.server.am.OomAdjuster.updateUidsLSP(OomAdjuster.java:1450)
at com.android.server.am.OomAdjuster.updateOomAdjInnerLSP(OomAdjuster.java:1050)
at com.android.server.am.OomAdjuster.performUpdateOomAdjLSP(OomAdjuster.java:736)
at com.android.server.am.OomAdjuster.updateOomAdjLSP(OomAdjuster.java:659)
at com.android.server.am.OomAdjuster.updateOomAdjLocked(OomAdjuster.java:641)
- locked <0x049322b3> (a com.android.server.am.ActivityManagerProcLock)
at com.android.server.am.ActivityManagerService.updateOomAdjLocked(ActivityManagerService.java:14704)
at com.android.server.am.ActiveServices.realStartServiceLocked(ActiveServices.java:4061)
at com.android.server.am.ActiveServices.bringUpServiceLocked(ActiveServices.java:3946)
at com.android.server.am.ActiveServices.bindServiceLocked(ActiveServices.java:2878)
at com.android.server.am.ActivityManagerService.bindIsolatedService(ActivityManagerService.java:12134)
- locked <0x0ab8b4c8> (a com.android.server.am.ActivityManagerService)
at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:2606)
at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2528)
at android.os.Binder.execTransactInternal(Binder.java:1179)
at android.os.Binder.execTransact(Binder.java:1143)

"PowerManagerService" prio=5 tid=36 Native | group="main" sCount=1 ucsCount=0 flags=1 obj=0x133c17e0 self=0xb400007361bf3a80 | sysTid=1636 nice=-10 cgrp=default sched=0/0 handle=0x714528fcb0 | state=S schedstat=( 5155086887 9797201141 76153 ) utm=283 stm=231 core=1 HZ=100 | stack=0x714518c000-0x714518e000 stackSize=1039KB | held mutexes=
native: #00 pc 00000000000a2808 /apex/com.android.runtime/lib64/bionic/libc.so (recvfrom+8)
native: #01 pc 00000000000640b0 /apex/com.android.runtime/lib64/bionic/libc.so (__system_property_set+760)
native: #02 pc 00000000000b0130 /system/lib64/libandroid_runtime.so (android::(anonymous namespace)::SystemProperties_set(_JNIEnv*, _jobject*, _jstring*, _jstring*)+308)
at android.os.SystemProperties.(Native method)
at android.os.SystemProperties.set(SystemProperties.java:233)
at android.app.PropertyInvalidatedCache.invalidateCacheLocked(PropertyInvalidatedCache.java:676)
at android.app.PropertyInvalidatedCache.invalidateCache(PropertyInvalidatedCache.java:646)
- locked <0x08b9a822> (a java.lang.Object)
at android.os.PowerManager.invalidateIsInteractiveCaches(PowerManager.java:2926)
at com.android.server.power.PowerManagerService$Injector.invalidateIsInteractiveCaches(PowerManagerService.java:918)
at com.android.server.power.PowerManagerService.setGlobalWakefulnessLocked(PowerManagerService.java:2029)
at com.android.server.power.PowerManagerService.setWakefulnessLocked(PowerManagerService.java:1970)
at com.android.server.power.PowerManagerService.dreamDisplayGroupNoUpdateLocked(PowerManagerService.java:1930)
at com.android.server.power.PowerManagerService.updateWakefulnessLocked(PowerManagerService.java:2858)
at com.android.server.power.PowerManagerService.updatePowerStateLocked(PowerManagerService.java:2150)
at com.android.server.power.PowerManagerService.handleUserActivityTimeout(PowerManagerService.java:2764)
- locked <0x0c0384ee> (a java.lang.Object)
at com.android.server.power.PowerManagerService.access$3600(PowerManagerService.java:139)
at com.android.server.power.PowerManagerService$PowerManagerHandlerCallback.handleMessage(PowerManagerService.java:4811)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.os.HandlerThread.run(HandlerThread.java:67)
at com.android.server.ServiceThread.run(ServiceThread.java:44)
----------------
tid=1 被 tid=164 block，tid=164 又被 tid=36 block
但是tid=36并没有等其他锁，应该就是tid=36这个线程，一直在处理它的业务逻辑，持有的锁一直没释放，block 164和1了

■ 下一步计划

导致该问题的原因是内存占用过高，com.android.documentsui被杀之前的日志暂未找到冻屏的log；下一步：将内存刷至剩余117M左右，再次验证。

1.之前system组的同学此结果还未验证(已飞书联系，待反馈验证结果)
2.从日志检查下36这个线程为什么这么耗时，一直没有完成，看堆栈是在设置系统属性，这个应该要不了多久才对
3.对于PropertyInvalidatedCache.java中invalidateCacheLocked方法，在androidT和S中实现有变化，检查这一变化的影响

1、目前进展
1）按照之前的一些分析结论，从发生死锁的方法PropertyInvalidatedCache.invalidateCacheLocked出发，找到12和13的区别，差别patch的信息如下：

This change corrects a latent defect related by the new bypass()
method in PropertyInvalidatedCache.  The defect is not current issue
because there are no clients using the bypass() method yet.

从patch的修改逻辑，没太看多太多逻辑性的东西，不过后续会将该patch先调整到目前的版本中，作为一个处理点。
2）找到了19：46-19：54的日志目前正在分析，这个时间段刚好是system_server 发生anr之前的时间，看是否能从这个时间段中，anr的一些其他信息。

2、下一步
1）将13的patch搬过来打入，让测试测试
2）结合之前的分析信息，进一步强化分析19：46-19：54这个时间的日志

1、5月26日进展
1）将PowerManager.invalidateIsInteractiveCaches,在android13的更新patch已经做好，并编译了Jenkins版本
提交如下：https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/202615
2）继续强化分析19：46-19：54之间的日志
分析的情况：
在这个时间段内容出现大量的如下日志信息：

05-17Freezer: check freeze binder ioctl
Some old kernels don't have the necessary binder ioctls for freezer
(BINDER_FREEZE & BINDER_GET_FROZEN_INFO). In such a case, disable
freezer with a warning log. 19:47:45.212  1000  1499  1738 D ActivityManager: freezing 24540 com.android.permissioncontroller
05-17 19:47:45.212  1000  1499  1738 E ActivityManager: Unable to freeze binder for 24540 com.android.permissioncontroller
01-01 12:44:54.141  root     0     0 I binder  : 1499:1738 ioctl 400c620e 7138afd5d8 returned -22
01-01 12:44:54.144  root     0     0 I binder  : 1499:1738 ioctl c00c620f 7138afd5b8 returned -22
05-17 19:47:45.214  1000  1499  1738 D ActivityManager: froze 24540 com.android.permissioncontroller
05-17 19:47:45.215  1000  1499  1738 E ActivityManager: Unable to freeze binder for 24540 com.android.permissioncontroller
05-17 19:47:45.224  1000  1499  1738 I ActivityManager: Killing 24540:com.android.permissioncontroller/u0a90 (adj 975): Unable to freeze binder interface
05-17 19:47:51.829  1000  1499  1738 D ActivityManager: freezing 5416 com.qualcomm.qti.qccauthmgr
05-17 19:47:51.831  1000  1499  1738 E ActivityManager: Unable to freeze binder for 5416 com.qualcomm.qti.qccauthmgr
01-01 12:45:00.778  root     0     0 I binder  : 1499:1738 ioctl 400c620e 7138afd5d8 returned -22
05-17 19:47:51.833  1000  1499  1738 D ActivityManager: froze 5416 com.qualcomm.qti.qccauthmgr
01-01 12:45:00.782  root     0     0 I binder  : 1499:1738 ioctl c00c620f 7138afd5b8 returned -22
05-17 19:47:51.833  1000  1499  1738 E ActivityManager: Unable to freeze binder for 5416 com.qualcomm.qti.qccauthmgr
05-17 19:47:51.837  1000  1499  1738 I ActivityManager: Killing 5416:com.qualcomm.qti.qccauthmgr/u0a83 (adj 975): Unable to freeze binder interface
01-01 12:45:09.020  root     0     0 I binder  : 1499:1738 ioctl 400c620e 7138afd5d8 returned -22

可以看出是系统在freeze相关的应用，并做了kill进程的操作，从freeze这个操作进行check，发现缺少了freeze的相关patch，
在内核比较低的版本上（4.19.157+），是不支持freeze的，不支持就会杀除进程。
谷歌针对freeze的patch信息如下：

Freezer: check freeze binder ioctl
Some old kernels don't have the necessary binder ioctls for freezer
(BINDER_FREEZE & BINDER_GET_FROZEN_INFO). In such a case, disable
freezer with a warning log.

后续会把这个patch添加进来。避免做freeze时将进程杀掉。

针对PowerManager.invalidateIsInteractiveCaches锁住的问题，就是SystemProperties.set方法耗时太久造成锁住的情况，
大概率是受到freeze相关的操作应用，因为从就是SystemProperties的实现原理来看，property service收到请求之后再set进property workspace（共享内存方式），
但是property service（init进程）是单线程工作，所以有时候它可能响应比较慢（比如它正在关闭一个子进程或者正在做其他事情）,前面因为freeze不停的杀除进程正好满足这个条件。
2、下一步
1）将freeze的patch打入
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/202849
2）在运行monkey测试时将游戏性能优化的策略停掉
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/202848
https://dev.thundercomm.com/gerrit/c/general/platform/vendor/thundercomm/apps/GameMode/+/202856
3）将3个方面的修改做一个Jenkins编译，后续在这个版本上进行验证

1、5月27日进展
将3个方面的修改编译了Jenkins
http://10.0.76.24:8080/job/VerifyBuild_for_IOT_6490/4021

在Jenkins版本验证了3个修改策略：
1）
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/202615
在自动进入屏保和退出屏保时，PowerManager.invalidateIsInteractiveCaches的逻辑正常，相关日志：

05-24 17:09:24.451  1063  1223 I DreamManagerService: Entering dreamland.
05-24 17:09:24.452  1063  1223 I PowerManagerService: Dreaming...
05-24 17:09:29.667  1063  2514 I DreamManagerService: Gently waking up from dream.
05-24 17:09:29.671  1063  1177 I DreamManagerService: Performing gentle wake from dream.

2）
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/202848
https://dev.thundercomm.com/gerrit/c/general/platform/vendor/thundercomm/apps/GameMode/+/202856
针对monkey测试时，调整游戏模式时性能优化的策略
monkey测试运行，有如下日志：

E GameMode_ActivityMonitoringService: [Perf] is not support Performance or in monkey test.

未运行monkey时，启动应用的日志：

I thunderperf: Maybe need boostperf for current app!
I ThunderBoostPerfService: Disable downscaling

3）
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/202849
未引入关于freeze的patch时，在启动的应用或者服务挂载到后台后，持续一段时间后，就会触发freeze，并杀除进程，日志信息如下：

1067  1195 W ActivityManager: Stopping service due to app idle: u0a52 -11m25s719ms com.kuaishou.nebula/com.kwai.chat.kwailink.service.NewKwa
1067  1705 D ActivityManager: freezing 9359 com.qualcomm.qti.qms.service.trustzoneaccess
1067  1705 E ActivityManager: Unable to freeze binder for 9359 com.qualcomm.qti.qms.service.trustzoneaccess
1067  1705 D ActivityManager: froze 9359 com.qualcomm.qti.qms.service.trustzoneaccess
1067  1705 I am_freeze: [9359,com.qualcomm.qti.qms.service.trustzoneaccess]
1067  1705 E ActivityManager: Unable to freeze binder for 9359 com.qualcomm.qti.qms.service.trustzoneaccess
1067  1705 I ActivityManager: Killing 9359:com.qualcomm.qti.qms.service.trustzoneaccess/u0a58 (adj 945): Unable to freeze binder interface

引入freeze的patch之后，打开同样的应用和服务，等待一段时间后，未发现类似的freeze日志输出，没有触发进程杀除的日志。

综述：3个修改策略在本地验证时运行正常，日志方面没有出现票中所出现的异常日志。

2、下一步
1）确认修改是否需要合入。

FlatBuild_HH_MCE_FSE.M.R.user.01.00.0107.C104版本验证20次未复现

在01.00.0108.C104版本验证20次未复现

FlatBuild_HH_MCE_FSE.M.R.user.01.00.0110.C104版本验证20次未复现

user.01.00.0110.C104（6/13）版本验证20次未复现

在FlatBuild_HH_MCE_FSE.M.R.user.01.00.0110.C105版本（6.15）复测20次未复现

FlatBuild_HH_MCE_FSE.M.D.user.01.00.C105.202306180036复测20次，未复现

FlatBuild_HH_MCE_FSE.M.D.user.01.00.C105.202306180036 复测20次未复现

FlatBuild_HH_MCE_FSE.M.D.user.01.00.C105.202306200207 版本复测20次未复现

FlatBuild_HH_MCE_FSE.M.R.user.01.00.0112.C105验证20次未复现

FlatBuild_HH_MCE_FSE.M.D.user.01.00.C105.202306250045 版本验证20次未复现