上午的寧靜被一個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/0x7ckernel: SyS_epoll_wait+0x2a0/0x32ckernel: SyS_epoll_pwait+0xa4/0x120kernel: cpu_switch_to+0x48/0x4cnative: #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中，這樣第二次的時候因為相等了就不會再走升級流程了，所以就不會卡白米了

總結

以上是生活随笔為你收集整理的由ContactsProvider的升级引发的OTA首次开机卡白米问题分析的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。