声明
版权声明：博文为原创内容，可以转载或引用，但须在明显位置标明原文作者和出处，未经同意不得擅自修改本文内容！博客地址：http://blog.csdn.net/luzhenrong45
最近客户返修了一个盒子（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启动阶段，日志稍微不同：
另外，使用 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_57_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解析器。
这里不具体介绍了，具体可以参考本人以前写的博文：
这里使用的是PULL解析器，PULL技术是基于事件类型的解析，基本的事件类型有 5 个：
START_DOCUMENT (常量0，标记文档的开始) START_TAG (常量2，标记一个标签的开始) TEXT (常量4，标记一个标签的内容) END_TAG (常量3，标记一个标签的结束) END_DOCUMENT (常量1，标记文档的结束)
while (eventType != XmlPullParser.START_TAG) { eventType = parser.next(); }从代码上分析，这里用了一个while循环，想要实现的功能是，一旦识别到XML的标签事件（START_TAG），便退出循环，开始下面真正的usage-history.xml解析工作。
但是，此处该码有一个致命的问题：如果待解析的XML文件中到达文件结尾时，还解析不到 START_TAG 事件，便会陷入死循环当中！而一旦进入死循环，System_server便无法启动
其他系统服务，更不会通知系统进入桌面，于是，便有可能导致系统开机后一直停留在开机动画播放阶段，不断循环！
而前面我们说到，该设备usage-history.xml是个零字节，因此问题便出在这里了！ 知道原因，那么，便知道怎么修改了，一旦解析到达文件末尾，还解析不到@H_986_502@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的系统源码，发现还有几处代码也是采用类似的写法，这些地方也是埋了坑的，哪天不小心就会陷入这些死循环，
导致另一个开机白屏问题。因此，也是需要把这些隐患一块修复掉！
参考资料：
《Android UsageStatsService：要点解析》
《Why-delayed-allocation-is-bad》
《How to Solve Zero Length File Problem in Linux’s Ext4 File System》
原文链接：https://www.f2er.com/xml/294668.html