settings put/get 断言失败
用例过程
目前遇到Android O上关于settings put/get失败的用例很多，看了很多个用例，耗时很久
run cts –abi arm64-v8a -m CtsTextTestCases -t
android.text.format.cts.DateFormatTest#test_is24HourFormat
–bugreport-on-failure
分析
日志附件
日志查询关键字：
time_12_24|test_is24HourFormat|
MemoryIntArray|System.getStringForUser|is24HourFormat|insertSystemSetting|getSystemSetting|SettingsProvider
正常机型的日志如下：
Line 1817: 01-01 00:01:39.059 1637 1637 E GenerationRegistry: Created backing store android.util.MemoryIntArray@56
Line 5734: 01-01 00:01:42.165 1637 1637 I GenerationRegistry: backingStore = android.util.MemoryIntArray@56
Line 13208: 01-01 00:01:44.793 1637 1637 I GenerationRegistry: backingStore = android.util.MemoryIntArray@56用例失败的机型出现两个MemoryIntArray，日志如下，
Line 15921: 01-01 08:04:38.108 2609 3035 E GenerationRegistry: Created backing store android.util.MemoryIntArray@fc
Line 15922: 01-01 08:04:38.108 2609 3035 I GenerationRegistry: backingStore = android.util.MemoryIntArray@fc
Line 28200: 01-01 08:08:41.169 2609 2946 I GenerationRegistry: backingStore = android.util.MemoryIntArray@50
Line 28253: 01-01 08:08:41.293 2609 3200 I GenerationRegistry: backingStore = android.util.MemoryIntArray@fc一个MemoryIntArray对应一个GenerationRegistry，对应一个SettingsRegistry
通过和其他同样Android O机型的日志对比发现，MemoryIntArray在失败用例的机型上每次都有两个实例
MemoryIntArray->GenerationRegistry->SettingsRegistry
这三者是一一对应的关系，而SettingsRegistry是在SettingsProvider的onCreat()创建的，那么是SettingsProvider创建了两次？
那SettingsProvider在哪被创建的？在onCreate中添加日志打印
一开始使用的是android.util.Log打印，日志打不出来，可能有丢失，就以为只创建了一次
（1）改用Slog打印
（2）不每次重启机器，改用stop、start这样方式启动system_server
（3）logcat的ring buffer设置大点
终于走上正路，窥得真貌。第一次创建时候在09:22:24，这是系统在刚启动时通过startOtherService()调用的installSystemProviders，这个是正常的。
第一行日志的ActivityManager_MU告诉我们SettingsProvider是单例的，但是在09:22:41为啥又创建了一遍么？
01-01 09:22:24.235 11247 11247 V ActivityManager_MU: isSingleton(system, ApplicationInfo{f87dbf9 com.android.providers.settings}, com.android.providers.settings.SettingsProvider, 0x40100000) = true
01-01 09:22:24.235 11247 11247 V ActivityManager_MU: generateApplicationProvidersLocked, cpi.uid = 1000
01-01 09:22:24.236 11247 11247 V ActivityManager_MU: isSingleton(system, ApplicationInfo{d74b73e android}, com.android.server.am.DumpHeapProvider, 0x40000000) = true
01-01 09:22:24.236 11247 11247 V ActivityManager_MU: generateApplicationProvidersLocked, cpi.uid = 1000
01-01 09:22:24.236 11247 11247 I ActivityThread: Pub settings: com.android.providers.settings.SettingsProvider
01-01 09:22:24.236 11247 11247 D ActivityThread: Loading provider settings: com.android.providers.settings.SettingsProvider
01-01 09:22:24.253 11247 11247 V ActivityThread: Instantiating local provider com.android.providers.settings.SettingsProvider
01-01 09:22:24.257 11247 11247 E SettingsProvider: onCreate
01-01 09:22:24.257 11247 11247 E SettingsProvider: java.lang.Exception
01-01 09:22:24.257 11247 11247 E SettingsProvider: at com.android.providers.settings.SettingsProvider.onCreate(SettingsProvider.java:321)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at android.content.ContentProvider.attachInfo(ContentProvider.java:1919)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at android.content.ContentProvider.attachInfo(ContentProvider.java:1894)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at android.app.ActivityThread.installProvider(ActivityThread.java:6286)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at android.app.ActivityThread.installContentProviders(ActivityThread.java:5852)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at android.app.ActivityThread.installSystemProviders(ActivityThread.java:6461)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at com.android.server.am.ActivityManagerService.installSystemProviders(ActivityManagerService.java:12127)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at com.android.server.SystemServer.startOtherServices(SystemServer.java:804)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at com.android.server.SystemServer.run(SystemServer.java:399)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at com.android.server.SystemServer.main(SystemServer.java:263)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at java.lang.reflect.Method.invoke(Native Method)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240)
01-01 09:22:24.257 11247 11247 E SettingsProvider: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:828)
01-01 09:22:24.266 11247 11247 I SettingsProvider: key=805306368
----------------------------------------------------------------------------------------
01-01 09:22:41.799 11247 11247 W SettingsProvider: onCreate
01-01 09:22:41.799 11247 11247 W SettingsProvider: java.lang.Exception
01-01 09:22:41.799 11247 11247 W SettingsProvider: at com.android.providers.settings.SettingsProvider.onCreate(SettingsProvider.java:333)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.content.ContentProvider.attachInfo(ContentProvider.java:1919)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.content.ContentProvider.attachInfo(ContentProvider.java:1894)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.app.ActivityThread.installProvider(ActivityThread.java:6286)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.app.ActivityThread.installContentProviders(ActivityThread.java:5852)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.app.ActivityThread.handleInstallProvider(ActivityThread.java:3124)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1814)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.os.Handler.dispatchMessage(Handler.java:105)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.os.Looper.loop(Looper.java:164)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at com.android.server.SystemServer.run(SystemServer.java:424)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at com.android.server.SystemServer.main(SystemServer.java:263)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at java.lang.reflect.Method.invoke(Native Method)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240)
01-01 09:22:41.799 11247 11247 W SettingsProvider: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:828)
01-01 09:22:41.801 2169 2169 E ServiceManager: add_service('settings',a3) uid=1000 - ALREADY REGISTERED, OVERRIDE
01-01 09:22:41.801 2169 2169 I ServiceManager: service 'settings' died继续根据09:22:41时的堆栈进行分析，为啥会通过Message再次创建一遍SettingsProvider呢？
01-01 09:22:41.799 11247 11247 W SettingsProvider: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1814)
继续对比正常机型的日志，正常机型在finishUserUnlocking后也发送了SYSTEM_USER_UNLOCK_MSG消息，也走消息处理到installEncryptionUnawareProviders()执行Installing ContentProviderInfo
Line 24020: 12-31 19:00:47.405 3828 3828 V ActivityThread: Instantiating local provider com.android.providers.settings.SettingsProviderLine 24021: 12-31 19:00:47.406 3828 3828 E SettingsProvider: onCreateLine 27266: 12-31 19:00:51.148 3828 3844 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 27371: 12-31 19:00:51.170 3828 3851 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 27384: 12-31 19:00:51.173 3828 3851 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 27396: 12-31 19:00:51.174 3828 3851 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 27422: 12-31 19:00:51.176 3828 3851 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 27455: 12-31 19:00:51.196 3828 3851 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 27542: 12-31 19:00:51.399 3828 3851 I WindowManager: checkBootAnimationComplete: Animation complete!Line 27553: 12-31 19:00:51.400 3828 3851 I WindowManager: checkBootAnimationComplete: Animation complete!Line 27569: 12-31 19:00:51.430 3828 3851 D ActivityManager: Finishing user boot 0Line 28013: 12-31 19:00:51.811 3828 3851 W ActivityManager: finishUserUnlockingLine 28015: 12-31 19:00:51.811 3828 3851 W ActivityManager: at com.android.server.am.UserController.finishUserUnlocking(UserController.java:332)
……Line 28508: 12-31 19:00:52.537 3828 3844 W ActivityManager: Installing ContentProviderInfo{name=com.google.android.inputmethod.latin.inputcontent className=com.google.android.apps.inputmethod.libs.search.gif.InputContentProvider}Line 28517: 12-31 19:00:52.537 3828 3844 V ActivityManager: Installing ContentProviderInfo{name=com.google.android.inputmethod.latin.inputcontent className=com.google.android.apps.inputmethod.libs.search.gif.InputContentProvider}
对比异常机型的日志发现执行Installing ContentProviderInfo，但是processlist列表中有.
{name=settings className=com.android.providers.settings.SettingsProvider}，从而导致创建了两遍
Line 790: 01-01 09:50:22.977 18037 18037 V ActivityThread: Instantiating local provider com.android.providers.settings.SettingsProviderLine 791: 01-01 09:50:22.979 18037 18037 E SettingsProvider: onCreateLine 64921: 01-01 09:50:33.207 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 64987: 01-01 09:50:33.220 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 65003: 01-01 09:50:33.222 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 65020: 01-01 09:50:33.224 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 65353: 01-01 09:50:33.361 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 65705: 01-01 09:50:33.427 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 65782: 01-01 09:50:33.628 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 66147: 01-01 09:50:33.829 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 66302: 01-01 09:50:33.939 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 66384: 01-01 09:50:34.043 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 66659: 01-01 09:50:34.218 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 66939: 01-01 09:50:34.420 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67074: 01-01 09:50:34.622 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67447: 01-01 09:50:34.822 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67605: 01-01 09:50:34.880 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67686: 01-01 09:50:34.928 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67701: 01-01 09:50:34.932 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67713: 01-01 09:50:34.934 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67778: 01-01 09:50:34.971 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67825: 01-01 09:50:34.985 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67904: 01-01 09:50:35.061 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 67939: 01-01 09:50:35.077 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 68005: 01-01 09:50:35.185 18037 18073 I WindowManager: checkBootAnimationComplete: Waiting for anim completeLine 68223: 01-01 09:50:35.386 18037 18073 I WindowManager: checkBootAnimationComplete: Animation complete!Line 68234: 01-01 09:50:35.387 18037 18073 I WindowManager: checkBootAnimationComplete: Animation complete!Line 68427: 01-01 09:50:35.411 18037 18073 D ActivityManager: Finishing user boot 0Line 68471: 01-01 09:50:35.648 18037 18073 W ActivityManager: finishUserUnlockingLine 68473: 01-01 09:50:35.648 18037 18073 W ActivityManager: at com.android.server.am.UserController.finishUserUnlocking(UserController.java:333)
……Line 69450: 01-01 09:50:35.905 18037 18065 V ActivityManager: cts skip Installing ContentProviderInfo{name=com.jamdeo.data.thumbnailengine.channels;com.jamdeo.data.thumbnailengine.events className=com.jamdeo.data.ThumbnailEngine}Line 69461: 01-01 09:50:35.906 18037 18065 V ActivityManager: cts skip Installing ContentProviderInfo{name=com.jamdeo.data.epgdata className=com.*.livetv.service.data.epg.EpgData}Line 69472: 01-01 09:50:35.906 18037 18065 V ActivityManager: cts skip Installing ContentProviderInfo{name=com.android.calendar className=com.android.providers.calendar.CalendarProvider2}Line 69488: 01-01 09:50:35.907 18037 18065 V ActivityManager: cts skip Installing ContentProviderInfo{name=com.*.keylab.speech.CoreProvider.up02 className=com.*.keylab.speech.core.CoreProvider}Line 69528: 01-01 09:50:35.908 18037 18065 V ActivityManager: cts skip Installing ContentProviderInfo{name=com.android.server.heapdump className=com.android.server.am.DumpHeapProvider}Line 69555: 01-01 09:50:35.910 18037 18065 V ActivityManager: cts skip Installing ContentProviderInfo{name=settings className=com.android.providers.settings.SettingsProvider}……Line 70328: 01-01 09:50:36.032 18037 18037 V ActivityThread: Instantiating local provider com.android.providers.settings.SettingsProviderLine 70337: 01-01 09:50:36.034 18037 18037 E SettingsProvider: onCreateLine 70924: 01-01 09:50:36.163 18037 18037 W SettingsProvider: onCreate为啥Process列表中多个了一个{name=settings className=com.android.providers.settings.SettingsProvider}
初步怀疑我们机型启动时间太长，get时候get到SettingsProvider
后面有精力再查吧，查到这就用了很久
注意事项
（1）跟随文件的日志打印方式，文件用Slog同样自己要用Slog
（2）使用stop、start重启system_server
（3）放大logcat ring buffer