文章目录

UsageStatsService之坑：一个XML解析异常导致的开机动画死循环
- 声明
- 问题说明
- 日志排查
- 猜想和验证
- 问题定位
- - 插曲 -- XML的解析
- 问题修复
- 杯弓蛇影
- 参考资料
- 修改说明

UsageStatsService之坑：一个XML解析异常导致的开机动画死循环

声明

郑重声明：博文为原创内容，可以转载或引用，但必须在明显位置标明原文作者和出处，未经同意不得擅自修改本文内容！

博客地址：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 connection11-07 08:39:17.800 I/SystemServer(  666): Enabled StrictMode logging for UI Looper11-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 Looper11-07 08:39:17.800 I/Installer(  666): connecting...11-07 08:39:17.800 I/SystemServer(  666): Entropy Mixer11-07 08:39:17.830 E/RKPowerHAL(  666): Error opening /sys/devices/system/cpu/cpufreq/interactive/boostpulse: No such file or directory11-07 08:39:17.830 I/SystemServer(  666): Power Manager11-07 08:39:17.830 I/SystemServer(  666): Activity Manager11-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 Manager11-07 08:39:18.580 D/dalvikvm(  666): GC_EXPLICIT freed 332K, 8% free 4862K/5252K, paused 2ms+2ms, total 25ms11-07 08:39:18.590 I/SystemServer(  666): User Service11-07 08:39:18.590 I/SystemServer(  666): Account Manager11-07 08:39:18.590 I/SystemServer(  666): Content Manager11-07 08:39:18.590 I/SystemServer(  666): System Content Providers11-07 08:39:18.690 I/libsuspend(  666): Selected early suspend11-07 08:39:18.690 I/libsuspend(  666): Starting early suspend unblocker thread11-07 08:39:18.690 I/SystemServer(  666): Lights Service11-07 08:39:18.690 I/SystemServer(  666): Battery Service11-07 08:39:18.690 I/SystemServer(  666): Vibrator Service11-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=0x416f731811-07 08:39:18.700 D/SurfaceFlinger(   99):  screen was previously acquired11-07 08:39:18.700 D/AlarmManagerService(  666): Kernel timezone updated to -480 minutes west of GMT11-07 08:39:18.700 I/SystemServer(  666): Alarm Manager11-07 08:39:18.700 I/SystemServer(  666): Init Watchdog11-07 08:39:18.700 I/SystemServer(  666): Input Manager11-07 08:39:18.700 I/InputManager(  666): Initializing input manager, mUseDevInputEventForAudioJack=false11-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 Looper11-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 Looper11-07 14:13:23.780 I/Installer(  669): connecting...11-07 14:13:23.780 I/SystemServer(  669): Entropy Mixer11-07 14:13:23.810 E/RKPowerHAL(  669): Error opening /sys/devices/system/cpu/cpufreq/interactive/boostpulse: No such file or directory11-07 14:13:23.810 I/SystemServer(  669): Power Manager11-07 14:13:23.810 I/SystemServer(  669): Activity Manager11-07 14:13:23.820 I/ActivityManager(  669): Memory class: 12811-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 13ms11-07 14:13:24.120 D/dalvikvm(  669): GC_CONCURRENT freed 402K, 10% free 4210K/4652K, paused 2ms+2ms, total 11ms11-07 14:13:24.280 D/dalvikvm(  669): GC_CONCURRENT freed 396K, 10% free 4210K/4652K, paused 2ms+1ms, total 11ms11-07 14:13:24.440 D/dalvikvm(  669): GC_CONCURRENT freed 403K, 10% free 4210K/4652K, paused 2ms+2ms, total 14ms11-07 14:13:24.620 D/dalvikvm(  669): GC_CONCURRENT freed 399K, 10% free 4210K/4652K, paused 2ms+2ms, total 12ms11-07 14:13:25.620 D/dalvikvm(  669): GC_CONCURRENT freed 400K, 10% free 4210K/4652K, paused 2ms+2ms, 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 当中来，从以下这句异常日志入手：

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

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

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

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

其中：

/data/system/usagestats/usage-日期” 文件记录的当天的使用记录的数据
/data/system/usagestats/usage-history.xml文件中读取每个APP中每个Activity最后启动的时间

UsageStatsService服务启动的时候，会去读取并解析这些文件。一般情况下，UsageStatsService取到的ver与 VERSION(常量1007)，通过增加log，发现这里取到的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

问题定位

到这里基本可以确定是system_server 启动过程中在读写 usage-history.xml 文件时出了问题。但是如果是简单的文件操作错误，最多是报个crash，理论上CPU占用率不应该那么高。除非是文件操作过程中发生死锁或者死循环之类的致命错误。

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

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

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

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

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

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

插曲 – XML的解析

在JAVA的世界里，解析xml文件有多种方式，不同的解析方式有着各自的优缺点和适用环境。在Android中常见的XML解析器分别为SAX解析器、DOM解析器以及PULL解析器。
这里就不展开具体介绍了，具体可以参考本人以前写的博文：

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

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

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

看代码，知道上面使用的是PULL的方式来解析xml文件的，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事件，便会陷入死循环当中！

而一旦陷在while死循环里面，system_server便无法往下继续启动
其他系统服务，因而不会等到系统ready后通知系统进入桌面。于是便出现系统开机后一直停留在开机动画播放阶段，不断循环的现象！

而前面我们说到，该设备usage-history.xml是个零字节空文件，因此问题便出在这里了！

问题修复

知道原因，那么，便知道怎么修改了，一旦解析到达xml文件末尾，还解析不到
START_TAG 事件，就应该主动退出while循环。

-             while (eventType != XmlPullParser.START_TAG) {
+             //PN: fix empty xml file cause death cycle
+             while (eventType != XmlPullParser.START_TAG && eventType != XmlPullParser.END_DOCUMENT) {eventType = parser.next();}

查看了各个历史版本，Android4.4以更低的版本皆存在这样的隐患问题，而Android5.0之后，由于UsageStatsService机制改变，因此已经修复该问题。

usage-history.xml一般情况下都会有内容，因此，触发到死循环的概率很低。但有些情况也可能导致 usage-history.xml为零字节：

比如用户强行断电情况下便可能导致IO读写无法正常结束，引发零字节问题。
比如 flash 硬件质量问题
比如Android Ext4文件系统的延迟分配（delalloc）功能，该功能网上反馈有有比较大的问题，可能造成数据丢失、0长度等问题，

PS: 解决此类问题的方案就是在分区挂载的时候，禁用延迟分配功能，也就是开启 nodelalloc 选项。

杯弓蛇影

解决完这个问题后，留了一心眼，重新搜索了整个Android4.2的系统源码，发现还有几处代码也是采用 “while (eventType != XmlPullParser.START_TAG)” 这样的写法，并且没有主动判断跳出循环。这些地方也是埋了坑的，哪天不小心就会陷入这些死循环，导致另一个开机白屏问题。因此，也是需要把这些隐患一块修复掉！

参考资料

《Android UsageStatsService：要点解析》

《Why-delayed-allocation-is-bad》

《How to Solve Zero Length File Problem in Linux’s Ext4 File System》

修改说明

作者	版本	修改时间	修改说明
WalkAloner	V1.0	2016/11/08	第一版
WalkAloner	V1.1	2019/07/26	图床搬迁，换markdown格式