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

  1. 云栖社区>
  2. 博客>
  3. 正文

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

宋金时 2016-10-14 15:11:18 浏览1310
展开阅读全文

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

初步分析

查看问题log,发现Boot phase到了PHASE_SYSTEM_SERVICES_READY
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的状态还没有就绪?看代码吧
startOtherServices
systemready
systemready_runnable

已知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

deliverPreBootCompleted
deliverPreBootCompleted_preboot

deliverPreBootCompleted_preboot_receiver

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

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

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

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

后续问题

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

原因是contactprovider的数据库版本有升级,在升级的同时触发了T9索引重建,重建的过程中用到了yellowpageprovider,来一下change再配合上面的traces可能会更直观
change
这个索引重建不是不能做,而是不能在OTA第一次开机过程中调用upgradereceiver的做,可以等正常开机后,BOOT_COMPLETED广播发出去的时候再触发做

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

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

网友评论

登录后评论
0/500
评论
宋金时
+ 关注