Binder Driver缺陷導致定屏的實戰分析

引用

本文講解非同步binder call是如何阻塞整個系統的，通過ramdump信息以及binder通信協議來演繹並還原定屏現場。

一、背景知識點

解決此問題所涉及到的基礎知識點有：Trace、CPU調度、Ramdump推導、Crash工具、GDB工具、Ftrace， 尤其深入理解binder IPC機制。

1.1 工具簡介

Trace：分析死鎖問題的最基本的技能，通過kill -3可生成相應的traces.txt文件，裡面記錄著當前時刻系統各線程 所處在的調用棧。

CPU調度：可通過查看schedstat節點，得知該線程是否長時間處於RQ隊列的等待

Ramdump：把系統memory中某一個時間點的數據信息保存起來的內存崩潰文件，屬於ELF文件格式。 當系統發生致命錯誤無法恢復的時候，主動觸發抓取ramdump能異常現場保留下來，這是屬於高級調試秘籍。

Crash工具：用於推導與分析ramdump內存信息。

GDB工具：由GNU開源組織發布的、UNIX/LINUX操作系統下的基於命令行的強大調試工具，比如用於分析coredump

Ftrace：用於分析Linux內核的運行時行為的強有力工具，比如能某方法的耗時數據、代碼的執行流情況。

1.2 Binder簡介Binder IPC是最為整個Android系統跨進程通信的基石，整個系統絕大多數的跨進程都是採用Binder，如果對Binder不太了解看本文會非常吃力，在Gityuan.com博客中有大量講解關於Binder原理的文章，見http://gityuan.com/2015/10/31/binder-prepare/，這裡不再贅述。

簡單列兩張關於Binder通信架構的圖，

Binder通信採用C/S架構，主要包含Client、Server、ServiceManager以及binder驅動部分，其中ServiceManager用於管理系統中的各種服務。Client向Server通信過程圖中畫的是虛線，是由於它們彼此之間不是直接交互的，而是採用ioctl的方式跟Binder驅動進行交互的，從而實現IPC通信方式。

接下來再以startService為例，展示一次Binder通信過程的方法執行流:

從圖中，可見當一次binder call發起後便停在waitForResponse()方法，等待執行完具體工作後才能結束。

那麼什麼時機binder call端會退出waitForResponse()方法？見下圖：

退出waitForResponse場景說明：

1）當Client收到BR_DEAD_REPLY或BR_FAILED_REPLY(往往是對端進程被殺或者transaction執行失敗)，則無論是同步還是非同步的binder call都會結束waitForResponse()方法。

2）正常通信的情況下，當收到BR_TRANSACTION_COMPLETE則結束同步binder call； 當收到BR_REPLY則結束非同步binder call。

二、初步分析

有了以上背景知識的鋪墊，接下來就進入正式實戰分析過程。

2.1 問題描述

Android 8.0系統用幾十台手機連續跑幾十個小時Monkey的情況下有概率出現定屏問題。

定屏是指屏幕長時間卡住不動，也可以成為凍屏或者hang機，絕大多數情況下都是由於多個線程之間存在直接或者間接死鎖而引發，而本案例實屬非常罕見例子， 非同步方法處於無限等待狀態被blocked，從而導致的定屏。

2.2 初步分析

通過查看trace，不難發現導致定屏的原因如下：

system_server的所有binder線程以及其中重要現場都在等待AMS鎖， 而AMS鎖被線程Binder:12635_C所持有； Binder:12635_C線程正在執行bindApplication()方法，調用棧如下：

終極難題：attachApplicationLocked()是屬於非同步binder call，之所以叫非同步binder call，就是由於可非同步執行而並不會阻塞線程。 但此處卻能阻塞整個系統，這一點基本是毀三觀的地方。

懷疑1：有同學可能會覺得是不是Binder驅動里的休眠喚醒問題，對端進程出現異常導致無法喚醒該binder線程從而阻塞系統？

回答1：這個觀點咋一看，好像合情合理，還挺能唬人的。接下來，我先來科普一下，以正視聽。

如果熟悉Binder原理的同學，應該知道上面說的是不可能發生的事情。oneway binder call，也就是所謂的非同步調用， Binder機制設計絕不可能傻到讓非同步的binder call來需要等待對端進程的喚醒。

真正的oneway binder call， 一旦是事務發送出去。 a)如果成功，則會向自己線程thread->todo隊列裡面放上BINDER_WORK_TRANSACTION_COMPLETE; b)如果失敗，則會向自己線程thread->todo隊列裡面放上BINDER_WORK_RETURN_ERROR。

緊接著，就會在binder_thread_read()過程把剛才的BINDER_WORK_XXX讀取出去，然後調出此次binder call。 之所以要往自己隊列放入BINDER_WORK_XXX，為了告知本次事務是否成功的投遞到對端進程。但整個過程，無需對端進程的參與。

也就是說bindApplication()方法作為非同步binder調用方法，只會等待自己向自己todo隊列寫入的BR_TRANSACTION_COMPLETE或BR_DEAD_REPLY或BR_FAILED_REPLY。

所以說，對端進程無法喚醒的說法是絕無可能的猜想。

懷疑2：CPU的優先順序反轉問題，當前Binder線程處於低優先順序，無法分配到CPU資源而阻塞系統？

回答2：從bugreport中來分析定屏過程被阻塞線程的cpu調度情況。

先講解之前，先來補充一點關於CPU解讀技巧：

nice值越小則優先順序越高。此處nice=-2, 可見優先順序還是比較高的;

schedstat括弧中的3個數字依次是Running、Runable、Switch，緊接著的是utm和stm

Running時間：CPU運行的時間，單位ns

Runable時間：RQ隊列的等待時間，單位ns

Switch次數：CPU調度切換次數

utm: 該線程在用戶態所執行的時間，單位是jiffies，jiffies定義為sysconf(_SC_CLK_TCK)，默認等於10ms

stm: 該線程在內核態所執行的時間，單位是jiffies，默認等於10ms

可見，該線程Running=186667489018ns,也約等於186667ms。在CPU運行時間包括用戶態(utm)和內核態(stm)。 utm + stm = (12112 + 6554) ×10 ms = 186666ms。

結論：utm + stm = schedstat第一個參數值。

有了以上基礎知識，再來看bugreport，由於系統被hang住，watchdog每過一分鐘就會輸出依次調用棧。我們把每一次調用找的schedstat數據拿出來看一下，如下：

可見，Runable時間基本沒有變化，也就說明該線程並沒有處於CPU等待隊列而得不到CPU調度，同時Running時間也幾乎沒有動。 所以該線程長時間處於非Runable狀態，從而排除CPU優先順序反轉問題。

再看Event Log

疑問：appDiedLock()方法一般是通過BinderDied死亡回調的情況下才執行，但死亡回調肯定是位於其他線程，由於該binder線程正處於繁忙狀態，並沒有時間處理。 為什麼同一個線程正在執行attachApplication()的過程，並沒有結束的情況下還能執行appDiedLock()方法？

觀察多份定屏的EventLog，最後時刻都會先執行attachApplication()，然後執行appDiedLock()。

此處懷疑跟殺進程有關或者是在某種Binder嵌套調用的情況下，將這兩件事情合在binder線程？這些都只是猜疑，本身又是概率問題，需要更深入地分析才能解答這些疑團。

三、ramdump分析

有效的信息太少，基本無法採用進一步分析，只能通過抓取ramdump希望能通過裡面的蛛絲馬跡來推出整個過程。

抓取的ramdump是只是觸發定屏後的最後一刻的異常現場，這就好比犯罪現場最後的畫面，我們無法得知案發的動機是什麼， 更無法得知中間到底發生了哪些狀態。要基於ramdump的靜態畫面，去推演整個作案過程，需要強大的推演能力。 先來分析這個ramdump信息，找到儘可能多的有效信息。

3.1 結構體binder_thread從ramdump中找到當前處於blocked線程的調用棧上的方法binder_ioctl_write_read()， 該方法的的第4個參數指向binder_read結構體。

利用crash工具便可進一步找到binder_thread的結構體如下：

解讀：

waiting_thread_node為空，則說明binder線程的 thread→transaction_stack不為空 或者 thread→todo不為空；

todo為空，結合前面的waiting_thread_node，則說明thread→transaction_stack一定不為空；

return_error和reply_error的cmd等於29185， 轉換為16進位等於0x7201, 代表的命令為BR_OK = _IO(『r』, 1), 說明該binder線程的終態並沒有error，或者中間發生error並且已被消耗掉；

looper = 17, 說明該線程處於等待狀態BINDER_LOOPER_STATE_WAITING

3.2 binder_transaction結構體既然thread→transaction_stack不為空，根據結構體binder_thread的成員transaction_stack = 0xffffffddf1538180， 則解析出binder_transaction結構體：

解讀：

from = 0x0, 說明發起端進程已死

sender_euid=10058， 這裡正是event log中出現的被一鍵清理所殺的進程，這裡隱約能感受到此次異常跟殺進程有關

to_thread所指向的是當前system_server的binder線程，說明這是遠端進程向該進程發起的請求

flags = 16, 說明是同步binder call

code = 11，說明該調用attachApplication()，此處雖無法完成確定，但從上下文以及前面的stack，基本可以這麼認為，後續會論證。

到這裡，想到把binder介面下的信息也拿出來，看看跟前面基本是吻合的code=b, 也應該是attachApplication(), 如下：

3.3 特殊的2916

看一下kernel Log，被hang住的binder線程有一個Binder通信失敗的信息：

29189=0x7205代表的是BR_DEAD_REPLY = _IO(『r』, 5), 則代表return_error=BR_DEAD_REPLY，發生錯誤行是2916，什麼場景下代碼會走到2916行呢， 來看Binder Driver的代碼：

根據return_error=BR_DEAD_REPLY，從2916往回看則推測代碼應該是走到2908行代碼； 往上推說明target_node = context→binder_context_mgr_node，這個target_node是指service_manager進程的binder_node。 那麼binder_context_mgr_node為空的場景，只有觸發servicemanger進程死亡，或者至少重啟過；但通過查看servicemanger進程並沒有死亡和重啟； 本身走到2900行， tr->target.handle等於空，在這個上下文裡面就難以解釋了，現在這個來看更是矛盾。

到此，不得不懷疑推理存在紕漏，甚至懷疑日誌輸出機制。經過反覆驗證，才發現原來忽略了2893行的binder_get_node_refs_for_txn()，代碼如下：

一切就豁然開朗，由於對端進程被殺，那麼note→proc==null, 從而有了return_error=BR_DEAD_REPLY。

3.4 binder_write_read結構體

看完被阻塞的binder線程和事務結構體，接著需要看一下數據情況，調用棧上的binder_ioctl_write_read()方法的第三個參數便指向binder_write_read結構體， 用crash工具解析後，得到如下信息：

解讀：

write_size=0, 看起來有些特別，本次通信過程不需要往Binder Driver寫數據，常規transaction都有命令需寫入Binder Driver；

read_size=256，本次通信過程需要讀取數據；

那麼什麼場景下，會出現write_size等於0，而read_size不等於0呢？ 需要查看用戶空間跟內核空間的Binder Driver交互的核心方法talkWithDriver()，代碼如下：

從上述代碼可知：read_size不等於0，則doReceive=true, needRead=true，從而mIn等於空； 再加上write_size=0則mOut為空。 也就是說該blocked線程最後一次跟Binder驅動交互時的mIn和mOut都為空。

而目前的線程是卡在attachApplicationLocked()過程，在執行該方法的過程一定是會向mOut裡面寫入數據的。但從案發後的最後一次現場來看mOut裡面的數據卻為空， 這是違反常規的操作，第一直覺可能會懷疑是不是出現了內存踩踏之類的，但每次都這麼湊巧地能只踩踏這個數據，是不太可能的事。為了進一步驗證，再把mOut和mIn這兩個buffer的數據拿出來。

3.5 mOut && mInIPCThreadState結構體在初始化的時候，分別設置mOut和mIn的size為256。Binder IPC過程便是利用mOut和mIn 分別承擔向Binder驅動寫數據以及從Binder驅動讀數據的功能。

雖然在反覆使用的過程中會出現老的命令被覆蓋的情況， 但還是可能有一些有用信息。

mOut和mIn是用戶空間的數據，並且是IPCThreadState對象的成員變數。程序在用戶空間停在IPCThreadState的waitForResponse()過程， 採用GDB列印出當前線程用戶空間的this指針的所有成員，即可找到mOut和mIn

解讀： mIn緩存區，mDataSize = 16, mDataPos = 16, 說明最後的talkWithDriver產生了兩個BR命令，並且已處理；mOut緩存區，mDataSize = 0, mDataPos = 0，說明BC_XXX都已被消耗

再來進一步看看這兩個緩存區中的數據，從上圖可知mIn和mOut的mData地址分別為0x7747500300、0x7747500400，緩存區大小都等於256位元組； mIn緩存區中存放都是BR_XXX命令(0x72)；mOut緩存區中存放都是BC_XXX命令(0x63)。 再來分別看看兩個緩存區中的數據：

mIn緩存區數據：

解讀：BR_NOOP = 0x720c, BR_CLEAR_DEATH_NOTIFICATION_DONE = 0x7210，可知mIn數據區中最後一次talkWithDriver的過程產生了兩個BR命令依次是： BR_NOOP， BR_CLEAR_DEATH_NOTIFICATION_DONE

mOut緩存區數據：

解讀：BC_FREE_BUFFER = 0x6303, BC_DEAD_BINDER_DONE = 0x6310，可知mOut數據區最後一次talkWithDriver的過程，所消耗掉的BC命令依次是：BC_FREE_BUFFER, BC_DEAD_BINDER_DONE

分析兩份ramdump裡面的mOut和mIn數據區內容內容基本完全一致，緩存區中的BC和BR信息完全一致。整個過程，通過ramdump推導發現被阻塞線程的todo隊列居然為空，最後一次處理過的transaction是BC_FREE_BUFFER、BC_DEAD_BINDER_DONE和BR_NOOP、BR_CLEAR_DEATH_NOTIFICATION_DONE，能解讀出來對本案例有所關聯線索也就只有這麼多。

3.6 疑難懸案

解決系統疑難問題可能不亞於去案件偵破，而本案就好比是密室殺人案。

案發後第一時間去勘察現場(抓取ramdump)，從房門和窗口都是由內部緊鎖的(mIn緩存區的write_size等於0)，兇手作案後是如何逃離現場的(todo隊列為空)？從被害人(blocked線程)身體留下的劍傷並不會致命(非同步線程不會被阻塞)，那到底死因是什麼呢？

從現場種種跡象來看(ramdump推導)很有可能是這並非第一案發現場(BUG不是發現在當前binder transaction過程)，極有可能是兇手在它處作案(其他transaction)後，再移屍到當前案發現場(binder嵌套結束後回到上一級調用處)，那麼真正的第一案發現場又在哪裡呢？

Trace、Log、Ramdump推導、Crash工具、GDB工具等十八般武藝都用過一輪了，已經沒有更多的信息可以挖掘了，這個問題幾乎要成為無頭公案。

四、真相大白

4.1 案件偵破此案一日不破，有如鯁在噎，寢食難安。腦中反覆回放案發現場的周邊布置，有一個非常重大的疑點進入腦海，其中有一個物件（BC_DEAD_BINDER_DONE協議)正常應該在其他房間(binder死亡訃告相關)，可為何會出現在案發現場(bindApplication的waitForResponse過程)呢？

基於最後的現場，順著這個線索通過逆向推理分析，去試圖推演兇手的整個作案過程。但對於如此錯終複雜的案情(binder通信系統每時每刻都有大量的事transaction發生著，協議之間的轉換也比較複雜)。

這個逆向推理過程非常複雜，通過不斷逆向與正向結合分析，每一層逆向回推，都會有N種可能性，儘可能多地排除完全不可能的分支，保留可能的分支再繼續回推，在整個推演過程最為燒腦與費時，見封面照片有大量的推理過程。最終奇蹟般地找到了第一案發現場，也找到了復現方法，為了節省篇幅，此處省略一萬字。

直接拿出結論，真正的第一案發現場如下：在進程剛啟動不久，執行到linkToDeath()方法前的瞬間將其殺掉則能復現定屏：

4.2 案卷解讀這個問題的複雜在於，即便找到了第一個案發現場以及復現路徑，要完全理解中間的每一次協議轉換過程，也是比較複雜的。 通過如下命令打開binder driver的ftrace信息，用於輸出每次binder通信協議與數據。

整個binder通信會不斷地在用戶空間與內核空間之間進行切換, Binder IPC通信過程的數據流向說明：（ BINDER_WORK_XXX簡稱為BW_XXX）

mOut：記錄用戶空間向Binder Driver寫入的命令

通過binder_thread_write()和binder_transaction()方法消費BC命令，併產生相應的BW_XXX命令，也可能不產生BW命令

當thread->return_error.cmd != BR_OK，則不會執行binder_thread_write()過程

thread→todo: 記錄等待當前binder線程需要處理的BINDER_WORK

通過binder_thread_read()方法消費BW命令，並生產相應的BR_XX命令，也可能不產生BR命令

一般情況，沒有BC_TRANSACION或者BC_REPLY，則不讀取; BW_DEAD_BINDER例外；

mIn: 記錄Binder Driver傳到用戶空間的命令

通過waitForResponse()和executeCommand()方法消費BR命令

另外，關於talkWithDriver, 當mIn有數據，意味著先不需要從binder driver讀數據。原因：needRead=0，則read_buffer size設置為0，當doReceive=true，則write_buffer size也設置為0。從而此次不會跟driver交互。

案發過程詳細過程：

過程解讀：(整個過程發生了9次 talkWithDriver）

該線程執行linkToDeath()，採用flush只寫不讀的方式，向Binder Driver的thread todo隊列寫入BW_DEAD_BINDER；

執行bindApplication(), 由於目標進程已死，則寫入BW_RETURN_ERROR到todo隊列，此時return_error.cmd = BR_DEAD_REPLY; 內核空間，將BW_DEAD_BINDER轉換為BR_DEAD_BINDER，同步將BW_DEAD_BINDER 放入proc->delivered_death; 回到用戶空間，執行sendObituary()， 此時還處於bindApplication()的waitForResponse()。

向mOut添加BC_CLEAR_DEATH_NOTIFICATION，採用flush方式，加上return_error.cmd = BR_DEAD_REPLY，此次不寫不讀。

執行第一個reportOneDeath()，此時return_error.cmd = BR_DEAD_REPLY則不寫入，取出BW_RETURN_ERROR，同時設置return_error.cmd=BR_OK； 回到用戶空間，終結第一個reportOneDeath()，錯誤地消耗了bindApplication()所產生的BR_DEAD_REPLY。

執行第二個reportOneDeath()，同時消耗了第一個和第二個reportOneDeath所產生的BR_TRANSACTION_COMPLETE協議，由於第二個reportOneDeath是同步binder call, 還需繼續等待BR_REPLY協議。

此時mOut和mIn都為空，進入內核binder_wait_for_work(),等待目標進程發起BC_REPLY命令，向當前線程todo隊列放入BW_TRANSACTION；收到BW_TRANSACTION協議後轉換為BR_REPLY，完成第二個reportOneDeath()。

執行第三個reportOneDeath()，收到BR_TRANSACTION_COMPLETE後，完成第二個reportOneDeath()。

到此徹底執行完sendObituary()，則需向mOut添加BC_DEAD_BINDER_DONE協議，收到該協議後，驅動將proc→delivered_death的BW_DEAD_BINDER_AND_CLEAR調整為BW_CLEAR_DEATH_NOTIFICATION，並放入thread->todo隊列；然後生成BR_CLEAR_DEATH_NOTIFICATION_DONE，完成本次通信；

回到bindApplication()的waitForResponse，此時mOut和mIn都為空，進入內核binder_wait_for_work(), 該線程不再接收其他事務，也無法產生事務，則永遠地被卡住。

共的來說，導致非同步binder調用阻塞原因如下：

第一個非同步reportOneDeath()消費掉bindApplication()所產生的BW_RETURN_ERROR；

第二個同步reportOneDeath()所消耗掉 第一個非同步reportOneDeath()自身殘留的BR_TRANSACTION_COMPLETE；

bindApplication()所產生的BW_RETURN_ERROR由於被別人所消費，導致陷入無盡地等待。

4.3 總結真正分析遠比這複雜，鑒於篇幅，文章只講解其中一個場景，不同的Binder Driver以及不同的Framework代碼組合有幾種不同的表現與處理流程。不過最本質的問題都是在於在嵌套的binder通信過程，BR_DEAD_REPLY錯誤地被其他通信所消耗從而導致的異常。

我的解決方案是當transaction發生錯誤，則將BW_RETURN_ERROR事務放入到當前線程todo隊列頭部，則保證自己產生的BW_RETURN_ERROR事務一定會被自己所正確地消耗，從而解決非同步binder通信在嵌套場景下的無限阻塞的問題，優化後的處理流程圖：

當然還有第二個解決方案就是儘可能避免一切binder嵌套，Google在最新的binder driver驅動裡面採用將BW_DEAD_BINDER放入proc的todo隊列來避免嵌套問題，這個方案本身也可以，但我認為在執行過程出現了BW_RETURN_ERROR還是應該放到隊列頭部，第一時間處理error，從而也能避免被錯誤消耗的BUG，另外後續如果binder新增其他邏輯，也有可能會導致嵌套的出現，那麼仍然會有類似的問題。

最近跟Google工程師來回多次溝通過這個問題，但他們仍然希望保持每次只往thread todo隊列尾部添加事務的邏輯，對於嵌套問題希望通過將其放入proc todo隊列的方式來解決。對此，擔心後續擴展性方面會忽略或者遺忘，又引發binder嵌套問題，Google工程師表示未來添加新功能，也會杜絕出現嵌套邏輯，保持邏輯與代碼的簡潔。

最後，這個密室殺人案的確是在它處作案(reportOneDeath消費掉bindApplication所產生的BW_RETURN_ERROR)後，再移屍到當前案發現場(執行完BR_DEAD_BINDER後回到bindApplication的waitForRespone方法)，從而導致非同步Binder調用也能被阻塞。

Android達摩院

喜歡這篇文章嗎？立刻分享出去讓更多人知道吧！