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

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

时间：2019-09-27 00:43:36

文章目录

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

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

声明

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

博客地址：/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: 12811-07 08:39:17.890 D/dalvikvm( 666): GC_CONCURRENT freed 246K, 7% free 4291K/4576K, paused 3ms+1ms, total 15ms11-07 08:39:17.900 I/SystemServer( 666): Display Manager11-07 08:39:17.900 I/SystemServer( 666): Telephony Registry11-07 08:39:17.900 I/ActivityManager( 666): Enabled StrictMode logging for AThread's Looper11-07 08:39:17.900 I/SystemServer( 666): Scheduling Policy11-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-1102usage-1103usage-1108usage-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 datasystem_se 1283system 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)” 这样的写法，并且没有主动判断跳出循环。这些地方也是埋了坑的，哪天不小心就会陷入这些死循环，导致另一个开机白屏问题。因此，也是需要把这些隐患一块修复掉！