天天看點

由Monkey測試引發的跨多個程序的Android系統死鎖問題分析

1、界面定住,沒有任何重新整理,所有輸入事件無效,包括power key

2、adb shell可以連接配接并操作手機

3、手機的data和sdcard存儲空間已滿

4、watchdog沒有重新開機system server

通過初步分析、深入分析(具體分析過程和關鍵代碼及log在下面)我們知道了問題的原因:

1、monkey測試的過程中起了bugreport,并将bugreport輸出到stdout的log通過同步pipe循環讀取出來然後write到sdcard的檔案中,但是由于sdcard空間滿了,write的時候發生了IO error導緻monkey異常跳出了讀取同步pipe的流程,由于bugreport還沒有将log輸出完畢是以會一直等待,而monkey則繼續運作。

2、bugreport起來之後通過set property的方式觸發了dumpstate去擷取log,然後通過同步local socket(以下為了描述友善簡短起見簡稱socket)與dumpstate建立連接配接,将dumpstate通過socket輸出的log讀取出來寫到stdout。

3、dumpstate起來之後會首先将與bugreport的socket通過dup2重定向到stdout,然後執行一系列的抓取log資訊的動作,包括cat proc節點、執行dumpsys batterystats等,這些動作都是通過run command的方式起的即fork一個程序,然後執行execvp,fork會繼承dumpstate的檔案描述符,是以起dumpsys batterystats之後dumpsys中的stdout就是與bugreport通信的socket,dumpsys batterystats會将stdout 檔案描述符通過binder傳遞到system server中。

4、binder driver負責在system server程序中重新配置設定一個檔案描述符來指向與bugreport通信的socket,system server收到dump batterystats的請求後開始把資訊輸出到bugreport的socket,由于bugreport被write block,導緻system server輸出的log無法被讀取,進而引起system server的dump thread拿着batterystats的一個lock而block了程序内多個其他thread。

5、monkey繼續運作向system server發起了dumpsys meminfo的請求,由于dump batterystats的線程拿着一個關鍵的lock沒有釋放,導緻dumpsys meminfo一直無法得到執行而block了monkey主線程。

6、watchdog線程檢測到system server被block之後開始執行相關邏輯,其中就有調用IActivityController的systemNotResponding方法,這個IActivityController是monkey注冊的,所有就會跨程序調用到了monkey端,monkey的binder thread收到這個請求之後開始執行,但是執行的過程中需要monkey主線dump完需要的資訊後notify它,由于monkey主線程dumpsys meminfo的過程中block,是以導緻watchdog線程也被block而無法kill system server。

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

針對問題的原因,給出以下解決方案:

解開死鎖問題的根本死結,當monkey向sdcard寫log的時候,如果發生IO error,我們捕獲它并繼續将monkey起的bugreport的輸出讀完,進而使system server的dump線程釋放持有的lock,使其他線程繼續正常工作,dumpsys、dumpstate、cat、bugreport等都能完成自己的同步輸入輸出,monkey主線程也會恢複,整個系統恢複正常。

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

1、檢視system server的traces發現多線程互鎖,主線程需要的鎖在thread 33手裡

2、thread 33需要的鎖在thread 86手裡

3、thread 86需要的鎖在thread 84手裡

4、thread 84拿着鎖在做IO操作,但是這個IO操作為什麼會一直block?

帶着問題與樸老師還有明浩兄溝通,明浩兄給出的結論是同步IO操作,如果讀端沒有将寫端寫入到buffer或者寫端自帶buffer中的資料讀取完,一旦寫端将buffer寫滿仍然需要繼續寫或者寫端自帶buffer沒人讀,寫端就會block,明浩兄自己模拟出了類似的寫端調用棧:

讀端的調用棧:

與此同時明浩兄還帶來了兩個好問題:

1.讀端的線程是哪個?這時候在幹什麼?沒有找到對應的bugreport.

2.watchdog為什麼沒有殺掉system_server呢?

當然還少不了建議的解決方案:

1.采用異步寫.

2.讀端要及時關閉socket.

問題就這樣結束了嗎?當然不能!

首先解釋明浩兄提出的第二個問題,watchdog為什麼沒有殺掉system_server呢?

watchdog thread在調用android.app.IActivityControllerStubProxy.systemNotResponding時被block,導緻不能及時順序的執行kill system server的動作:

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

執行android.app.IActivityControllerStubProxy.systemNotResponding調用到了何方神聖?為什麼會被block?

通過搜尋代碼和trace定位到是調用到了monkey中,而且發現了條件循環和wait:

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

mWatchdogWaiting置為false的條件是跑完runMonkeyCycles之後走到下面才設定false并notifyall,但是目前monkey的main thread也block了:

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

monkey的main thread執行reportDumpsysMemInfo時被block的trace:

又看到了同步IO被block的調用棧,這次是讀端block。那麼問題就來了,讀端是誰?為什麼寫端沒有寫?

接下來watchdog沒有kill system server的問題就轉變為monkey的主線程為什麼會被block?導緻不能及時的設定條件為false并notifyall進而使watchdog繼續工作?

好了,再捋一捋,有點亂:

watchdog thread等待monkey的binder thread執行完systemNotResponding,monkey的binder thread又等着monkey的main thread執行完reportDumpsysMemInfo去notify自己,而reportDumpsysMemInfo的執行需要拿到一個BatteryStatsImpl執行個體的鎖,但是BatteryStatsImpl執行個體的鎖又被tid=84的binder thread拿着,也就是上面最早執行同步socket操作的thread,繞了一大圈發現這是一個連環死鎖,最終死鎖的關鍵還是這個tid=84的thread.

system server中dumpsys meminfo被block的trace:

好你個thread 84,竟然這麼多人被你block,你到底在幹啥?我們再看看它的trace:

仔細看這個traces,再仔細看這個traces,原來它在做dumpsys batterystats的操作,這個操作是誰發起的?

趕緊ps檢視一下所有的dumpsys,發現有兩個,一個是Z狀态,僵屍了,一個是S狀态。

Z狀态?發生了啥?趕緊看看父程序是誰,發現是dumpstate,為啥dumpstate沒有幫它兒子收屍?趕緊看代碼:

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析
由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

原來dumpstate起了dumpsys batterystats之後如果waitpid等待逾時就會通過kill來發送SIGTERM優雅的結束dumpsys batterystats,但是貌似它忘記了一件事情,就是再次waitpid替兒子收屍。。。太大意了,導緻兒子變成僵屍!

但是盡管如此,處于僵屍狀态的程序已經把占用的資源已經釋放掉了,其中就包括檔案描述符,是以還是解釋不了thread 84為啥被block?

接着看dumpsys batterystats是如何調用system server去做dump操作的,繼續看代碼:

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

原來dumpsys把STDOUT傳遞給了system server去dump batterystats,但是上面dumpsys已經釋放了所有檔案資源,并且傳遞的是STDOUT,不應該block system server的thread 84啊?

帶着這個問題繼續燒腦,看源碼,發現dumpstate是bugreport通過set property起的,然後通過socket與dumpstate建立連接配接,bugreport讀取這個socket中的資料并write到标準輸出,而dumpstate又通過dup2把與bugreport的socket重定向到了stdout:

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析
由Monkey測試引發的跨多個程式的Android系統死鎖問題分析
由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

run_command是通過先fork然後在子程序中用execvp的方式執行的dumpsys batterystats,這樣dumpsys batterystats就繼承了dumpstate的stdout,對應的就是與bugreport通信的socket,是以就算dumpsys程序的stdout被關閉也隻會對這個socket的引用計數減1,現在這個socket對應的引用計數還有2,分别是dumpstate程序自己以及system server,是以dumpsys的Z狀态不會中斷system server的thread 84,是以問題的關鍵還是在于thread 84在向這個socket同步寫資料,但是socket的另一端沒有讀。

我們知道socket的另一端是bugreport,但是它為什麼沒有及時的把socket中的資料讀走呢?趕緊用debuggerd dump出來bugreport的調用棧,發現bugreport在往标準輸出裡面寫資料的時候被block了:

bugreport往标準輸出裡面寫資料時為什麼會被block?

先通過ps看一下bugreport的父程序是誰,發現是monkey程序,那monkey程序為什麼不把bugreport的輸出讀走?從上面我們知道monkey的主線程block在了dumpsys meminfo,看它的其他線程也沒有調用bugreport的調用棧,那bugreport是怎麼起來的?什麼時候起來的?百思不得其解,通過一遍一遍的看代碼以及出問題時sdcard沒有空間的種種線索發現了以下可疑代碼和一個推論:

由Monkey測試引發的跨多個程式的Android系統死鎖問題分析

monkey起bugreport的方式就是調用上面的commandLineReport函數,這個函數起了bugreport之後會通過同步pipe的方式讀取bugreport的标準輸出,正常情況下會一直讀完,mRequestBugreport為true就會把這些資料寫到sdcard指定的檔案裡。如果在向sdcard寫入這些log資料的時候存儲空間滿了,就會發生IO exception,那麼就會跳出readline的while循環,進而繼續執行其他操作,導緻bugreport在write的時候block,進一步導緻system server的thread 84在write的時候block,因為bugreport無法讀取socket中的資料。

monkey主線程跳出readline的while循環之後繼續執行,然後執行到了dumpsys meminfo的操作,上面ps出來的另外一個S狀态的dumpsys的父程序就是monkey,由于system server的thread 84拿着dumpsys meminfo線程需要的鎖,是以monkey主線程也被block了,monkey主線程block導緻system server的watchdog調用systemNotResponding一直無法傳回而無法繼續kill system server。

好了,分析到這裡就回答完明浩兄的兩個問題了,system server不被watchdog kill的原因,以及thread 84的同步socket的讀端是誰也找到了,為什麼不讀的原因也找到了。

1、在發生問題時,通過進入到bugreport程序的proc的fd目錄下,cat 1(stdout)整個系統就全部恢複了,原理如上

2、通過dumpsys batterystats|more可以使system server被block而引發watchdog重新開機,原理就是上面的分析

3、有測試的同學發現它們通過java代碼寫的模拟shell執行的調用logcat的代碼時而有效,時而logcat起來之後沒有響應,調用程序一直waitfor無法傳回,原因就是它們調用的logcat指令在執行時有時手機裡面的crash資訊比較多導緻同步pipe的buffer被用完,而他們的調用程序沒有将同步pipe中的資料讀出,導緻logcat程序在同步寫pipe的時候block,而他的調用程序一直在空waitfor,時而有效是因為手機裡面crash資訊比較少甚至沒有,執行他這行代碼後logcat程序不會因為資料太多而在write的時候被block,他們的具體代碼如下:

可以看到調用“Runtime.getRuntime().exec(command);”之後直接waitfor了,沒有管p的輸出,正确的用法應該是:

4、問題是在L版本上發生,通過搜尋和檢視AOSP的最新master分支發現他們也送出了一些patch

<a href="https://android-review.googlesource.com/#/c/150928/">https://android-review.googlesource.com/#/c/150928/</a>

<a href="https://android-review.googlesource.com/#/c/142952/">https://android-review.googlesource.com/#/c/142952/</a>

繼續閱讀