由ContactsProvider的升级引发的OTA首次开机卡白米问题分析

上午的宁静被一个OTA卡白米问题打破，接下来不断有人反馈不同机型都复现了OTA后卡白米，10.9号OTA升级到10.10号的版本，全机型问题，线刷没有问题，好吧，接下来就根据这些信息开始初步分析log吧！

初步分析

查看问题log，发现Boot phase到了PHASE_SYSTEM_SERVICES_READY



并且走到了PackageManagerService.systemReady

10-10 15:26:47.762  3152  3152 W ContextImpl:
Calling a method in the system process without a qualified user:
android.app.ContextImpl.bindService:1295
miui.provider.ExtraGuard.init:69
com.android.server.pm.PackageManagerServiceInjector.initExtraGuard:429
com.android.server.pm.PackageManagerService.systemReady:15195
com.android.server.SystemServer.startOtherServices:1133

继续看log发现以下异常信息

10-10 15:27:07.784  3152  3221 E ActivityManager:
Attempt to launch receivers of broadcast intent Intent
{ act=android.net.conn.DATA_ACTIVITY_CHANGE (has extras) } before boot completion

这说明系统启动没有正常完成，ActivityManager的状态还没有就绪，难道system server的启动流程出现了异常？

赶紧打出system server的traces看一下

"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x75f14fb8 self=0x558db1ec10
| sysTid=3152 nice=-2 cgrp=default sched=0/0 handle=0x7fb6a3afc8
| state=S schedstat=( 5043600992 157397768 10523 ) utm=367 stm=137 core=5 HZ=100
| stack=0x7fe85de000-0x7fe85e0000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0x70/0x7c
kernel: SyS_epoll_wait+0x2a0/0x32c
kernel: SyS_epoll_pwait+0xa4/0x120
kernel: cpu_switch_to+0x48/0x4c
native: #00 pc 0000000000069be4  /system/lib64/libc.so (__epoll_pwait+8)
native: #01 pc 000000000001cca4  /system/lib64/libc.so (epoll_pwait+32)
native: #02 pc 000000000001be88  /system/lib64/libutils.so (_ZN7android6Looper9pollInnerEi+144)
native: #03 pc 000000000001c268  /system/lib64/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+80)
native: #04 pc 00000000000d2580  /system/lib64/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+48)
native: #05 pc 000000000000082c  /data/dalvik-cache/arm64/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+144)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:323)
at android.os.Looper.loop(Looper.java:135)
at com.android.server.SystemServer.run(SystemServer.java:299)
at com.android.server.SystemServer.main(SystemServer.java:181)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:738)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:628)

看起来主线程没有什么异常，已经进入主消息循环了，也就是说startOtherServices已经走完了，都走完了为啥activitymanager的状态还没有就绪？看代码吧







已知PMS的systemready已经走了，整个startOtherServices也走完了，所以AMS的systemready一定调用了，但是调用了为什么没有ready？

仔细看上面的代码可以看到一些端倪，因为调用AMS的systemready时传入的是一个runnable，runnable里面是启动systemui并通知一堆系统service running，从代码中可以看到这个runnable是在systemready函数的后半部分执行的，而当前出问题的状态是这个runnable并没有执行。

除了这个runnable之外还有一个关键的状态就是AMS的mSystemReady，通过am start发现log中打出来AMS没有ready的信息，产生这种状态的唯一的可能就是在AMS的systemready函数中没有正常执行完毕。

查看代码发现OTA后第一次调用到AMS的systemready之后mDidUpdate为false，mWaitingUpdate也是false，继续往下走到deliverPreBootCompleted，这里又传入了一个runnable，非常关键的一步，如果是OTA后第一次调用deliverPreBootCompleted会返回true给mWaitingUpdate，以为在deliverPreBootCompleted里面会发送ACTION_PRE_BOOT_COMPLETED给所有注册的receiver，并且添加FLAG_RECEIVER_BOOT_UPGRADE，在发送广播的时候就从同步调用变成了异步，返回后继续执行，mWaitingUpdate为true，然后return出去，mSystemReady在这一次没有机会设置为true，那什么时候设置呢？AMS ready的剩余代码什么时候执行呢？带着问题继续看代码

深入分析

还记得上面调用deliverPreBootCompleted时传入的runnable吗？当OTA后第一开机的ACTION_PRE_BOOT_COMPLETED广播发送给所有的receiver之后就会调用这个runnable，它里面会将mDidUpdate置为true并再次调用AMS的systemready函数，这次会正常执行完所以的流程，包括设置mSystemReady等状态为true，调用startOtherServices传入的runnable启动systemui和notify systemservice running，启动home等，但是现在这些都没有做。。。好吧，一言不合说不做就不做，Android就是任性！

赶紧看看它为啥没做，deliverPreBootCompleted也调用了，runnable也传过去，那问题就出在deliverPreBootCompleted里面的广播发送了？要想知道，还得看代码和log









好了，代码和log看到这里，基本定位到了大概原因，这个广播是有序发送的，并且是显式指定component的方式，每个发送完了都会把结果给PreBootContinuation并调用performReceive发送下一个，如果都发完了会把之前传入的runnable post 到消息队列里面，显而易见，没有走到post这一步，也就是说上面的广播在发送过程中出问题了，出什么问题了呢？还好这个问题可以必现，赶紧复现追一下代码，发现需要给6个receiver发送广播，出问题时只发送到第二个contactsproviders的时候就断了，log也对应了这一点，并且log中发现了contactsproviders升级数据库版本的信息，同时又仔细看了一下system server的trace，发现有个关于getprovider的线程不是太正常，一直处于waiting状态



contactsproviders执行之后一直没有完成，而AMS这么又有一个binder 线程一直在等待provider，这是不是有某种对应关系？赶紧看一下contactsproviders所在进程的traces，发现真有关系，在ContactsUpgradeReceiver里面执行数据库升级之后去请求一个content provider的时候block住了



真是踏破铁鞋无觅处，得来好不费功夫啊，system server一直在等待你完成通知它，你却在这睡大觉，但是又引来一个问题，这里的调用为什么会一直block？继续看代码，断点追代码，在getContentProviderImpl里发现了蹊跷，为contactsprovider 请求的yellowpage provider去startProcessLocked的时候由于system还没有ready所以start的操作被hold住了，所以导致contactsprovider的query操作被一直block



通过分析代码发现，不允许yellowpageprovider的进程起来是合理的，不合理的是contactsprovider在OTA过第一次开机upgrade的过程中不合理的请求了query yellowpageprovider，从而block整个系统启动，导致卡白米

后续问题

到这里可能有细心的同学会问，为什么之前OTA没问题，今天就有问题了？

原因是contactprovider的数据库版本有升级，在升级的同时触发了T9索引重建，重建的过程中用到了yellowpageprovider，来一下change再配合上面的traces可能会更直观



这个索引重建不是不能做，而是不能在OTA第一次开机过程中调用upgradereceiver的做，可以等正常开机后，BOOT_COMPLETED广播发出去的时候再触发做

可能还有更细心的同学会问，为什么卡住之后再重启一下就好了呢？

这是因为在ContactsUpgradeReceiver中会先判断DB VERSION，第一次因为升级了所以不相等，就走升级流程，升级之前先把最新的DB VERSION put到了preference中，这样第二次的时候因为相等了就不会再走升级流程了，所以就不会卡白米了