android502

『壹』 Android P 系統穩定性問題分析方法總結

Android系統最開始是為手機設計的，在機頂盒，電視，帶屏音箱等大屏上運行後，晶元廠家做些適配，產品廠家也會做系統客制化，有時候還要適配第三方應用..等待
這種適配容易引人系統的穩定性問題，系統穩定性對於用戶體驗至關重要，很多問題也都比較類似，android系統對系統性能，穩定性分析工具也比較多，下面根據工作中遇到的問題做個總結。

從表現來看有: 死機重啟, 自動關機, 無法開機,凍屏,黑屏以及閃退, 無響應等情況;

從技術層面來劃分無外乎兩大類: 長時間無法執行完成(Timeout) 以及異常崩潰(crash). 主要分類如下:

ANR(Application Not responding)，是指普通app進程超過一定時間沒有執行完，系統會彈出應用無響應對話框. 如果
該進程運行在system進程, 更准確的來說,應該是(System Not Responding, SNR)

ANR產生的原因可能是各種各樣的，但常見的原因可以分為：

1.logcat日誌
2.trace文件(保存在/data/anr/traces.txt)
從logcat里可以看到死鎖的列印
從traces.txt可以看到線程的函數調用棧

10-16 00:50:10 820 907 E ActivityManager: ANR in com.android.systemui, time=130090695
10-16 00:50:10 820 907 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000114 (has extras) }
10-16 00:50:10 820 907 E ActivityManager: Load: 30.4 / 22.34 / 19.94
10-16 00:50:10 820 907 E ActivityManager: Android time :[2015-10-16 00:50:05.76] [130191,266]
10-16 00:50:10 820 907 E ActivityManager: CPU usage from 6753ms to -4ms ago:
10-16 00:50:10 820 907 E ActivityManager: 47% 320/netd: 3.1% user + 44% kernel / faults: 14886 minor 3 major
10-16 00:50:10 820 907 E ActivityManager: 15% 10007/com.sohu.sohuvideo: 2.8% user + 12% kernel / faults: 1144 minor
10-16 00:50:10 820 907 E ActivityManager: 13% 10654/hif_thread: 0% user + 13% kernel
10-16 00:50:10 820 907 E ActivityManager: 11% 175/mmcqd/0: 0% user + 11% kernel
10-16 00:50:10 820 907 E ActivityManager: 5.1% 12165/app_process: 1.6% user + 3.5% kernel / faults: 9703 minor 540 major
10-16 00:50:10 820 907 E ActivityManager: 3.3% 29533/com.android.systemui: 2.6% user + 0.7% kernel / faults: 8402 minor 343 major
......
10-16 00:50:10 820 907 E ActivityManager: +0% 12832/cat: 0% user + 0% kernel
10-16 00:50:10 820 907 E ActivityManager: +0% 13211/zygote64: 0% user + 0% kernel
10-16 00:50:10 820 907 E ActivityManager: 87% TOTAL: 3% user + 18% kernel + 64% iowait + 0.5% softirq

發生ANR的時間 00:50:10 ,可以從這個時間點之前的日誌中，還原ANR出現時系統的運行狀態
發生ANR的進程 com.android.system.ui
發生ANR的原因 Reason關鍵字表明了ANR的原因是處理TIME_TICK廣播消息超時
CPU負載 Load關鍵字表明了最近1分鍾、5分鍾、15分鍾內的CPU負載分別是30.4、22.3、19.94.CPU最近1分鍾的負載最具參考價值，因為ANR的超時限制基本都是1分鍾以內， 這可以近似的理解為CPU最近1分鍾平均有30.4個任務要處理，這個負載值是比較高的
CPU使用統計時間段 CPU usage from XX to XX ago關鍵字表明了這是在ANR發生之前一段時間內的CPU統計,類似的還有CPU usage from XX to XX after關鍵字，表明是ANR發生之後一段時間內的CPU統計
各進程的CPU使用率
以com.android.systemui進程的CPU使用率為例，它包含以下信息：
總的CPU使用率: 3.3%，其中systemui進程在用戶態的CPU使用率是2.6%，在內核態的使用率是0.7%
缺頁次數fault：8402 minor表示高速緩存中的缺頁次數，343 major表示內存的缺頁次數。minor可以理解為進程在做內存訪問，major可以理解為進程在做IO操作。 當前minor和major值都是比較高的，從側面反映了發生ANR之前，systemui進程有有較多的內存訪問操作，引發的IO次數也會較多
CPU使用匯總 TOTAL關鍵字表明了CPU使用的匯總，87%是總的CPU使用率，其中有一項iowait表明CPU在等待IO的時間，佔到64%，說明發生ANR以前，有大量的IO操作。app_process、 system_server, com.android.systemui這幾個進程的major值都比較大，說明這些進程的IO操作較為頻繁，從而拉升了整個iowait的時間

traces.txt 如下
----- pid 29533 at 2015-10-16 00:48:29 -----
Cmd line: com.android.systemui
DALVIK THREADS (54):
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 obj=0x75bd5818 self=0x7f8549a000
| sysTid=29533 nice=0 cgrp=bg_non_interactive sched=0/0 handle=0x7f894bbe58
| state=S schedstat=( 289080040422 93461978317 904874 ) utm=20599 stm=8309 core=0 HZ=100
| stack=0x7fdffda000-0x7fdffdc000 stackSize=8MB
| held mutexes=
at com.mediatek.anrappmanager.MessageLogger.println(SourceFile:77)

Android系統中，有硬體WatchDog用於定時檢測關鍵硬體是否正常工作，類似地，在framework層有一個軟體WatchDog用於定期檢測關鍵系統服務是否發生死鎖事件。
watchdog 每過30s 檢測一次， 如果要監控的線程30s 後沒有響應，系統會mp出此進程堆棧，如果超過60s 沒有相應，會觸發watchdog，並重啟系統
10:57:23.718 579 1308 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on ActivityManager (ActivityManager)
10:57:23.725 579 1308 W Watchdog: android.fg annotated stack trace:
10:57:23.726 579 1308 W Watchdog: at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:26271)
10:57:23.727 579 1308 W Watchdog: - waiting to lock <0x0bb47e39> (a com.android.server.am.ActivityManagerService)
10:57:23.727 579 1308 W Watchdog: at com.android.server.Watchdog DeliveryTracker.alarmTimedOut(AlarmManagerService.java:4151)
10:57:23.733 579 1308 W Watchdog: - waiting to lock <0x00aaee38> (a java.lang.Object)
......
10:57:23.736 579 1308 W Watchdog: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:838)
10:57:23.739 579 1308 W Watchdog: ActivityManager annotated stack trace:
10:57:23.740 579 1308 W Watchdog: at com.android.server.am.ActivityStack$ActivityStackHandler.handleMessage(ActivityStack.java:405)
10:57:23.740 579 1308 W Watchdog: - waiting to lock <0x0bb47e39> (a com.android.server.am.ActivityManagerService)
10:57:23.740 579 1308 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:106)
10:57:23.741 579 1308 W Watchdog: *** GOODBYE!
分析：
提示 ActivityManagerService的android.fg,main,ActivityManager 線程Block了,但logcat里只能看到
android.fg等待0x0bb47e39 鎖,main 等待0x00aaee38鎖,ActivityManager等待0x0bb47e39鎖,無法進一步分析,需要看traces.txt
Cmd line: system_server
......
"main" prio=5 tid=1 Blocked

當出現應用閃退，可以從兩個方面查看：
1、是否應用崩潰：
可以通過logcat –s AndroidRuntime DEBUG過濾日誌，查看應用奔潰的具體堆棧信息。
其中AndroidRuntime的TAG列印java層信息，DEBUG的TAG列印native層的信息。
2、是否被lowmemorykiller殺掉：
可以通過 logcat –s lowmemorykiller 過濾日誌，注意adj 0是代表前台進程。例如：
03-08 04:16:58.084 310 310 I lowmemorykiller: Killing'com.google.android.tvlauncher' (2520), uid 10007, adj 0
發生這種情況，需要mpsys meminfo 查看當前內存狀態，是否有進程內存泄漏，導致系統內存不夠，出現前台進程被殺，造成閃退。

測試過程中，經常遇到屏幕閃爍的現象，需要排除是OSD層閃爍，還是video層閃爍。
1、先通過android原生方法：screencap截圖, screenrecord 錄制視頻，這里都是截取的OSD層，查看是否有閃屏現象。
2、OSD沒有問題，就需要從更底層的顯示模塊分析，一般需要晶元廠家提供debug手段，不同晶元廠家方案不一樣。
3, 有時候輸出不穩定，hdmi/mipi信號干擾，輸出頻率異常等也會導致閃屏，這種情況需要硬體協助分析。
如果OSD層也閃爍，則需從系統和應用層面分析。如曾遇到在開機向導界面，有個應用不斷被喚起，導致走開機向導時出現連續閃灰屏的現象。

黑屏分UI黑屏，視頻播放黑屏但UI正常等，2種場景

1、screencap截屏，排查OSD層圖形是否正常，
2、如果OSD圖形正常，需要排查顯示輸出模塊是否異常。
3、電視機裡面屏顯是單獨控制，如果屏參配置錯誤會導致整改黑屏。
OSD異常，需要排查頂層activity是否黑屏，window是否有異常等.

1，排查視頻圖層或者window是否創建成功。
2，排查解碼是否有異常，不同的應用youtube,netflix,iptv解碼方式不一樣，需要具體問題具體分析。

如下，ActivityManager因為空對象引用而掛掉，導致system_server重啟
*** [FATAL EXCEPTION IN SYSTEM PROCESS: ActivityHanager [
^ava.lang.NullPointerException: Attempt to invoke virtual method 'void co®.android.internal.os.KernelSingleUidTimeReader.iBarkDataAsStale(boolean)' on a null object reference
at com.android.internal.os.BatteryStatsIiaplSConstants.(BatteryStatslnpl.java:13355)
at com.android.internal.os.BatteryStatsInplSConstants.upddteConstants(BatteryStatsImpl.java:13330)
at com.android.internal-o-batteryStatslMpl$Constants-onChange(BatteryStatsInpl-java:13316)
at android.database.Contentobserver.onChange(ContentObserver.java:145)
解決方法：修復空指針

DEBUG : pid: 296, tid: 1721, name: Binder：296_4 >>> /system/bin/surfaceflinger <<<
DEBUG : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr ------
DEBUG : Abort message: 'status.cpp:149] Failed HIDL return status not checked: Status(EXTRANSACTIONFAILED):
DEBUG : r0 00000000 rl 000006b9
DEBUG ： C4 00000128 r5 000006b9
r2 00000006 r3 a5c5d620
r6 a235d60c r7 0000010c
DEAD_OB3ECT：
DEBUG : r8 00000019 r9 0000015d
DEBUG : ip a6ablbec sp a235d5f8
rlO a568f090 rll a620dce9
Ir a5be901d pc a5be0da2
/system/lib/libc.so (abort+62)
/system/lib/libbase.so (android::base::DefaultAborter(char const )+6)
backtrace:
/system/lib/libsurfaceflinger.so
/system/lib/libsurfaceflinger.so
/system/lib/libsurfaceflinger.so
/system/lib/libsurfaceflinger.so
/system/lib/libbase.so (android::base::LogMessage::~LogMessage()+502)
/system/lib/libhidlbase.so (android::hardware::details::return_status::~return_status()+184)
(android::Hwc2::impl::Composer::getActiveConfig(unsigned long long, unsigned int )+56)
(HWC2::Display::getActiveConfig(std::_1::shared_ptr<HWC2：:Display::Config const>*) const+38)
(android::HWComposer::getActiveConfig(int) const+64)
(android::SurfaceFlinger::resyncToHardwareVsync(bool)+64)
可以根據backtrace來進行定位異常崩潰的地方。Android P上， backtrace使用Java上下文來顯示，省去使用addr2line來轉換的一個過程，方便調試分析問題。但是實際場景中，
有些native進程崩潰只有pc地址，而無函數信息，或者需要定位到具體的某個文件某個函數，則可藉助堆棧分析工具addr2line。
addr2line：根據堆棧定位具體函數和文件
addr2line -e libsurfaceflinger.so -f 00071a09
addr2line -e libsurfaceflinger.so -f 00071a09
_
frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp:1229
需注意兩點：
1、需用帶debug信息的LINK目錄裡面的so庫，機頂盒上的so庫是無法定位的：
out/target/proct/xx/obj/SHARED_LIBRARIES/libsurfaceflinger_intermediates/LINKED/libsurfaceflinger.so
或者：out/target/proct/xx/symbols/system/lib/libsurfaceflinger.so
2、定位的文件，必現和機器上出現問題的版本一致，否則定位不準確
debuggerd：列印當前進程實時堆棧：debuggerd –b pid

主要可以分為以下3類
1)Data abort
Unable to handle kernel NULL pointer dereference at virtual address...
Unable to handle kernel paging request at virtual address...
Unhandled fault...at...
Unhandled prefetch abort...at...
2)BUG/BUG_ON
Oops - BUG...
例如：
Out of memory and no killable processes...
rbus timeout...
...
PS:WARN_ON只mp stacks，kernel還是正常
3)bad mode
Oops - bad mode...
日誌列印:
〃錯誤類型原因
[214.962667] 08:14:19.315 (2)-0488 Unable to handle kernel paging request at virtual address 6b6b6cl7
[214.973889] 08:14:19.326 (2)-0488 addr：6b6b6c17 pgd = d0824000
[214.980132] [6b6b6c17J •pgd=O000eO0e
〃Oopsttl誤碼序號
[214.983865] 08:14:19.336 (2)-0488 Internal error： Oops： 805 [#1] PREEMPT SMP ARM
[214.9914S3] Moles linked in: 8192eu ufsd(PO) jnl(O) fusion(O)
〃發生也錯誤的CPU序號
(215.001878] 08:14:19.354 (2)-0488 CPU： 2 PID: 488 Comm: system_server Tainted: P 4.4.3+ #113
(2)-0488 Hardware name: rtd284x
[215.011865] 08:14:19.364
〃當前PC指針 98:14:19.377 (2)-0488 PC is at mutex_unlo<k+0xc/0x38
(21S.024846] 08:14:19.383 (2)-0488 LR is at storage_pm_event+0xb4/0xe8
(21S.031026]
//Registers 08:14:19.390 (2)-0488 ：[<ceb78ffc>] Ir : [<C0542034>] psr: 200f0013
I 215.037644] sp : ccf79e38 ip : eceoeeee fp : 9b34648c
I 215.037644]
08:14:19.404 (2)-0488 rlO： 00000080 r9 ：Cl8b3864 r8 : oeeeeeoe
215.051370]
215.058692] 08:14:19.411 (2)-0488 P7 ： C1293a98 P6 ：C1293940 r5 : C1293940 r4 ：C1293a80
21S.067345]
[ 215.076014] 08:14:19.420 (2)-0488 r3 : 00000033 r2 ：00000000 ri : 000^000 re ：6b6b6c07
[ 215.085307]
08:14:19.428 (2)-0488 Flags: nzCv IRQs on FIQs on Mode SVC 32 ISA ARM Segment user
08:14:19.438 (2)-0488 Control: 10c5383d Table： 1082406a DAC： 00000055
//Process.不 ,定是該process的錯誤，只是發生錯誤時,剛好在運行該process
[215.093168]
//Stacks 08:14:19.446 (2)-0488 Process syste«i_server (pid: 488, stack limit = 0xccf78218)

(21S.101827] 08:14:19.454 (2)-0488 Stack: 0xccf79e38 (Oxccf79d7。 to 0xccf7a08Q) - par(0xcf796d4)

---[ end trace 45d55384id6a0974 ]--- Kernel panic not syncing: Fatal exception
[217.359794] 08:14:21.712 (0)-0488
解決方案: kernel異常一般找晶元原廠協助分析。

系統卡頓時，一般先分三步走：
1、查看當前系統的CPU，IO等參數，輸入top、iotop命令： （如：iotop -s io -m 9）
如果有異常飆高的進程，kill掉後會發現系統恢復正常。
之前項目上遇到過某些U盤IO性能比較差，媒體中心又在後台掃描媒體問題，導致系統各種卡頓，io wait時間比較長。
2、系統進程卡住，觸發Watchdog：ps –A |grep system_server,一般而言，system_server正常的進程號是200多，如果發現進程號變成幾千，則可能出現重啟，結合tombstone和 /data/anr下的trace文件分析重啟原因
3、當前應用出現卡頓，造成ANR。輸入logcat | grep ANR，如果有ANR列印，再去/data/anr下面查看相應進程的traces文件
有時在應用裡面操作卡頓，按鍵響應延遲，但是卻沒有生成ANR，此時如果退出該應用（如果無法退出，在抓取足夠信息的情況下，可以串口直接kill掉卡頓的應用），則一切正常，可能是應用自身實現問題，或者調用了其它介面導致（例如曾遇到應用調用了中間件、mediaplayer某些介面導致操作嚴重卡頓，按鍵響應延遲），這種情況則需應用和相應介面的實現者去排查。

系統完全卡死，一般分三種情況
1，串口無響應，大概率kernel panic，
2，串口日誌狂輸出，把系統堵塞， 優化日誌輸出，關注關閉後壓測。
3，Input系統完全堵塞，導致任何輸入都無響應。