原文來自我的微信公眾號： Android達摩院
本文講解非同步binder call是如何阻塞整個系統的，透過ramdump資訊以及binder通訊協議來演繹並還原定屏現場，分析過程之複雜，見封面稿紙。
一、背景知識點
解決此問題所涉及到的基礎知識點有：Trace、CPU排程、Ramdump推導、Crash工具、GDB工具、Ftrace，尤其深入理解binder IPC機制。
歡迎關注Gityuan的微信公眾號：
Android達摩院(AndroidAcademy)
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不太瞭解看本文會非常吃力，在
http：//
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
01-19 19：02：33。668 12635 24699 I am_proc_start： ［0，6686，10058，com。xxx。calculator，activity，com。xxx。calculator/。convert。ConvertActivity］
01-19 19：02：33。840 12635 12846 I am_kill ： ［0，6686，com。xxx。calculator，-10000，remove task］
01-19 19：02：33。911 12635 13399 I am_proc_bound： ［0，6686，com。xxx。calculator］
01-19 19：02：33。913 12635 13399 I am_proc_died： ［0，6686，com。xxx。calculator，18］
疑問：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（）， 如下：
thread 13399： l 11 need_return 0 tr 0
incoming transaction 2845163： ffffffddf1538180 from 0：0 to 12635：13399 code b
flags 10 pri 0：120 r1 node 466186 size 92：8 data ffffff8014202c98
3。3 特殊的2916
看一下kernel Log，被hang住的binder執行緒有一個Binder通訊失敗的資訊：
binder ： release 6686：6686 transaction 2845163 out， still active
binder ： 12635：13399 transaction failed 29189/-22， size 3812-24 line 2916
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 && mIn
IPCThreadState結構體在初始化的時候，分別設定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種可能性，透過不斷排除其他的可能性，儘可能多地排除完全不可能的分支，保留可能的分支再繼續回推，最終奇蹟般地找到了第一案發現場，也找到了復現方法。
這個逆向推理過程非常複雜，首先需要深入掌握Binder原理，在整個推演過程最為燒腦與費時。為了節省篇幅，此處省略一萬字。
直接拿出結論，真正的第一案發現場如下：在程序剛啟動不久，執行到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互動。
以下是一次定屏復現過程吐出的ftrace資訊：
Binder：1885_5-2351 ［002］ 。。。1 242。804499： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce6928
Binder：1885_5-2351 ［002］ 。。。1 242。804503： binder_command： cmd=0x40046304 BC_INCREFS
Binder：1885_5-2351 ［002］ 。。。1 242。804515： binder_command： cmd=0x40046305 BC_ACQUIRE
Binder：1885_5-2351 ［002］ 。。。1 242。804517： binder_command： cmd=0x400c630e BC_REQUEST_DEATH_NOTIFICATION
Binder：1885_5-2351 ［002］ 。。。1 242。804524： binder_write_done： ret=0
Binder：1885_5-2351 ［002］ 。。。1 242。804526： binder_ioctl_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。854847： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce4f18
Binder：1885_5-2351 ［003］ 。。。1 242。854852： binder_command： cmd=0x40406300 BC_TRANSACTION // bindApplication（），
Binder：1885_5-2351 ［003］ 。。。1 242。854900： binder_write_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。854902： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=1
//binder_thread_read（）處理BINDER_WORK_DEAD_BINDER，生成BR_DEAD_BINDER
Binder：1885_5-2351 ［003］ 。。。1 242。854905： binder_return： cmd=0x8008720f BR_DEAD_BINDER
Binder：1885_5-2351 ［003］ 。。。1 242。854906： binder_read_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。854908： binder_ioctl_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。854920： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce4d58
//既有可能是thread->return_error。cmd ！= BR_OK
Binder：1885_5-2351 ［003］ 。。。1 242。854922： binder_write_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。854923： binder_ioctl_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。863203： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce1c08
Binder：1885_5-2351 ［003］ 。。。1 242。863258： binder_write_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。863263： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=1
//取出BINDER_WORK_RETURN_ERROR， BR_DEAD_REPLY， 此次炸死。BR_TRANSACTION_COMPLETE僅僅是列印錯誤
Binder：1885_5-2351 ［003］ 。。。1 242。863272： binder_return： cmd=0x7206 BR_TRANSACTION_COMPLETE
Binder：1885_5-2351 ［003］ 。。。1 242。863276： binder_read_done： ret=0
Binder：1885_5-2351 ［003］ 。。。1 242。863279： binder_ioctl_done： ret=0
// sendObituary（）
Binder：1885_5-2351 ［003］ 。。。1 242。868356： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce31a8
Binder：1885_5-2351 ［003］ 。。。1 242。868392： binder_command： cmd=0x400c630f BC_CLEAR_DEATH_NOTIFICATION
//雷被拿了，return_error=BR_Ok才可以寫； 將death->work。type由BINDER_WORK_DEAD_BINDER改為 BINDER_WORK_DEAD_BINDER_AND_CLEAR。
Binder：1885_5-2351 ［003］ 。。。1 242。868403： binder_command： cmd=0x40406300 BC_TRANSACTION //（同步）
Binder：1885_5-2351 ［003］ 。。。1 242。868707： binder_transaction： transaction=187839 dest_node=14103 dest_proc=2198 dest_thread=0 reply=0 flags=0x11 code=0x1f
Binder：1885_5-2351 ［003］ 。。。1 242。868734： binder_transaction_alloc_buf： transaction=187839 data_size=96 offsets_size=0
Binder：1885_5-2351 ［003］ 。。。1 242。868786： binder_command： cmd=0x40406300 BC_TRANSACTION //（非同步）
Binder：1885_5-2351 ［003］ 。。。1 242。868802： binder_transaction： transaction=187840 dest_node=563 dest_proc=746 dest_thread=0 reply=0 flags=0x10 code=0x8
Binder：1885_5-2351 ［003］ 。。。1 242。868807： binder_transaction_alloc_buf： transaction=187840 data_size=1952 offsets_size=112
Binder：1885_5-2351 ［003］ 。。。2 242。868822： binder_transaction_ref_to_node： transaction=187840 node=37276 src_ref=37277 src_desc=940 ==> dest_ptr=0x00000079ba160780
Binder：1885_5-2351 ［003］ 。。。2 242。868829： binder_transaction_ref_to_node： transaction=187840 node=158140 src_ref=158141 src_desc=116 ==> dest_ptr=0x00000079ba03f6c0
Binder：1885_5-2351 ［003］ 。。。2 242。868833： binder_transaction_ref_to_node： transaction=187840 node=8192 src_ref=8193 src_desc=110 ==> dest_ptr=0x00000079bc81b220
Binder：1885_5-2351 ［003］ 。。。2 242。868837： binder_transaction_ref_to_node： transaction=187840 node=18544 src_ref=18545 src_desc=416 ==> dest_ptr=0x00000079ba1dbd20
Binder：1885_5-2351 ［003］ 。。。2 242。868839： binder_transaction_ref_to_node： transaction=187840 node=8192 src_ref=8193 src_desc=110 ==> dest_ptr=0x00000079bc81b220
Binder：1885_5-2351 ［003］ 。。。2 242。868842： binder_transaction_ref_to_node： transaction=187840 node=18659 src_ref=18660 src_desc=420 ==> dest_ptr=0x00000079bd0b3720
Binder：1885_5-2351 ［003］ 。。。2 242。868844： binder_transaction_ref_to_node： transaction=187840 node=8192 src_ref=8193 src_desc=110 ==> dest_ptr=0x00000079bc81b220
Binder：1885_5-2351 ［003］ 。。。2 242。868847： binder_transaction_ref_to_node： transaction=187840 node=18719 src_ref=18720 src_desc=423 ==> dest_ptr=0x00000079bd0b4120
Binder：1885_5-2351 ［003］ 。。。2 242。868849： binder_transaction_ref_to_node： transaction=187840 node=8192 src_ref=8193 src_desc=110 ==> dest_ptr=0x00000079bc81b220
Binder：1885_5-2351 ［003］ 。。。2 242。868852： binder_transaction_ref_to_node： transaction=187840 node=18919 src_ref=18920 src_desc=431 ==> dest_ptr=0x00000079ba1ba320
Binder：1885_5-2351 ［003］ 。。。2 242。868854： binder_transaction_ref_to_node： transaction=187840 node=8192 src_ref=8193 src_desc=110 ==> dest_ptr=0x00000079bc81b220
Binder：1885_5-2351 ［003］ 。。。2 242。868857： binder_transaction_ref_to_node： transaction=187840 node=18785 src_ref=18786 src_desc=425 ==> dest_ptr=0x00000079bd0b4a20
Binder：1885_5-2351 ［003］ 。。。2 242。868863： binder_transaction_ref_to_node： transaction=187840 node=130076 src_ref=130077 src_desc=1405 ==> dest_ptr=0x00000079ba03f060
Binder：1885_5-2351 ［003］ 。。。2 242。868867： binder_transaction_ref_to_node： transaction=187840 node=159857 src_ref=159858 src_desc=154 ==> dest_ptr=0x00000079ba160c40
Binder：1885_5-2351 ［000］ 。。。1 242。869114： binder_write_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。869117： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=1
Binder：1885_5-2351 ［000］ 。。。1 242。869120： binder_return： cmd=0x7206 BR_TRANSACTION_COMPLETE
Binder：1885_5-2351 ［000］ 。。。1 242。869122： binder_return： cmd=0x7206 BR_TRANSACTION_COMPLETE
Binder：1885_5-2351 ［000］ 。。。1 242。869124： binder_read_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。869126： binder_ioctl_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。869137： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce31a8
Binder：1885_5-2351 ［000］ 。。。1 242。869140： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=0
Binder：1885_5-2351 ［000］ 。。。1 242。869195： binder_transaction_received： transaction=187841
Binder：1885_5-2351 ［000］ 。。。1 242。869198： binder_return： cmd=0x80407203 BR_REPLY
Binder：1885_5-2351 ［000］ 。。。1 242。869202： binder_read_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。869203： binder_ioctl_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。873656： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce1e98
Binder：1885_5-2351 ［000］ 。。。1 242。873664： binder_command： cmd=0x40086303 BC_FREE_BUFFER
Binder：1885_5-2351 ［000］ 。。。1 242。873668： binder_transaction_buffer_release： transaction=187841 data_size=0 offsets_size=0
Binder：1885_5-2351 ［000］ 。。。1 242。873671： binder_command： cmd=0x40406300 BC_TRANSACTION
Binder：1885_5-2351 ［000］ 。。。1 242。873784： binder_transaction： transaction=187849 dest_node=127265 dest_proc=5730 dest_thread=0 reply=0 flags=0x11 code=0x31
Binder：1885_5-2351 ［000］ 。。。1 242。873787： binder_transaction_alloc_buf： transaction=187849 data_size=76 offsets_size=0
Binder：1885_5-2351 ［000］ 。。。1 242。873814： binder_write_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。873816： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=1
Binder：1885_5-2351 ［000］ 。。。1 242。873820： binder_return： cmd=0x7206 BR_TRANSACTION_COMPLETE
Binder：1885_5-2351 ［000］ 。。。1 242。873821： binder_read_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。873823： binder_ioctl_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。876271： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce1e98
Binder：1885_5-2351 ［000］ 。。。1 242。876302： binder_command： cmd=0x40406300 BC_TRANSACTION
Binder：1885_5-2351 ［000］ 。。。1 242。876417： binder_transaction： transaction=187850 dest_node=23725 dest_proc=3051 dest_thread=0 reply=0 flags=0x11 code=0x31
Binder：1885_5-2351 ［000］ 。。。1 242。876423： binder_transaction_alloc_buf： transaction=187850 data_size=76 offsets_size=0
Binder：1885_5-2351 ［000］ 。。。1 242。876456： binder_write_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。876459： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=1
Binder：1885_5-2351 ［000］ 。。。1 242。876461： binder_return： cmd=0x7206 BR_TRANSACTION_COMPLETE
Binder：1885_5-2351 ［000］ 。。。1 242。876463： binder_read_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。876464： binder_ioctl_done： ret=0
// sendObituary（）結束
Binder：1885_5-2351 ［000］ 。。。1 242。886935： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce4f18
Binder：1885_5-2351 ［000］ 。。。1 242。886975： binder_command： cmd=0x40086310 BC_DEAD_BINDER_DONE
Binder：1885_5-2351 ［000］ 。。。1 242。886980： binder_write_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。886984： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=1
Binder：1885_5-2351 ［000］ 。。。1 242。886993： binder_return： cmd=0x80087210 BR_CLEAR_DEATH_NOTIFICATION_DONE
Binder：1885_5-2351 ［000］ 。。。1 242。886996： binder_read_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。886999： binder_ioctl_done： ret=0
Binder：1885_5-2351 ［000］ 。。。1 242。887012： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce4f18
Binder：1885_5-2351 ［000］ 。。。1 242。887013： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=0
Binder：1885_5-2351 ［000］ 。。。1 260。021887： binder_read_done： ret=-512
Binder：1885_5-2351 ［000］ 。。。1 260。021893： binder_ioctl_done： ret=-512
Binder：1885_5-2351 ［000］ 。。。1 260。023938： binder_ioctl： cmd=0xc0306201 arg=0x71f6ce4f18
Binder：1885_5-2351 ［000］ 。。。1 260。023972： binder_wait_for_work： proc_work=0 transaction_stack=1 thread_todo=0
將以上資訊轉換為表格形式來展示案發過程：
以流程圖的方式來展示案發過程：
過程解讀：
該執行緒執行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（）， 該執行緒不再接收其他事務，也無法產生事務，則永遠地被卡住。
總結：整個過程發生了10次 talkWithDriver（）
第一個非同步reportOneDeath（）消費掉bindApplication（）所產生的BW_RETURN_ERROR；
第二個同步reportOneDeath（）所消耗掉 第一個非同步reportOneDeath（）自身殘留的BR_TRANSACTION_COMPLETE；
bindApplication（）所產生的BW_RETURN_ERROR由於被別人所消費，導致陷入無盡地等待。
4。3 總結
真正分析遠比這複雜，鑑於篇幅，文章只講解其中一個場景，不同的Binder Driver以及不同的Framework程式碼組合有幾種不同的表現與處理流程。不過最本質的問題都是在於在巢狀的binder通訊過程，BR_DEAD_REPLY錯誤地被其他通訊所消耗從而導致的異常。我的解決方案是一旦發生錯誤，則當BW_RETURN_ERROR事務放入到當前執行緒todo佇列頭部，則保證自己產生的BW_RETURN_ERROR事務一定會被自己所正確地消耗，解決非同步binder通訊在巢狀場景下的無限阻塞的問題，最佳化後的處理流程圖：
當然還有第二個解決方案就是儘可能避免一切binder巢狀，Google在最新的binder driver驅動裡面採用將BW_DEAD_BINDER放入proc的todo佇列來避免巢狀問題，這個方案本身也OK，但我認為在執行過程出現了BW_RETURN_ERROR還是應該放到佇列頭部，第一時間處理error，從而也能避免被錯誤消耗的BUG，另外後續如果binder新增其他邏輯，也有可能會導致巢狀的出現，那麼仍然會有類似的問題。最近跟Google工程師來回多次溝透過這個問題，他們仍然希望保持每次只往thread todo佇列尾部新增事務的邏輯，對於巢狀問題希望透過將其放入proc todo佇列的方式來解決。對此，我擔心後續擴充套件性方面會忽略或者遺忘，又引發binder巢狀問題，Google工程師表示未來新增新功能，也會杜絕出現巢狀邏輯，保持邏輯與程式碼的簡潔。
最後，這個密室殺人案的確是在它處作案（reportOneDeath消費掉bindApplication所產生的BW_RETURN_ERROR）後，再移屍到當前案發現場（執行完BR_DEAD_BINDER後回到bindApplication的waitForRespone方法），從而導致非同步Binder呼叫也能被阻塞。
