異步binder call是如何阻塞整個系統(tǒng)的

引言

本文講解異步binder call是如何阻塞整個系統(tǒng)的，通過ramdump信息以及binder通信協(xié)議來演繹并還原定屏現場。

一、背景知識點

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

1.1 工具簡介

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

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

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

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

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

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

1.2 Binder簡介

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

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

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

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

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

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

退出waitForResponse場景說明：

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

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

二、初步分析

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

2.1 問題描述

Android 8.0系統(tǒng)用幾十臺手機連續(xù)跑幾十個小時Monkey的情況下有概率出現定屏問題。

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

2.2 初步分析

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

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

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

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

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

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

真正的oneway binder call， 一旦是事務發(fā)送出去。 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的優(yōu)先級反轉問題，當前Binder線程處于低優(yōu)先級，無法分配到CPU資源而阻塞系統(tǒng)？

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

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

nice值越小則優(yōu)先級越高。此處nice=-2, 可見優(yōu)先級還是比較高的;

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

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

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

Switch次數：CPU調度切換次數

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

stm: 該線程在內核態(tài)所執(zhí)行的時間，單位是jiffies，默認等于10ms

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

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

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

可見，Runable時間基本沒有變化，也就說明該線程并沒有處于CPU等待隊列而得不到CPU調度，同時Running時間也幾乎沒有動。 所以該線程長時間處于非Runable狀態(tài)，從而排除CPU優(yōu)先級反轉問題。

再看Event Log

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

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

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

三、ramdump分析

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

抓取的ramdump是只是觸發(fā)定屏后的最后一刻的異常現場，這就好比犯罪現場最后的畫面，我們無法得知案發(fā)的動機是什么， 更無法得知中間到底發(fā)生了哪些狀態(tài)。要基于ramdump的靜態(tài)畫面，去推演整個作案過程，需要強大的推演能力。 先來分析這個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線程的終態(tài)并沒有error，或者中間發(fā)生error并且已被消耗掉；

looper = 17, 說明該線程處于等待狀態(tài)BINDER_LOOPER_STATE_WAITING

3.2 binder_transaction結構體

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

解讀：

from = 0x0, 說明發(fā)起端進程已死

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

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

flags = 16, 說明是同步binder call

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

到這里，想到把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，發(fā)生錯誤行是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為空的場景，只有觸發(fā)servicemanger進程死亡，或者至少重啟過；但通過查看servicemanger進程并沒有死亡和重啟； 本身走到2900行， tr->target.handle等于空，在這個上下文里面就難以解釋了，現在這個來看更是矛盾。

到此，不得不懷疑推理存在紕漏，甚至懷疑日志輸出機制。經過反復驗證，才發(fā)現原來忽略了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寫數據，常規(guī)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()過程，在執(zhí)行該方法的過程一定是會向mOut里面寫入數據的。但從案發(fā)后的最后一次現場來看mOut里面的數據卻為空， 這是違反常規(guī)的操作，第一直覺可能會懷疑是不是出現了內存踩踏之類的，但每次都這么湊巧地能只踩踏這個數據，是不太可能的事。為了進一步驗證，再把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緩存區(qū)，mDataSize = 16, mDataPos = 16, 說明最后的talkWithDriver產生了兩個BR命令，并且已處理；mOut緩存區(qū)，mDataSize = 0, mDataPos = 0，說明BC_XXX都已被消耗

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

mIn緩存區(qū)數據：

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

mOut緩存區(qū)數據：

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

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

3.6 疑難懸案

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

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

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

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

四、真相大白

4.1 案件偵破

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

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

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

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

4.2 案卷解讀

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

整個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，則不會執(zhí)行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交互。

案發(fā)過程詳細過程：

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

該線程執(zhí)行l(wèi)inkToDeath()，采用flush只寫不讀的方式，向Binder Driver的thread todo隊列寫入BW_DEAD_BINDER；

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

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

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

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

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

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

到此徹底執(zhí)行完sendObituary()，則需向mOut添加BC_DEAD_BINDER_DONE協(xié)議，收到該協(xié)議后，驅動將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發(fā)生錯誤，則將BW_RETURN_ERROR事務放入到當前線程todo隊列頭部，則保證自己產生的BW_RETURN_ERROR事務一定會被自己所正確地消耗，從而解決異步binder通信在嵌套場景下的無限阻塞的問題，優(yōu)化后的處理流程圖：

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

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

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