声明

最近客户返修了一个盒子（Android4.2系统），问题现象表现为盒子开机后，系统的开机动画不断循环播放，一直没进Launcher，而且是必现问题，每次开机都是如此。

同样的ROM，同样硬件类型的盒子，其他盒子都复制不出来，因此刚开始怀疑是OTA升级异常导致ROM系统文件丢失，进而导致开机启动异常。

后来确认过，客户升级使用的OTA包是没有问题的，从升级日志上来看也是OK的。为了排除ROM文件导致问题的可能性，我还一一将boot 、kernel、system、recovery各个分区使用分区刷机工具重新刷机了，问题依旧...

幸运的是，盒子接上内部串口线，还能进入命令行模式，各种系统命令如ps,lsof,top，logcat 都能正常使用，这样情况还不算最糟。（之前排查开机黑屏问题，什么工具都用不了，各种想哭...）

趁现场环境还在，于是果断先把logcat日志复现了一份。

首先，我们知道，按照Android正常的开机启动流程，system_server进程起来之后，会把一些系统重要的服务逐个拉起来，比如：PowerManagerService、ActivityManagerService、DisplayManagerService、PackageManagerService，这个从系统的logcat日志也可以看出来，大致如下所示：

11-07 08:39:17.790 I/SystemServer(  666): Entered the Android system server!

11-07 08:39:17.800 I/installd(  103): new connection

11-07 08:39:17.800 I/SystemServer(  666): Enabled StrictMode logging for UI Looper

11-07 08:39:17.800 I/SystemServer(  666): Waiting for installd to be ready.

11-07 08:39:17.800 I/SystemServer(  666): Enabled StrictMode logging for WM Looper

11-07 08:39:17.800 I/Installer(  666): connecting...

11-07 08:39:17.800 I/SystemServer(  666): Entropy Mixer

11-07 08:39:17.830 E/RKPowerHAL(  666): Error opening /sys/devices/system/cpu/cpufreq/interactive/boostpulse: No such file or directory

11-07 08:39:17.830 I/SystemServer(  666): Power Manager

11-07 08:39:17.830 I/SystemServer(  666): Activity Manager

11-07 08:39:17.840 I/ActivityManager(  666): Memory class: 128

11-07 08:39:17.890 D/dalvikvm(  666): GC_CONCURRENT freed 246K,7% free 4291K/4576K,paused 3ms+1ms,total 15ms

11-07 08:39:17.900 I/SystemServer(  666): Display Manager

11-07 08:39:17.900 I/SystemServer(  666): Telephony Registry

11-07 08:39:17.900 I/ActivityManager(  666): Enabled StrictMode logging for AThread's Looper

11-07 08:39:17.900 I/SystemServer(  666): Scheduling Policy

11-07 08:39:17.910 I/DisplayManagerService(  666): Display device added: DisplayDeviceInfo{"内置屏幕": 1920 x 1080,60.000004 fps,density 160,159.89508 x 160.42105 dpi,touch INTERNAL,FLAG_DEFAULT_DISPLAY,FLAG_ROTATES_WITH_CONTENT,FLAG_SECURE,FLAG_SUPPORTS_PROTECTED_BUFFERS,rotation 0,type BUILT_IN,address null}

11-07 08:39:17.920 I/SystemServer(  666): Package Manager

11-07 08:39:18.580 D/dalvikvm(  666): GC_EXPLICIT freed 332K,8% free 4862K/5252K,paused 2ms+2ms,total 25ms

11-07 08:39:18.590 I/SystemServer(  666): User Service

11-07 08:39:18.590 I/SystemServer(  666): Account Manager

11-07 08:39:18.590 I/SystemServer(  666): Content Manager

11-07 08:39:18.590 I/SystemServer(  666): System Content Providers

11-07 08:39:18.690 I/libsuspend(  666): Selected early suspend

11-07 08:39:18.690 I/libsuspend(  666): Starting early suspend unblocker thread

11-07 08:39:18.690 I/SystemServer(  666): Lights Service

11-07 08:39:18.690 I/SystemServer(  666): Battery Service

11-07 08:39:18.690 I/SystemServer(  666): Vibrator Service

11-07 08:39:18.700 D/PermissionCache(   99): checking android.permission.ACCESS_SURFACE_FLINGER for uid=1000 => granted (316 us)

11-07 08:39:18.700 D/SurfaceFlinger(   99): Screen acquired,type=0 flinger=0x416f7318

11-07 08:39:18.700 D/SurfaceFlinger(   99):  screen was prevIoUsly acquired

11-07 08:39:18.700 D/AlarmManagerService(  666): Kernel timezone updated to -480 minutes west of GMT

11-07 08:39:18.700 I/SystemServer(  666): Alarm Manager

11-07 08:39:18.700 I/SystemServer(  666): Init Watchdog

11-07 08:39:18.700 I/SystemServer(  666): Input Manager

11-07 08:39:18.700 I/InputManager(  666): Initializing input manager,mUseDevInputEventForAudioJack=false

11-07 08:39:18.700 I/SystemServer(  666): Window Manager

而出问题的盒子，logcat日志而不尽相同，通过对比正常日志，发现在system_server启动阶段，日志稍微不同：

11-07 14:13:23.780 I/SystemServer(  669): Entered the Android system server!

11-07 14:13:23.780 I/SystemServer(  669): Enabled StrictMode logging for UI Looper

11-07 14:13:23.780 I/SystemServer(  669): Waiting for installd to be ready.

11-07 14:13:23.780 I/SystemServer(  669): Enabled StrictMode logging for WM Looper

11-07 14:13:23.780 I/Installer(  669): connecting...

11-07 14:13:23.780 I/SystemServer(  669): Entropy Mixer

11-07 14:13:23.810 E/RKPowerHAL(  669): Error opening /sys/devices/system/cpu/cpufreq/interactive/boostpulse: No such file or directory

11-07 14:13:23.810 I/SystemServer(  669): Power Manager

11-07 14:13:23.810 I/SystemServer(  669): Activity Manager

11-07 14:13:23.820 I/ActivityManager(  669): Memory class: 128

11-07 14:13:23.850 W/UsageStats(  669): Usage stats version changed; dropping （！！！可疑之处！！！！）

11-07 14:13:23.950 D/dalvikvm(  669): GC_CONCURRENT freed 283K,8% free 4211K/4536K,paused 2ms+1ms,total 13ms

11-07 14:13:24.120 D/dalvikvm(  669): GC_CONCURRENT freed 402K,10% free 4210K/4652K,total 11ms

11-07 14:13:24.280 D/dalvikvm(  669): GC_CONCURRENT freed 396K,total 11ms

11-07 14:13:24.440 D/dalvikvm(  669): GC_CONCURRENT freed 403K,total 14ms

11-07 14:13:24.620 D/dalvikvm(  669): GC_CONCURRENT freed 399K,total 12ms

11-07 14:13:25.620 D/dalvikvm(  669): GC_CONCURRENT freed 400K,total 13ms

另外，使用 top 命令查看cpu占用率情况，发现system_server进程 cpu占用率高达 25% ，足足占了一个核的资源！

重新启动几次，发现日志大致相同。因此基本可以确定，问题出在 system_server 的初始化阶段。更具体地讲，从日志上看，system_server在启动 ActivityManagerService 服务之后，便”戛然而止“了，接下来的系统服务都没有拉起来，而是不断打印一堆GC垃圾回收集日志。
但是，如果细心查看日志，会发现，出问题的盒子在不断打印GC日志之前，静悄悄地打印了一条不为人所知的日志：

11-07 14:13:23.850 W/UsageStats(  669): Usage stats version changed; dropping

正常的启动过程并不会打印这条日志，而且在这条日志之后，就开始无穷无尽的打印dalviak GC垃圾收集回收日志，让我不得不怀疑这个地方。

那么，“UsageStatsService” 又是什么鬼？

通过查询资料，大致知道UsageStatsService是Android一个私有service，主要作用是收集用户使用每一个APP的频率、使用时常等，用于统计应用程序的使用情况。

该service 是在ActivityManagerService服务中启动的：

这也刚好验证了我的猜想，问题出在ActivityManagerService服务的启动阶段。既然如此，那就回到UsageStatService 当中来，从以下这句异常日志入手：

Slog.w(TAG,"Usage stats version changed; dropping");

搜索了一下源码，发现该句日志是在UsageStatsService.java文件中一个叫“ readStatsFLOCK ” 的函数调用中打印的：

关于UsageStatsService的工作原理这里不打算深入介绍，我们只需要知道UsageStatsService会在/data/system/usagestats/ 目录下保存一些记录app使用频率和时长的数据文件。类似如下：

ls  /data/system/usagestats/
usage-20161102
usage-20161103
usage-20161108
usage-history.xml

其中：

1./data/system/usagestats/usage-日期” 文件记录的当天的使用记录的数据

2./data/system/usagestats/usage-history.xml文件中读取每个APP中每个Activity最后启动的时间

UsageStatsService服务启动的时候，会去读取并解析这些文件。一般情况下，UsageStatsService取到的ver与 VERSION (常量1007)，通过打日志，发现这里取到的ver居然为0，检查了一下/data/system/usagestats/下面的文件，居然都是零字节的！

猜想：会不会是system_server初始化过程中，UsageStatService解析这些零字节文件时发生了文件操作异常？

于是使用 lsof 命令查看出问题时data分区所有被打开的文件，发现其中就有usage-history.xml ！并且操作该文件的进程恰恰就是system_server！

root@android:/data/system/usagestats #　lsof　| grep data                          
system_se  1283     system   54       ???                ???       ???        ??? /data/system/usagestats/usage-history.xml

基本可以确定是在操作 usage-history.xml 文件时出了问题，如果是简单的文件操作错误，那么理论上cpu占用率不会那么高。除非是文件操作过程中发生死锁或者死循环之类的致使错误。

UsageStatsService服务会在多个地方操作到usage-history.xml 文件，应该单纯从代码上看，并不能快速确定出总理的地方？

@H_210_403@或许可以看看 system_server的调用堆栈，兴许可以给我们留下一些线索...

查看进程堆栈，一种简单而实用的方法就是使用Android自带的DDMS工具。打开DDMS,选中需要查看的进程号，这里选择的自然是 system_server (进程号为1283)，UsageStatsService是由ActivityManager启动的，因此先选中ActivityManager，接下来就查看相应的调用堆栈了。

从函数中调用堆栈信息中，可以看到UsageStatsService相关的堆栈停在了readHistoryStatsFLOCK()，代码370行的地方。

这个时候确实需要查看一下源码了：

	readHistoryStatsFLOCK(AtomicFile file) 函数主要负责解析我们前面说到的usage-history.xml文件。

在JAVA的世界里，解析xml文件有多种方式，不同的解析方式有着各自的优缺点和适用环境。在Android中常见的XML解析器分别为SAX解析器、DOM解析器以及PULL解析器。

这里不具体介绍了，具体可以参考本人以前写的博文：

《Android XML文档解析(一)——SAX解析》 @H_161_502@

@H_161_502@

《Android XML文档解析(二)——DOM解析》 @H_161_502@

@H_161_502@

《Android XML文档解析(三)——PULL解析》 @H_161_502@

@H_161_502@

	这里使用的是PULL解析器，PULL技术是基于事件类型的解析，基本的事件类型有 5 个：

START_DOCUMENT  (常量0，标记文档的开始)
START_TAG (常量2，标记一个标签的开始)
TEXT (常量4，标记一个标签的内容)
END_TAG (常量3，标记一个标签的结束)
END_DOCUMENT (常量1，标记文档的结束)

	
	使用 parser.next() 可以进入下一个元素并触发相应事件。现在，再来看看刚才那段代码：

while (eventType != XmlPullParser.START_TAG) {
    eventType = parser.next();
}
 	从代码上分析，这里用了一个while循环，想要实现的功能是，一旦识别到XML的标签事件（START_TAG），便退出循环，开始下面真正的usage-history.xml解析工作。

但是，此处该码有一个致命的问题：如果待解析的XML文件中到达文件结尾时，还解析不到 START_TAG 事件，便会陷入死循环当中！而一旦进入死循环，System_server便无法启动

其他系统服务，更不会通知系统进入桌面，于是，便有可能导致系统开机后一直停留在开机动画播放阶段，不断循环！

而前面我们说到，该设备usage-history.xml是个零字节，因此问题便出在这里了！ 知道原因，那么，便知道怎么修改了，一旦解析到达文件末尾，还解析不到START_TAG 事件，就应该主动退出while循环：
             while (eventType != XmlPullParser.START_TAG) {		 
+                //PN: fix empty xml file cause death cycle
+                if (eventType == XmlPullParser.END_DOCUMENT) {
+                	Slog.w(TAG,"get END_DOCUMENT tag of xml file,maybe the file is empty,stop parsing");
+                	break;
+                }
                 eventType = parser.next();
             }

 查看了各个历史版本，Android4.4以更低的版本皆存在这样的隐患问题，而Android5.0之后，由于UsageStatsService机制改变，因此已经修复该问题。
usage-history.xml一般情况下都会有内容，因此，触发到死循环的概率很低。但有些情况也可能导致 usage-history.xml为零字节，
比较Android Ext4文件系统的延迟分配（delalloc）功能，该功能网上反馈有有比较大的问题，可能造成数据丢失、0长度等问题，在用户强行断电情况下便可能导致零字节问题。
 
 PS: 解决此类问题的方案就是在分区挂载的时候，禁用延迟分配功能，也就是开启 nodelalloc 选项。

 另外，搜索了整个Android4.2的系统源码，发现还有几处代码也是采用类似的写法，这些地方也是埋了坑的，哪天不小心就会陷入这些死循环，
导致另一个开机白屏问题。因此，也是需要把这些隐患一块修复掉！