hi3716c-android4.0.3SDK在開機動畫階段停留很長時間並黑屏不進入launcher原因分析

最近基於海思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時斷電的情況。