Android hibernation 导致的冻屏问题分析

爱学习的替身

已于 2023-04-09 19:21:58 修改

阅读量995

点赞数 7

文章标签： android java

于 2023-04-08 22:48:39 首次发布

本文链接：https://blog.csdn.net/ztisen/article/details/130035340

版权

客户售后维护项目报出用户手中机器在过开机向导时概率冻屏重启的问题，问题非常严重，客户投诉

疑点一：此批次的机器早已出货，陆续售卖，为何在一个特定时间7/15号开始报出问题，之前为什么没有？
疑点二：另外两家运营商为啥没有反馈同样的问题，难道和运营商软件配置有关？
疑点三：客退的机器数量较大，复现概率应该很高，为什么这边测试从来没有复现过？
幸好客户提供了log，不然真不知道咋整了
OK，直接贴分析的log，存在SWT(Software Watchdog Timeout)
trace：

"main" prio=5 tid=1 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x7162d170 self=0xb4000075eefae380
| sysTid=2036 nice=-2 cgrp=foreground sched=0/0 handle=0x77b4aa64f8
| state=S schedstat=( 5911682801 1974540122 10009 ) utm=491 stm=99 core=4 HZ=100
| stack=0x7fedead000-0x7fedeaf000 stackSize=8188KB
| held mutexes=
at com.android.server.am.ContentProviderHelper.removeContentProvider(ContentProviderHelper.java:728)
- waiting to lock <0x085130da> (a com.android.server.am.ActivityManagerService) held by thread 128
at com.android.server.am.ActivityManagerService.removeContentProvider(ActivityManagerService.java:6300)
...
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:2036_8" prio=5 tid=128 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x13e066d8 self=0xb4000075ef0c4580
| sysTid=2791 nice=-2 cgrp=foreground sched=0/0 handle=0x7387de6cb0
| state=S schedstat=( 294280768 342847392 580 ) utm=24 stm=5 core=2 HZ=100
| stack=0x7387cef000-0x7387cf1000 stackSize=991KB
| held mutexes=
at
com.android.server.wm.ActivityTaskManagerService$LocalService.resumeTopActivities(ActivityTaskManagerService.java:5853)
- waiting to lock <0x05357b79> (a com.android.server.wm.WindowManagerGlobalLock) held by thread 129
...
at com.android.server.am.ActivityManagerService.forceStopPackage(ActivityManagerService.java:3997)
- locked <0x085130da> (a com.android.server.am.ActivityManagerService)
at com.android.server.apphibernation.AppHibernationService.hibernatePackageForUser(AppHibernationService.java:379)
at com.android.server.apphibernation.AppHibernationService.setHibernatingForUser(AppHibernationService.java:290)
- locked <0x0e0620b1> (a java.lang.Object)
at
com.android.server.apphibernation.AppHibernationService$AppHibernationServiceStub.setHibernatingForUser(AppHibernationService.j
at android.apphibernation.IAppHibernationService$Stub.onTransact(IAppHibernationService.java:134)
at android.os.Binder.execTransactInternal(Binder.java:1179)
at android.os.Binder.execTransact(Binder.java:1143)

"Binder:2036_7" prio=5 tid=129 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x13e059d0 self=0xb4000075ef0cd090
| sysTid=2488 nice=-10 cgrp=foreground sched=0/0 handle=0x7370d1dcb0
| state=S schedstat=( 838259745 949143643 2399 ) utm=69 stm=14 core=7 HZ=100
| stack=0x7370c26000-0x7370c28000 stackSize=991KB
| held mutexes=
at com.android.server.apphibernation.AppHibernationService.isHibernatingGlobally(AppHibernationService.java:246)
- waiting to lock <0x0e0620b1> (a java.lang.Object) held by thread 128
at
com.android.server.apphibernation.AppHibernationService$LocalService.isHibernatingGlobally(AppHibernationService.java:743)
...
at com.android.server.wm.ActivityClientController.activityPaused(ActivityClientController.java:165)
- locked <0x05357b79> (a com.android.server.wm.WindowManagerGlobalLock)
at android.app.IActivityClientController$Stub.onTransact(IActivityClientController.java:540)
at com.android.server.wm.ActivityClientController.onTransact(ActivityClientController.java:111)
at android.os.Binder.execTransactInternal(Binder.java:1179)
at android.os.Binder.execTransact(Binder.java:1143)

发现是system_server死锁了：Binder:2036_8和Binder:2036_7形成死锁

Thread mian waiting 0x085130 what hold by thread Binder:2036_8
Thread Binder:2036_8 hold 0x0e0620b1 and waiting 0x05357b79
Thread Binder:2036_7 hold 0x05357b79 and waiting 0x0e0620b1

一般对于死锁问题分析思路：

1.调查两个线程对应的调用栈逻辑是否存在异常调用，是否是修改导致的，通过review Commit record，未发现setHibernatingForUser和activityPaused方法对应逻辑存在修改，调用逻辑比对同Google原生代码一致。
2.调查两个线程对应的调用(binder)对端逻辑是否正常，是否存在异常调用
两个线程都是Binder调用：
AppHibernationService.setHibernatingForUser对应的对端是com.google.android.permissioncontroller，是GMS包中管理应用权限的应用，无源代码。
ActivityClientController.activityPaused对应的对端是com.google.android.setupwizard，是GMS包中第一次开机时的开机向导应用，无源代码。

头疼了，两个都没有源码，不确定是不是异常状态导致的调用异常，只能接着往下分析了，首先这里已经明确了是setHibernatingForUser和activityPaused方法起冲突，也就是在开机向导应用和后台运行的GooglePermissionController产生冲突。

虽然无源码分析，但我们知道其中activityPaused方法为Activity切换时系统调用的方法，不是指某一特定Activity的行为，而是任何Activity切换都会进行此调用，也就是说可能并不是只有开机向导存在此问题，这也可能发生在别的应用使用过程中，后续压测能在其他界面复现这个问题也验证这一观点。

虽然通过log分析开机向导界面activity切换确实比较频繁，但另外两家运营商的开机向导同样频繁却没有反馈这一问题，即这个activityPaused的调用不是主要原因，接下来看这个setHibernatingForUser方法，经过调查发现这个方法涉及到Google在Android S上新添加的APP
Hibernation机制。
https://developer.android.google.cn/topic/performance/app-hibernation?hl=en
大家可以进去看看，这边总结下：APP Hibernation 应用休眠机制，就是每15天执行一次检查，若存在一个应用90days以上未被使用（没有和用户产生互动，包括没有弹窗，通知，用户没有点开应用等），系统就会将这个应用设置为休眠状态，此时系统会进行一些回收权限，清理缓存等操作。

客户是从7/15号开始陆续反馈此类问题，而版本编译时间巧了为4/17号 4/17~7/15正好超过90天，符合这个条件，顺着这条线，继续往下分析。通过反编译GooglePermissionController代码，虽然反编译的代码阅读困难，但结合冻屏时GooglePermissionController的堆栈信息
确定：存在HibernationJobService Job进行了设置休眠的操作。

Cmd line: com.google.android.permissioncontroller
"main" prio=5 tid=1 Native
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x70e70b80 self=0xb40000780fbd87b0
| sysTid=5045 nice=0 cgrp=background sched=0/0 handle=0x79cd9e04f8
| state=S schedstat=( 3325023354 2776504421 10391 ) utm=212 stm=120 core=5 HZ=100
| stack=0x7fe0e23000-0x7fe0e25000 stackSize=8188KB
| held mutexes=
native: #00 pc 00000000000a1c8c /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+12)
native: #01 pc 000000000005b8d4 /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
native: #02 pc 0000000000052f54 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+292)
native: #03 pc 0000000000054190 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*,
int*)+64)
native: #04 pc 0000000000053ed4 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int,
android::Parcel const&, android::Parcel*, unsigned int)+224)
native: #05 pc 000000000004ba1c /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel
const&, android::Parcel*, unsigned int)+196)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(BinderProxy.java:571)
at android.apphibernation.IAppHibernationService$Stub$Proxy.setHibernatingForUser(IAppHibernationService.java:223)
at android.apphibernation.AppHibernationManager.setHibernatingForUser(AppHibernationManager.java:78)
at com.android.permissioncontroller.hibernation.HibernationController.hibernateApps(HibernationController.kt:67)
at
com.android.permissioncontroller.hibernation.HibernationJobService$onStartJob$1.invokeSuspend(HibernationPolicy.kt:566)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.app.ActivityThread.main(ActivityThread.java:7879)
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:1009)

反编译的代码我就不贴了，大家可以自己尝试下顺着看堆栈是能看懂的。
OK，我们结合工厂反馈的信息重新梳理下问题发生的过程：

这批机器在工厂生产时烧入的版本是4/17号编译的版本，所以系统在第一次开机时在未同步时间之前，记录到的最后一次使用应用的时间就是4/17
这批机器在产线上存在大约3分钟时长的开机待机，GooglePermissionController下发了Job任务，并且任务存储到JobScheduler中了，在合适的时机触发
7/15号之后这批机器到用户手中，正常插卡开机，系统同步时间到实际时间，然后用户过开机向导，若此时Job启动，发现7/15-4/17>90days，触发休眠应用机制，和activity跳转概率性起冲突导致死锁，表现就是开机向导界面卡死

结论：Google的APP Hibernation机制和正常的activity跳转概率性起冲突

因为此问题复现条件过于苛刻，要大于90天以上才有概率复现，并且此为S上的新机制，没有相关的测试用例支撑，所以测试过程中并未发现此问题，导致直到用户手中才报出问题。并且这个hibernation Job每隔15days就会执行一遍，也就是说即使用户手上的机器这次执行没出问题，但在15天以后还是有一定概率出这个问题，相当于这个炸弹一直存在，不定时爆炸，急需解决

OK，到这里，基本摸清了问题复现的原因了，那么怎么修改呢？

对于一般的死锁问题，解决方案都是将其中并不强相关的调用过程通过新另一个线程的方式执行解决，hibernation并不需要即时性的进行操作，所以只要将hibernation的执行过程移到另一个线程中就行了，这样循环持锁的链条就断了，Google也确实是这么干的，这个问题就是Android S上hibernation机制遗留的一个BUG，对比T的代码，Google在T上已经修复这个问题，S上目前提供了一个规避方案：
https://android-review.googlesource.com/c/platform/frameworks/base/+/1935380
Google的解决方案其实比较简单，就是在setHibernatingForUser方法中通过线程池在另一线程中进行后续hibernatePackageForUser的调用，避免后续死锁产生。

		if (isHibernating) {
- 			hibernatePackageForUser(packageName, userId, pkgState);
+ 			mBackgroundExecutor.execute(() -> hibernatePackageForUser(packageName, realUserId));
		} else {
- 			unhibernatePackageForUser(packageName, userId, pkgState);
+ 			mBackgroundExecutor.execute(
+ 			() -> unhibernatePackageForUser(packageName, realUserId));
+		 	pkgState.lastUnhibernatedMs = System.currentTimeMillis();
		}

验证

好了，说了这么多，解决方案也有了，问题来了，如何验证：
合入Google提供的Patch，这个问题验证起来比较麻烦，因为其中hibernation机制触发的硬性要求就是应用未使用的时间要超过90days，实际操作过程中不能真的等这么多天去验证问题的，虽然可以通过手动设置时间满足条件，但测试效率较差，并且JobScheduler中还有很多不确定因素会影响Job的执行。

思路：既然这个问题是setHibernatingForUser和activityPaused这两个方法的调用起冲突，那我们就保证能人为的频繁触发这两个方法的调用即可。

对此设计了一个较为高效的验证方案：
问题的复发概率不高，为了提高复发效率，需要频繁触发调用，开发了一个快速跳转Avtivity的测试应用来模拟实际的应用切换场景，主要逻辑是startActivity方法在20S内不停切换Activity以此来触发activityPaused调用。

编写此冻屏问题的测试用例给到测试：

刷机正常启动
在开机向导界面，使用命令过滤logcat判断Job任务是否第一次启动
（因为hibernation 是通过JobScheduler excute Job来执行的，JobScheduler调度时间无法控制，这里等待Job执行一次）

adb shell ‘logcat | grep -i HibernationPolicy’

如果有类似如下的日志打印，则说明机器已下发Job并且第一次执行了
如果没有，请继续等待。如果3mis内没有log，记录数据，开始新一轮测试。

07-25 20:44:01.796 4031 4031 I HibernationPolicy: onStartJob
07-25 20:44:01.819 4031 4031 I HibernationPolicy: Skipping auto revoke first run when scheduled by system

Job起来后，设置unused_threshold_millis为1000，回读这个值，确认修改成功
（这是Google为方便调试开放的接口，原来的不使用应用的阈值是90days，这里改成1000ms，方便hibernation触发。因为下面的命令手动执行hibernation job，这里不需要修改15天一次的验证频率auto_revoke_check_frequency_millis）

adb shell device_config put permissions auto_revoke_unused_threshold_millis2 1000
adb shell device_config get permissions auto_revoke_unused_threshold_millis2

安装测试app并启动测试Activity，点击屏幕上的开始测试按钮，开始20S Activity自动跳转
（安装并打开测试应用，让应用不断调用activityPaused方法）

adb install autoJumpActivity.apk;adb shell am start com.tis.myapplication/.TestActivity

紧接上一个，立即执行命令强制jobscheduler执行job任务（通过cmd命令强制执行hibernation Job保证调用setHibernatingForUser方法）

adb shell cmd jobscheduler run -u 0 -f
com.google.android.permissioncontroller 2

30S后，观察手机是否可以正常按Power灭屏（如果触发了冻屏，则无法正常亮灭屏）
为保证验证方法的有效性，需要进行对比验证：
在未合入Patch的版本上进行验证 44/50 复现问题
在已合入Patch的版本上进行验证 0/50 未复现问题
至此问题解决。

最后的最后：

虽然问题解决了，但是客户非常好奇为什么同样的机器，不同的运营商复现概率差别如此大，其他两家运营商基本没有上报这个问题，这还需进一步调查。
分析GooglePermissionController代码发现，此hibernation的任务是通过JobScheduler进行运行的，JobScheduler是Android 5.0上新添加的API，JobScheduler 机制中把每个需要后台的业务抽象为一个Job，对于这些Job系统会收集起来，选择一个它认为合适的时机进行统一唤醒运行，来提高资源的利用率和减少不必要的唤醒，从而提高性能，节省电源。这个hibernation job启动的时间高度不可控，统计数据上成离散状，有时开机向导显示5~10S就能启动，有时却得1min以外，并且这个job的启动还会受到thermal的影响，同一台机器因为大量测试，机器发热，还会推迟job的运行，给测试压测增加了不可控因素，需排除这些干扰。
经过统计发现：70%都能在60S内完成，对比3家的数据统计发现：出问题运营商的机器相比较另外两家 hibernation Job启动的并没有多大区别。

最终由客户端在实际的用户环境下按照实际的用户插卡情况复现问题分析发现：
若插入对应的SIM卡，出问题的运营商在开机向导第一个界面识卡准备时间较短，很快就能显示WelcomeScreen界面，之后Hibernation Job才启动，若此时进行开机向导设置，大量的activity切换就有很大概率和hibernaion起冲突，造成死锁，机器卡死重启；而另外两家运营商存在eSim配置，在第一个界面识卡准备时间较长(多了25S左右)，当显示出WelcomeScreen界面时，后台的Hibernation Job已执行完了，此时再有activity切换就复现不出问题，概率明显下降。