Android的BUG(三) - 廣為人知的詬病:頻繁重啟問題

weixin_34292959發表於2015-10-31

使用過Android的同學,尤其是用過山寨pad,應該對Android的重啟問題印象深刻吧。Android由於其設計的複雜性,可能會使得系統在不經意時陷入異常狀態,因此Android設計了一套看門狗機制,當檢測到問題後,自動重啟。

再說說我碰到的問題吧,剛帶起Android的時候,android的重啟問題異常嚴重,經常操作一會後,介面卡住,等待1分鐘左右,重啟…, trace大約如下:

W/Watchdog(  813): *** WATCHDOG KILLING SYSTEM PROCESS: com.android.server.am.ActivityManagerService
W/AudioFlinger(  745): power manager service died !!!
I/ServiceManager(  737): service 'input_method' died
I/ServiceManager(  737): service 'textservices' died
I/ServiceManager(  737): service 'uimode' died
I/ServiceManager(  737): service 'vibrator' died
I/ServiceManager(  737): service 'battery' died
I/ServiceManager(  737): service 'permission' died
I/ServiceManager(  737): service 'cpuinfo' died

從這個trace上看,問題是出在ActivityManangerService中,但是什麼問題呢?繼續追蹤watchDog的重啟機制,可以 看到,其實現機制就是通過探測系統中各個service的鎖是否正常來實現的(詳情不細述,想了解的可以看看鄧凡平的《深入理解Android:卷1》, 這本書相當不錯),當有死鎖情況時,會殺掉system server程式以致android framework重啟而讓系統繼續工作。

這個問題,一開始也讓我困惑半天,無從下手,Android由於其複雜的架構和巨量的原始碼,啃起來還是蠻痛苦的。好在android提供的除錯方法和工具,還算比較完備,從log中發現,其在watch dog退出之前,生成了anr的trace,那就從這個地方分析吧。

剛拿到anr的trace,還是無頭緒,都是呼叫棧的dump,仔細看看,發現一個很好的資訊隱藏在這個棧幀資訊中:
如下一個棧幀:

----- pid 861 at 2012-02-11 14:57:50 -----
Cmd line: system_server
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x2ba9c460 self=0x8e820
  | sysTid=861 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=716342112
  | schedstat=( 0 0 0 ) utm=464 stm=65 core=0
  at com.android.server.am.ActivityManagerService.isUserAMonkey(ActivityManagerService.java:~6546)
  - waiting to lock <0x2c1141c8> (a com.android.server.am.ActivityManagerService) held by tid=59 (Binder Thread #6)
  at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:1273)
  at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:1545)
  at android.os.Binder.execTransact(Binder.java:338)
  at com.android.server.SystemServer.init1(Native Method)
  at com.android.server.SystemServer.main(SystemServer.java:808)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:511)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:784)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:551)
  at dalvik.system.NativeStart.main(Native Method)

這說明什麼?看上面的紅色部分,說明這個主執行緒在等待鎖一個object 0x2c1141c8 (通常就是synchronized操作,這裡就是com.android.server.am.ActivityManagerService型別的一 個object),但被tid=59佔住了, 再看看 tid=59的棧幀:

"Binder Thread #6" prio=5 tid=59 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x2c3bd838 self=0x34c5d8
  | sysTid=1120 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=3460688
  | schedstat=( 0 0 0 ) utm=168 stm=48 core=0
  at com.android.server.am.BatteryStatsService.noteStopWakelock(BatteryStatsService.java:~114)
  - waiting to lock <0x2c117d50> (a com.android.internal.os.BatteryStatsImpl) held by tid=13 (ProcessStats)
  at com.android.server.PowerManagerService.noteStopWakeLocked(PowerManagerService.java:798)
  at com.android.server.PowerManagerService.releaseWakeLockLocked(PowerManagerService.java:1015)
  at com.android.server.PowerManagerService.releaseWakeLock(PowerManagerService.java:967)
  at android.os.PowerManager$WakeLock.release(PowerManager.java:319)
  at android.os.PowerManager$WakeLock.release(PowerManager.java:300)
  at com.android.server.am.ActivityStack.activityIdleInternal(ActivityStack.java:3254)
  at com.android.server.am.ActivityManagerService.activityIdle(ActivityManagerService.java:3953)
  at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:362)
  at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:1545)
  at android.os.Binder.execTransact(Binder.java:338)
  at dalvik.system.NativeStart.run(Native Method)

tid為何沒有釋放鎖object 0x2c1141c8呢?因為它在等到鎖 object 0x2c117d50(一個com.android.internal.os.BatteryStatsImpl型別的物件)!如果大家有較豐富的捉蟲經 驗的話,看到這, 想必都清楚了,持鎖時又請求鎖,極大的可能就是死鎖了!

再看請求的鎖被tid=13持有的情況吧:

"ProcessStats" prio=5 tid=13 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x2c146f58 self=0x2954f0
  | sysTid=877 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=2709096
  | schedstat=( 0 0 0 ) utm=6 stm=4 core=0
  at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:~12430)
  - waiting to lock <0x2c1141c8> (a com.android.server.am.ActivityManagerService) held by tid=59 (Binder Thread #6)
  at android.app.ContextImpl.sendBroadcast(ContextImpl.java:909)
  at com.android.server.DropBoxManagerService.add(DropBoxManagerService.java:236)
  at android.os.DropBoxManager.addText(DropBoxManager.java:272)
  at com.android.server.am.ActivityManagerService$11.run(ActivityManagerService.java:7630)
  at com.android.server.am.ActivityManagerService.addErrorToDropBox(ActivityManagerService.java:7635)
  at com.android.server.am.ActivityManagerService.handleApplicationWtf(ActivityManagerService.java:7448)
  at com.android.internal.os.RuntimeInit.wtf(RuntimeInit.java:345)
  at android.util.Log$1.onTerribleFailure(Log.java:103)
  at android.util.Log.wtf(Log.java:278)
  at com.android.internal.os.BatteryStatsImpl.getNetworkStatsDetailGroupedByUid(BatteryStatsImpl.java:5738)
  at com.android.internal.os.BatteryStatsImpl.access$100(BatteryStatsImpl.java:76)
  at com.android.internal.os.BatteryStatsImpl$Uid.computeCurrentTcpBytesReceived(BatteryStatsImpl.java:2457)
  at com.android.internal.os.BatteryStatsImpl$Uid.getTcpBytesReceived(BatteryStatsImpl.java:2446)
  at com.android.internal.os.BatteryStatsImpl.writeSummaryToParcel(BatteryStatsImpl.java:5437)
  at com.android.internal.os.BatteryStatsImpl.writeLocked(BatteryStatsImpl.java:4836)
  at com.android.internal.os.BatteryStatsImpl.writeAsyncLocked(BatteryStatsImpl.java:4818)
  at com.android.server.am.ActivityManagerService.updateCpuStatsNow(ActivityManagerService.java:1649)
  at com.android.server.am.ActivityManagerService$3.run(ActivityManagerService.java:1531)

OK,這裡又是持鎖請求鎖,請求的鎖被tid=59佔住了!這裡就是tid=59和tid=13之間死鎖了!

問題這裡已經找到了,如何修復呢?其實,問題的原因也不復雜,仔細分析下出錯的棧,可以找到規律,出錯時都是系統在使用Log.wtf() 記錄錯誤時引起的。Wtf是what a terrible failure的簡稱,說明系統遇到嚴重錯誤了。通過此問題,追蹤下來是kernel的版本太低,不支援netfilter引起的。

不過,這說明不了是android的bug,但仔細看看: Log.wtf最終會 在addErrorToDropBox 中呼叫com.android.server.am.ActivityManagerService.broadcastIntent,這是需要鎖 com.android.server.am.ActivityManagerService這個物件的,如果寫程式碼的(包括android和後繼開發 者)不小心,隨便在一些地方捕獲異常來個Log.wtf,就會造成系統重啟,而且本意想要的add dropbox的功能此時也是無法正常實現,看來android在設計和測試這個功能時,也是沒嚴肅對待。

解決方法: 要麼認真的解決掉wtf,要麼簡單的註釋掉 ActivityManagerService.java 的方法handleApplicationWtf中的addErrorToDropBox。本來就是工作的不好,而且只是生成除錯資訊,對產品意義不太大。

另外要說明的是:這裡只是造成重啟問題的一個原因。android由於是開源的,大家都會改或新增程式碼,對這裡面的鎖操作稍有不慎就會使得系統出現重啟問題,據我除錯過的嚴重問題的經驗來看,大約有八成以上都是此類 多執行緒同步/狀態機 問題引起的。

Android重啟的一個主要原因就是這裡所說的:系統monitor的鎖被死鎖或持鎖時間過長導致的。本文只說了一個android公共的問題, 實際開發時,由於客製化及硬體問題(比如GPU)引起的死鎖和持鎖時間過長導致重啟的BUG有很多,都是可以通過此方法發現並進一步找方法解決,好好穩定 一下系統,現在android的重啟問題還是被抱怨的很慘。


 

 

版權宣告:本文為博主原創文章,未經博主允許不得轉載。

相關文章