這是作者在2017年處理的數組越界的案例,要了解該問題需熟練掌握以下知識:
一. 問題描述
引言
一般數組越界問題, 往往是涉及多線程并發的情況下, 某個或多個臨界資源(比如類或對象的成員變量)多線程并發讀寫而導緻的異常。出現這樣情況, 一般是該保護的地方沒有用同步鎖保護,或者是用錯了同步鎖,這類問題比較正常。但本文要分享的案例卻是一個方法内的臨界資源已被加鎖保護的情況下仍然出現的數組越界問題, 導緻system_server挂掉,手機重新開機。
問題調用棧
2017-02-27 07:14:46 system_server_crash (text, 1021 bytes)
Process: system_server
java.lang.IndexOutOfBoundsException: Invalid index 8, size is 8
at java.util.ArrayList.throwIndexOutOfBoundsException(ArrayList.java:255)
at java.util.ArrayList.get(ArrayList.java:308)
at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2901)
at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2891)
at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:12483)
at com.android.server.am.ActivityManagerService.killAppAtUsersRequest(ActivityManagerService.java:12434)
at com.android.server.am.AppNotRespondingDialog$1.handleMessage(AppNotRespondingDialog.java:114)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:148)
at android.os.HandlerThread.run(HandlerThread.java:61)
at com.android.server.ServiceThread.run(ServiceThread.java:46)
該問題出現在Android 6.0的機型上,從調用棧可以看出是在某個應用發生ANR的時候彈出對話框的過程導緻手機重新開機。
疑問
來看看調用棧上的finishTopRunningActivityLocked()方法:
![](https://img.laitimes.com/img/__Qf2AjLwojIjJCLyojI0JCLicmbw5SMzUmY3cjM1ATYwczNzcjY4ADMxEmYycTMhFGNmZTO08CX0JXZ252bj91Ztl2Lc52YucWbp5GZzNmLn9Gbi1yZtl2Lc9CX6MHc0RHaiojIsJye.png)
在Android源碼裡面有大量方法名為xxxLock, 其含義是指該方法是非線程安全的, 所有調用該方法的地方一定是加過鎖的. 也就是說
finishTopRunningActivityLocked()該方法一定是被AMS鎖synchronized所保護, 既然同步鎖保護, 為何還會出現mTaskHistory變量擷取過程為出現資料越界的問題? 先告訴大家答案, 這個問題是Android 6.0原生問題,是一個低機率事件,最新的版本已修複。
接下來, 開始一步步剖析, 解開謎團.
二. 問題分析
分析重新開機異常問題,最重要的是從時間點附近逐漸分析推理整個過程。重新開機發生在2017-02-27 07:14:46,需要逐一遴選基于該時間點附近的關鍵日志。這個過程日志有很多,需要有一定的功底,對于一行靜态的日志能推算出複雜系統的動态執行流程,具體篩選過程就不再一一贅述了,下面直接列出跟該問題直接相關的核心日志資訊。
核心日志
//Step 1. ANR
02-27 07:14:44.015 1236 1275 E ActivityManager: ANR in com.dailyyoga.cn (com.dailyyoga.cn/.activity.PlanDetailActivity)
02-27 07:14:44.015 1236 1275 E ActivityManager: PID: 13930
02-27 07:14:44.015 1236 1275 E ActivityManager: Reason: Input dispatching timed out (Waiting because the touched window's input channel is not registered with the input dispatcher. The window may be in the process of being removed.)
//Step 2. AS.finishTopRunningActivityLocked()
02-27 07:14:46.197 1236 1276 ActivityManager: Force finishing activity com.dailyyoga.cn/.activity.PlanDetailActivity
// Step 3. AS.startPausingLocked()
02-27 07:14:46.206 1236 1276 W ActivityManager: Exception thrown during pause
02-27 07:14:46.206 1236 1276 W ActivityManager: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
02-27 07:14:46.206 1236 1276 W ActivityManager: at android.os.BinderProxy.transactNative(Native Method)
02-27 07:14:46.206 1236 1276 W ActivityManager: at android.os.BinderProxy.transact(Binder.java:503)
02-27 07:14:46.206 1236 1276 W ActivityManager: at android.app.ApplicationThreadProxy.schedulePauseActivity(ApplicationThreadNative.java:727)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.startPausingLocked(ActivityStack.java:915)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.finishActivityLocked(ActivityStack.java:3030)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2886)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2891)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:12483)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.am.ActivityManagerService.killAppAtUsersRequest(ActivityManagerService.java:12434)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.am.AppNotRespondingDialog$1.handleMessage(AppNotRespondingDialog.java:114)
02-27 07:14:46.206 1236 1276 W ActivityManager: at android.os.Handler.dispatchMessage(Handler.java:102)
02-27 07:14:46.206 1236 1276 W ActivityManager: at android.os.Looper.loop(Looper.java:148)
02-27 07:14:46.206 1236 1276 W ActivityManager: at android.os.HandlerThread.run(HandlerThread.java:61)
02-27 07:14:46.206 1236 1276 W ActivityManager: at com.android.server.ServiceThread.run(ServiceThread.java:46)
//Step 4. AS.resumeTopActivityInnerLocked()
02-27 07:14:46.209 1236 1276 I ActivityManager: Restarting because process died: ActivityRecord{909d520 u0 com.dailyyoga.cn/.FrameworkActivity t1861}
//Step 5. ASS.startSpecificActivityLocked()
02-27 07:14:46.211 1236 1276 W ActivityManager: Exception when starting activity com.dailyyoga.cn/.FrameworkActivity
02-27 07:14:46.211 1236 1276 W ActivityManager: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
02-27 07:14:46.211 1236 1276 W ActivityManager: at android.os.BinderProxy.transactNative(Native Method)
02-27 07:14:46.211 1236 1276 W ActivityManager: at android.os.BinderProxy.transact(Binder.java:503)
02-27 07:14:46.211 1236 1276 W ActivityManager: at android.app.ApplicationThreadProxy.scheduleLaunchActivity(ApplicationThreadNative.java:826)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStackSupervisor.realStartActivityLocked(ActivityStackSupervisor.java:1357)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStackSupervisor.startSpecificActivityLocked(ActivityStackSupervisor.java:1457)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.resumeTopActivityInnerLocked(ActivityStack.java:2058)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.resumeTopActivityLocked(ActivityStack.java:1605)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.resumeTopActivityLocked(ActivityStack.java:1588)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.startPausingLocked(ActivityStack.java:970)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.finishActivityLocked(ActivityStack.java:3030)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2886)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2891)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:12483)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.ActivityManagerService.killAppAtUsersRequest(ActivityManagerService.java:12434)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.am.AppNotRespondingDialog$1.handleMessage(AppNotRespondingDialog.java:114)
02-27 07:14:46.211 1236 1276 W ActivityManager: at android.os.Handler.dispatchMessage(Handler.java:102)
02-27 07:14:46.211 1236 1276 W ActivityManager: at android.os.Looper.loop(Looper.java:148)
02-27 07:14:46.211 1236 1276 W ActivityManager: at android.os.HandlerThread.run(HandlerThread.java:61)
02-27 07:14:46.211 1236 1276 W ActivityManager: at com.android.server.ServiceThread.run(ServiceThread.java:46)
//Step 6. AMS.startProcessLocked()
02-27 07:14:46.211 1236 1276 D ActivityManager: cleanUpApplicationRecord -- 13930
02-27 07:14:46.211 1236 1277 I libprocessgroup: Killing pid 14312 in uid 10227 as part of process group 13930
//Step 7. AS.removeHistoryRecordsForAppLocked()
02-27 07:14:46.216 1236 1276 W ActivityManager: Force removing ActivityRecord{909d520 u0 com.dailyyoga.cn/.FrameworkActivity t1861}: app died, no saved state
//論證Step6的正确性
02-27 07:14:46.230 1236 1276 [null] I ActivityManager: Start proc 14895:com.dailyyoga.cn/u0a227 for activity com.dailyyoga.cn/.FrameworkActivity
接下來,基于上述的日志從源碼中找到相應的方法,推測代碼執行流。要了解該問題需熟練掌握程序建立流程、Activity啟動流程、ANR執行流程。
Step 1. ANR
從核心日志,可以看到com.dailyyoga.cn發生了一次ANR,網上一搜得知這個App是每日瑜伽。該App在界面PlanDetailActivity時,超過5s主線程沒有響應input事件, 進而引發應用ANR。由于發生的是前台ANR, 則會彈出對話框, 讓使用者選擇是等待還是關閉該應用。
作為一個App是否有可能導緻系統重新開機,這個還不确定,至少有一點可以推測出,那就是系統重新開機跟ANR對話框有一定的關系。
Step 2. AS.finishTopRunningActivityLocked
發生ANR後間隔2s就出現上面這行log, 可定位已執行到如下方法,這個方法是由finishTopRunningActivityLocked()調用的。
Step 3. AS.startPausingLocked
每日瑜伽應用發生異常後, 這時會設定mPausingActivity = null, 這個很重要, 前面傳遞的參數resuming=false, 則便會走到如下流程
Step 4. AS.resumeTopActivityInnerLocked
雖然這裡沒有出現調用棧, 不難看出, 這裡發生異常的地方, 應該是next.app.thread.scheduleResumeActivity.之後開始執行startSpecificActivityLocked操作.
Step 5. ASS.startSpecificActivityLocked
進入startSpecificActivityLocked方法, 執行realStartActivityLocked()出現Exception, 這裡是關鍵,正常情況直接傳回了.
這裡發生異常, 那麼會執行重新建立程序的操作.
Step 6. AMS.startProcessLocked
緊接着, 看到cleanUpApplicationRecord的log, 反推調用情況有多種, 結合上面輸出的libprocessgroup log, 逐一排除, 可以發現程式執行到startProcessLocked()的如下流程:
app.pid>0 導緻需要殺舊的程序組, 以及清理程序相關資訊.
startProcessLocked過程
根據程序名,從mProcessNames查詢是否存在該程序.
會先設定app.setPid(0),
當程序建立後執行app.setPid(startResult.pid), 設定程序pid;
cleanUpApplicationRecordLocked()
當restart=true, 不會設定改變pid; 重新開機過程會設定pid=0; (即存在provider處于launching狀态),
當restart=false, 且pid>0, 則app.setPid(0);
在AMS.handleAppDiedLocked的過程, 會調用 AMS.cleanUpApplicationRecord, 清理元件資訊, 輸出上述log.
Step 7. AS.removeHistoryRecordsForAppLocked
在前面Step6執行handleAppDiedLocked過程, 先執行cleanUpApplicationRecord, 然後經過層層調用會進入AS.removeHistoryRecordsForAppLocked過程。這裡的最後一行removeActivityFromHistoryLocked(r, “appDied”), 則進入Step8。
Step 8. AS.removeActivityFromHistoryLocked
再來看看removeTask,則進入Step9。
Step 9. AS.removeTask
這便是整個問題最為核心的地方, 直接把每日瑜伽的task, 從ActivityStack的mTaskHistory裡面移除.
Step 10. AS.finishTopRunningActivityLocked
執行完removeTask()方法,層層回溯,再回到Step2的finishTopRunningActivityLocked()執行完成。
也就是對應如下代碼的第2886行,核心是把task從mTaskHistory中移除。
執行完2886行,程式繼續往下走。由于com.dailyyoga.cn應用的TASK中有3個activity,則不進入第2891行,直接進入2901行。
由于task從mTaskHistory中移除,此時便出現的數組越界問題。
總結
整個過程出現多次Exception引發的重新開機問題,這個調用鍊如下:
finishTopRunningActivityLocked
finishActivityLocked
startPausingLocked
resumeTopActivityInnerLocked
startSpecificActivityLocked
startProcessLocked
handleAppDiedLocked
cleanUpApplicationRecord
removeHistoryRecordsForAppLocked
removeActivityFromHistoryLocked
removeTask
解讀:
App發生一次ANR, 使用者點選确定關閉該App;
AS.finishActivityLocked()過程, 執行activity pause操作, 調用schedulePauseActivity過程發生Exception, 導緻觸發AS.resumeTopActivityInnerLocked()
AS.resumeTopActivityInnerLocked()過程, 執行resume FrameworkActivity, 調用scheduleResumeActivity()過程發生Exception, 導緻觸發ASS.startSpecificActivityLocked();
ASS.startSpecificActivityLocked()過程, 執行realStartActivityLocked(), 調用scheduleLaunchActivity過程發生Exception, 導緻觸發AMS.startProcessLocked();
AMS.startProcessLocked()過程, 由于app.pid>0, 導緻需要先殺掉舊的程序組, 以及執行handleAppDiedLocked()流程;
沒有執行cleanUpApplicationRecordLocked過程, 往往是死亡回調沒有回來.
AMS.handleAppDiedLocked過程, 執行AS.removeTask()流程, 進而導緻task從ActivityStack的mTaskHistory裡面移除.
最後回到AS.finishTopRunningActivityLocked過程, 便會出現mTaskHistory的數組越界問題.
三. 解決方案
AS.finishTopRunningActivityLocked()方法的主要功能是結束目前在棧頂正處于運作狀态的Activity。
過程會有finishActivityLocked方法,本案例在期間發生多次Exception,需要resume目前發生ANR activity的下一個activity,并該該activity所在的task從mTaskHistory中移除。
結論:當task發生remove時,會減少mTaskHistory中的成員個數,從導緻mTaskHistory.get(taskNdx)出現數組越界。
問題關鍵點:需要resume的activity可能是跟目前activity所歸屬的應用
當發生ANR的應用如果隻有單一activity,那麼resume的一定是其他應用的activity;在發生異常的時候,便會移除其他應用的task。而發生ANR的應用的task并沒有被移除,隻是序号變小,則需重新計算該task所在mTaskHistory的位置序号。
當發生ANR的應用至少有兩個activity,那麼resume的一定是還是目前app的下一個activity;在發生異常的時候,便會移除目前應用的task。此時要麼task所在mTaskHistory的位置序号變小,要麼目前task直接被移除了,這取決于該應用示範有多個task。這時還需要再執行finishActivityLocked(),否則有可能出現不斷重新開機發生crash的應用。
不管以上那種情況,隻要出現了task被remove的情況,都需要更新計算task所在mTaskHistory的位置序号,才能確定不會出現數組越界。至于是否還需要執行finishActivityLocked,這就取決于是否會引發是否會引發重新開機crash應用的重新開機行為。
微信公衆号
Gityuan
| 微網誌
weibo.com/gityuan
| 部落格
留言區交流