最近基于海思3716c方案的智能机顶盒批量出货了,但出现了意想不到的问题。有少数机顶盒在开机动画停留很长时间有5分钟之多,之后黑屏,不进入Launcher,就像死机了一样。此问题出现概率达到百分之二,概率很高。
根据此现象,联想到开发阶段出现的一个类似情形,机顶盒开机后一直进不了主界面。当时没有大规模出现,认为可能是某人的误操作。当时重新格式化了data分区后,机器就又正常运行了。现在回想起来,感觉开发人员神经太大条了,这么严重的问题都放过。开发阶段遇到的偶然问题,在真正用户使用阶段就可能大规模出现,成为致命问题。
将问题机顶盒连上串口,发现还能进入命令行,还能输入命令,敲logcat还能打印出日志,还算好办。日志的最后部分如下:
- I/sysproc ( 1545): Entered system_init()
- I/sysproc ( 1545): ServiceManager: 0x1219320
- D/SensorService( 1545): nuSensorService starting...I/sysproc ( 1545): System server: starting Android runtime.
- I/sysproc ( 1545): System server: starting Android services.
- I/SystemServer( 1545): Entered the Android system server!
- I/sysproc ( 1545): System server: entering thread pool.
- D/SensorService( 1545): nuSensorService thread starting...
- I/SystemServer( 1545): Samba Service
- I/SystemServer( 1545): NFS Service
- I/SystemServer( 1545): Entropy Service
- I/SystemServer( 1545): Power Manager
- I/SystemServer( 1545): Activity Manager
- E/ ( 1424): [86400205 ERROR-tuner]:HI_UNF_TUNER_GetSNR[1748]:SIGNAL DROP
- E/ ( 1424): [86400205 ERROR-tuner]:HI_UNF_TUNER_GetSignalStrength[2012]:SIGNAL DROP
- I/ActivityManager( 1545): Memory class: 64
- W/UsageStats( 1545): Usage stats version changed; dropping
-
根据日志分析,可能停在system_server的初始化阶段。ps一下看到最后的进程就是system_server。打印如下:
- root 1030 1 3808 344 ffffffff 400fac74 S /system/bin/xcmidware
- root 1035 1 780 408 c007bf30 400a0e54 S /system/bin/sh
- root 1036 1 1380 148 ffffffff 0000825c S /sbin/adbd
- root 1316 2 0 0 bf0a1ca4 00000000 S MixerEngineTask
- root 1347 2 0 0 bf98bb28 00000000 S x5hdqam_sop
- root 1367 2 0 0 c00a1e98 00000000 S galcore workque
- root 1368 2 0 0 c00aba1c 00000000 S galcore daemon
- system 1421 1 137036 10728 ffffffff 40059670 S /system/bin/surfaceflinger
- root 1422 1 14820 3712 ffffffff 40105670 S /system/bin/updserver
- root 1423 1 14712 3676 ffffffff 4008d670 S /system/bin/fpserver
- root 1424 1 29380 6596 ffffffff 400fdf78 S /system/bin/cy_dvb_daemon
- root 1430 2 0 0 c0099a68 00000000 D HDMI_kthread
- root 1431 2 0 0 c0099a68 00000000 D HDMI_kCEC
- system 1545 1022 455764 33108 ffffffff 4003e670 S system_server
- root 1661 1035 960 336 00000000 400df438 R ps
找了一个正常的机顶盒,抓了个日志,看到Activity Manager下一个初始化项为Telephony Registry。
- I/sysproc ( 1545): System server: starting Android runtime.
- I/sysproc ( 1545): System server: starting Android services.
- I/sysproc ( 1545): System server: entering thread pool.
- D/SensorService( 1545): nuSensorService thread starting...
- I/SystemServer( 1545): Entered the Android system server!
- I/SystemServer( 1545): Samba Service
- I/SystemServer( 1545): NFS Service
- I/SystemServer( 1545): Entropy Service
- I/SystemServer( 1545): Power Manager
- I/SystemServer( 1545): Activity Manager
- I/ActivityManager( 1545): Memory class: 64
- I/ActivityManager( 1545): Enabled StrictMode logging for AThread's Looper
- I/SystemServer( 1545): Telephony Registry
- I/SystemServer( 1545): Package Manager
- D/dalvikvm( 1545): GC_CONCURRENT freed 265K, 4% free 9345K/9671K, paused 2ms+3ms
- D/dalvikvm( 1545): GC_CONCURRENT freed 285K, 5% free 9515K/9927K, paused 2ms+3ms
- E/StrictMode( 1545): A resource was acquired at attached stack trace but never released. See java.io.Closeable for information on avoiding resource leaks.
-
继续回到问题机顶盒,敲入busybox top查看,system_server的CPU使用率竟然占到了90%
- PID PPID USER STAT VSZ %MEM CPU %CPU COMMAND
- 2441 1042 0 R 1120 0.1 0 9.0 busybox top
- 1565 1030 1000 S 631m 89.2 0 90.0 system_server
-
怀疑是system_server在初始化 Activity Manager过程中陷入死循环了。再多次仔细对比日志,发现有个蹊跷打印UsageStats,正常和问题状态不一样。去读frameworks/base/services/java/com/android/server/am/UsageStatsService.java的代码,发现这个文件会读取文件,怀疑操作文件的时候出问题了。
- W/UsageStats( 1545): Usage stats version changed; dropping
-
运行lsof查看程序打开文件情况,与data分区相关的就是如下几项。与system_server相关的就是usage-history.xml
- keystore 1031 keystore cwd ??? ??? ??? ??? /data/misc/keystore
- nfsinit 1032 root 7 ??? ??? ??? ??? /data/exports
- system_se 1548 system 52 ??? ??? ??? ??? /data/system/usagestats/usage-history.xml
-
为了加快速度找到错误准确地方,想到了用eclipse中adt插件的ddms功能。因system_server是java程序,应该可以看到堆栈情况。
通过ddms很快看到堆栈地方,停在了readHistoryStatsFLOCK(), while (eventType != XmlPullParser.START_TAG) 陷入了死循环,当usage-history.xml文件内容为空时,处理不对。从代码得知没有判断内容为空parser.next()返回的是XmlPullParser.END_DOCUMENT的情况。
修改为:
- //Slog.w(TAG,"windsome eventType=" + eventType + ", START_TAG="+XmlPullParser.START_TAG+", TEXT="+XmlPullParser.TEXT+", END_TAG="+XmlPullParser.END_TAG+", START_DOCUMENT="+XmlPullParser.START_DOCUMENT+", END_DOCUMENT="+XmlPullParser.END_DOCUMENT);
- while ((eventType != XmlPullParser.START_TAG) && (eventType != XmlPullParser.END_DOCUMENT)) {
- eventType = parser.next();
- //Slog.w(TAG,"windsome eventType="+eventType);
- }
- //Slog.w(TAG,"windsome 2");
奇怪的是,手机上很少出现此问题,可能跟手机是用电池供电有关吧,很少遇到写usage-history.xml时断电的情况。