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

一、背景知識(shí)點(diǎn)

解決此問題所涉及到的基礎(chǔ)知識(shí)點(diǎn)有：Trace、CPU調(diào)度、Ramdump推導(dǎo)、Crash工具、GDB工具、Ftrace， 尤其深入理解binder IPC機(jī)制。

1.1 工具簡介

• Trace：分析死鎖問題的最基本的技能，通過kill -3可生成相應(yīng)的traces.txt文件，里面記錄著當(dāng)前時(shí)刻系統(tǒng)各線程 所處在的調(diào)用棧。
• CPU調(diào)度：可通過查看schedstat節(jié)點(diǎn)，得知該線程是否長時(shí)間處于RQ隊(duì)列的等待
• Ramdump：把系統(tǒng)memory中某一個(gè)時(shí)間點(diǎn)的數(shù)據(jù)信息保存起來的內(nèi)存崩潰文件，屬于ELF文件格式。 當(dāng)系統(tǒng)發(fā)生致命錯(cuò)誤無法恢復(fù)的時(shí)候，主動(dòng)觸發(fā)抓取ramdump能異?，F(xiàn)場保留下來，這是屬于高級(jí)調(diào)試秘籍。
• Crash工具：用于推導(dǎo)與分析ramdump內(nèi)存信息。
• GDB工具：由GNU開源組織發(fā)布的、UNIX/LINUX操作系統(tǒng)下的基于命令行的強(qiáng)大調(diào)試工具，比如用于分析coredump
• Ftrace：用于分析Linux內(nèi)核的運(yùn)行時(shí)行為的強(qiáng)有力工具，比如能某方法的耗時(shí)數(shù)據(jù)、代碼的執(zhí)行流情況。

1.2 Binder簡介

Binder IPC是最為整個(gè)Android系統(tǒng)跨進(jìn)程通信的基石，整個(gè)系統(tǒng)絕大多數(shù)的跨進(jìn)程都是采用Binder，如果對(duì)Binder不太了解看本文會(huì)非常吃力，在Gityuan.com博客中有大量講解關(guān)于Binder原理的文章，見http://gityuan.com/2015/10/31/binder-prepare/。這里不再贅述，簡單列兩張關(guān)于Binder通信架構(gòu)的圖。

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

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

從圖中，可見當(dāng)一次binder call發(fā)起后便停在waitForResponse()方法，等待執(zhí)行完具體工作后才能結(jié)束。 那么什么時(shí)機(jī)binder call端會(huì)退出waitForResponse()方法？見下圖：

退出waitForResponse場景說明：

• 1）當(dāng)Client收到BR_DEAD_REPLY或BR_FAILED_REPLY(往往是對(duì)端進(jìn)程被殺或者transaction執(zhí)行失敗)，則無論是同步還是異步的binder call都會(huì)結(jié)束waitForResponse()方法。
• 2）正常通信的情況下，當(dāng)收到BR_TRANSACTION_COMPLETE則結(jié)束同步binder call； 當(dāng)收到BR_REPLY則結(jié)束異步binder call。

二、初步分析

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

2.1 問題描述

Android 8.0系統(tǒng)用幾十臺(tái)手機(jī)連續(xù)跑幾十個(gè)小時(shí)Monkey的情況下有概率出現(xiàn)定屏問題。

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

2.2 初步分析

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

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

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

懷疑1：有同學(xué)可能會(huì)覺得是不是Binder驅(qū)動(dòng)里的休眠喚醒問題，對(duì)端進(jìn)程出現(xiàn)異常導(dǎo)致無法喚醒該binder線程從而阻塞系統(tǒng)？?
回答1：這個(gè)觀點(diǎn)咋一看，好像合情合理，還挺能唬人的。接下來，我先來科普一下，以正視聽。

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

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

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

也就是說bindApplication()方法作為異步binder調(diào)用方法，只會(huì)等待自己向自己todo隊(duì)列寫入的BR_TRANSACTION_COMPLETE或BR_DEAD_REPLY或BR_FAILED_REPLY。

所以說，對(duì)端進(jìn)程無法喚醒的說法是絕無可能的猜想。

懷疑2：CPU的優(yōu)先級(jí)反轉(zhuǎn)問題，當(dāng)前Binder線程處于低優(yōu)先級(jí)，無法分配到CPU資源而阻塞系統(tǒng)？?
回答2：從bugreport中來分析定屏過程被阻塞線程的cpu調(diào)度情況。

先講解之前，先來補(bǔ)充一點(diǎn)關(guān)于CPU解讀技巧：

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

schedstat括號(hào)中的3個(gè)數(shù)字依次是Running、Runable、Switch，緊接著的是utm和stm

• Running時(shí)間：CPU運(yùn)行的時(shí)間，單位ns
• Runable時(shí)間：RQ隊(duì)列的等待時(shí)間，單位ns
• Switch次數(shù)：CPU調(diào)度切換次數(shù)
• utm: 該線程在用戶態(tài)所執(zhí)行的時(shí)間，單位是jiffies，jiffies定義為sysconf(_SC_CLK_TCK)，默認(rèn)等于10ms
• stm: 該線程在內(nèi)核態(tài)所執(zhí)行的時(shí)間，單位是jiffies，默認(rèn)等于10ms

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

結(jié)論：utm + stm = schedstat第一個(gè)參數(shù)值。

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

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

再看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死亡回調(diào)的情況下才執(zhí)行，但死亡回調(diào)肯定是位于其他線程，由于該binder線程正處于繁忙狀態(tài)，并沒有時(shí)間處理。 為什么同一個(gè)線程正在執(zhí)行attachApplication()的過程，并沒有結(jié)束的情況下還能執(zhí)行appDiedLock()方法？

觀察多份定屏的EventLog，最后時(shí)刻都會(huì)先執(zhí)行attachApplication()，然后執(zhí)行appDiedLock()。此處懷疑跟殺進(jìn)程有關(guān)，或者是在某種Binder嵌套調(diào)用的情況下，將這兩件事情合在binder線程？這些都只是猜疑，本身又是概率問題，需要更深入地分析才能解答這些疑團(tuán)。

三、ramdump分析

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

抓取的ramdump是只是觸發(fā)定屏后的最后一刻的異?，F(xiàn)場，這就好比犯罪現(xiàn)場最后的畫面，我們無法得知案發(fā)的動(dòng)機(jī)是什么， 更無法得知中間到底發(fā)生了哪些狀態(tài)。要基于ramdump的靜態(tài)畫面，去推演整個(gè)作案過程，需要強(qiáng)大的推演能力。 先來分析這個(gè)ramdump信息，找到盡可能多的有效信息。

3.1 結(jié)構(gòu)體binder_thread

從ramdump中找到當(dāng)前處于blocked線程的調(diào)用棧上的方法binder_ioctl_write_read()， 該方法的的第4個(gè)參數(shù)指向binder_read結(jié)構(gòu)體， 采用crash工具便可進(jìn)一步找到binder_thread的結(jié)構(gòu)體如下：

解讀：

• waiting_thread_node為空，則說明binder線程的 thread→transaction_stack不為空 或者 thread→todo不為空；
• todo為空，結(jié)合前面的waiting_thread_node，則說明thread→transaction_stack一定不為空；
• return_error和reply_error的cmd等于29185， 轉(zhuǎn)換為16進(jìn)制等于0x7201, 代表的命令為BR_OK = _IO(‘r’, 1), 說明該binder線程的終態(tài)并沒有error，或者中間發(fā)生error并且已被消耗掉；
• looper = 17, 說明該線程處于等待狀態(tài)BINDER_LOOPER_STATE_WAITING

3.2 binder_transaction結(jié)構(gòu)體

既然thread→transaction_stack不為空，根據(jù)結(jié)構(gòu)體binder_thread的成員transaction_stack = 0xffffffddf1538180， 則解析出binder_transaction結(jié)構(gòu)體

解讀：

• from = 0x0, 說明發(fā)起端進(jìn)程已死
• sender_euid=10058， 這里正是event log中出現(xiàn)的被一鍵清理所殺的進(jìn)程，這里隱約能感受到此次異常跟殺進(jìn)程有關(guān)
• to_thread所指向的是當(dāng)前system_server的binder線程，說明這是遠(yuǎn)端進(jìn)程向該進(jìn)程發(fā)起的請求
• flags = 16, 說明是同步binder call
• code = 11，說明該調(diào)用attachApplication()，此處雖無法完成確定，但從上下文以及前面的stack，基本可以這么認(rèn)為，后續(xù)會(huì)論證。

到這里，想到把binder接口下的信息也拿出來，看看跟前面基本是吻合的code=b, 也應(yīng)該是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線程有一個(gè)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ā)生錯(cuò)誤行是2916，什么場景下代碼會(huì)走到2916行呢， 來看Binder Driver的代碼：

根據(jù)return_error=BR_DEAD_REPLY，從2916往回看則推測代碼應(yīng)該是走到2908行代碼； 往上推說明target_node = context→binder_context_mgr_node，這個(gè)target_node是指service_manager進(jìn)程的binder_node。 那么binder_context_mgr_node為空的場景，只有觸發(fā)servicemanger進(jìn)程死亡，或者至少重啟過；但通過查看servicemanger進(jìn)程并沒有死亡和重啟； 本身走到2900行， tr->target.handle等于空，在這個(gè)上下文里面就難以解釋了，現(xiàn)在這個(gè)來看更是矛盾。

到此，不得不懷疑推理存在紕漏，甚至懷疑日志輸出機(jī)制。經(jīng)過反復(fù)驗(yàn)證，才發(fā)現(xiàn)原來忽略了2893行的binder_get_node_refs_for_txn()，代碼如下：

一切就豁然開朗，由于對(duì)端進(jìn)程被殺，那么note→proc==null, 從而有了return_error=BR_DEAD_REPLY。

3.4 binder_write_read結(jié)構(gòu)體

看完被阻塞的binder線程和事務(wù)結(jié)構(gòu)體，接著需要看一下數(shù)據(jù)情況，調(diào)用棧上的binder_ioctl_write_read()方法的第三個(gè)參數(shù)便指向binder_write_read結(jié)構(gòu)體， 用crash工具解析后，得到如下信息：

解讀：

• write_size=0, 看起來有些特別，本次通信過程不需要往Binder Driver寫數(shù)據(jù)，常規(guī)transaction都有命令需寫入Binder Driver；
• read_size=256，本次通信過程需要讀取數(shù)據(jù)；

那么什么場景下，會(huì)出現(xiàn)write_size等于0，而read_size不等于0呢？ 需要查看用戶空間跟內(nèi)核空間的Binder Driver交互的核心方法talkWithDriver()，代碼如下：

從上述代碼可知：read_size不等于0，則doReceive=true, needRead=true，從而mIn等于空； 再加上write_size=0則mOut為空。 也就是說該blocked線程最后一次跟Binder驅(qū)動(dòng)交互時(shí)的mIn和mOut都為空。

而目前的線程是卡在attachApplicationLocked()過程，在執(zhí)行該方法的過程一定是會(huì)向mOut里面寫入數(shù)據(jù)的。但從案發(fā)后的最后一次現(xiàn)場來看mOut里面的數(shù)據(jù)卻為空， 這是違反常規(guī)的操作，第一直覺可能會(huì)懷疑是不是出現(xiàn)了內(nèi)存踩踏之類的，但每次都這么湊巧地能只踩踏這個(gè)數(shù)據(jù)，是不太可能的事。為了進(jìn)一步驗(yàn)證，再把mOut和mIn這兩個(gè)buffer的數(shù)據(jù)拿出來。

3.5 mOut && mIn

IPCThreadState結(jié)構(gòu)體在初始化的時(shí)候，分別設(shè)置mOut和mIn的size為256。Binder IPC過程便是利用mOut和mIn 分別承擔(dān)向Binder驅(qū)動(dòng)寫數(shù)據(jù)以及從Binder驅(qū)動(dòng)讀數(shù)據(jù)的功能。雖然在反復(fù)使用的過程中會(huì)出現(xiàn)老的命令被覆蓋的情況， 但還是可能有一些有用信息。

mOut和mIn是用戶空間的數(shù)據(jù)，并且是IPCThreadState對(duì)象的成員變量。程序在用戶空間停在IPCThreadState的waitForResponse()過程， 采用GDB打印出當(dāng)前線程用戶空間的this指針的所有成員，即可找到mOut和mIn

解讀： mIn緩存區(qū)，mDataSize = 16, mDataPos = 16, 說明最后的talkWithDriver產(chǎn)生了兩個(gè)BR命令，并且已處理；mOut緩存區(qū)，mDataSize = 0, mDataPos = 0，說明BC_XXX都已被消耗

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

mIn緩存區(qū)數(shù)據(jù)：

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

mOut緩存區(qū)數(shù)據(jù)：

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

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

3.6 疑難懸案

解決系統(tǒng)疑難問題可能不亞于去案件偵破，而本案就好比是密室殺人案。案發(fā)后第一時(shí)間去勘察現(xiàn)場(抓取ramdump)，從房門和窗口都是由內(nèi)部緊鎖的(mIn緩存區(qū)的write_size等于0)，兇手作案后是如何逃離現(xiàn)場的(todo隊(duì)列為空)？從被害人(blocked線程)身體留下的劍傷并不會(huì)致命(異步線程不會(huì)被阻塞)，那到底死因是什么呢？從現(xiàn)場種種跡象來看(ramdump推導(dǎo))很有可能是這并非第一案發(fā)現(xiàn)場(BUG不是發(fā)現(xiàn)在當(dāng)前binder transaction過程)，極有可能是兇手在它處作案(其他transaction)后，再移尸到當(dāng)前案發(fā)現(xiàn)場(binder嵌套結(jié)束后回到上一級(jí)調(diào)用處)，那么真正的第一案發(fā)現(xiàn)場又在哪里呢？這些都匪夷所思。

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

四、真相大白

4.1 案件偵破

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

基于最后的現(xiàn)場，順著這個(gè)線索通過逆向推理分析，去試圖推演兇手的整個(gè)作案過程。但對(duì)于如此錯(cuò)終復(fù)雜的案情(binder通信系統(tǒng)每時(shí)每刻都有大量的事transaction發(fā)生著，協(xié)議之間的轉(zhuǎn)換也比較復(fù)雜)，僅憑一兩個(gè)協(xié)議來逆向回推案發(fā)現(xiàn)場是如何一步步演化幾乎是不太可能的事。跟同事一起討論，通過不斷逆向與正向結(jié)合分析，每一層逆向回推，都會(huì)有N種可能性，通過不斷排除其他的可能性，盡可能多地排除完全不可能的分支，保留可能的分支再繼續(xù)回推，最終奇跡般地找到了第一案發(fā)現(xiàn)場，也找到了復(fù)現(xiàn)方法。

這個(gè)逆向推理過程非常復(fù)雜，首先需要深入掌握Binder原理，在整個(gè)推演過程最為燒腦與費(fèi)時(shí)。為了節(jié)省篇幅，此處省略一萬字。

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

4.2 案卷解讀

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

整個(gè)binder通信會(huì)不斷地在用戶空間與內(nèi)核空間之間進(jìn)行切換, Binder IPC通信過程的數(shù)據(jù)流向說明：（ BINDER_WORK_XXX簡稱為BW_XXX）

• mOut：記錄用戶空間向Binder Driver寫入的命令
  • 通過binder_thread_write()和binder_transaction()方法消費(fèi)BC命令，并產(chǎn)生相應(yīng)的BW_XXX命令，也可能不產(chǎn)生BW命令
  • 當(dāng)thread->return_error.cmd != BR_OK，則不會(huì)執(zhí)行binder_thread_write()過程
• thread→todo: 記錄等待當(dāng)前binder線程需要處理的BINDER_WORK
  • 通過binder_thread_read()方法消費(fèi)BW命令，并生產(chǎn)相應(yīng)的BR_XX命令，也可能不產(chǎn)生BR命令
  • 一般情況，沒有BC_TRANSACION或者BC_REPLY，則不讀取; BW_DEAD_BINDER例外；
• mIn: 記錄Binder Driver傳到用戶空間的命令
  • 通過waitForResponse()和executeCommand()方法消費(fèi)BR命令

另外，關(guān)于talkWithDriver, 當(dāng)mIn有數(shù)據(jù)，意味著先不需要從binder driver讀數(shù)據(jù)。原因：needRead=0，則read_buffer size設(shè)置為0，當(dāng)doReceive=true，則write_buffer size也設(shè)置為0。從而此次不會(huì)跟driver交互。

以下是一次定屏復(fù)現(xiàn)過程吐出的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=0Binder: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=0Binder: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=0Binder: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僅僅是打印錯(cuò)誤 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=0Binder: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=0Binder: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=0Binder: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（）結(jié)束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=0Binder: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

將以上信息轉(zhuǎn)換為表格形式來展示案發(fā)過程：

以流程圖的方式來展示案發(fā)過程：

過程解讀：

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

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

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

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

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

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

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

到此徹底執(zhí)行完sendObituary()，則需向mOut添加BC_DEAD_BINDER_DONE協(xié)議，收到該協(xié)議后，驅(qū)動(dòng)將proc→delivered_death的BW_DEAD_BINDER_AND_CLEAR調(diào)整為BW_CLEAR_DEATH_NOTIFICATION，并放入thread->todo隊(duì)列；然后生成BR_CLEAR_DEATH_NOTIFICATION_DONE，完成本次通信；

回到bindApplication()的waitForResponse，此時(shí)mOut和mIn都為空，進(jìn)入內(nèi)核binder_wait_for_work(), 該線程不再接收其他事務(wù)，也無法產(chǎn)生事務(wù)，則永遠(yuǎn)地被卡住。

總結(jié)：整個(gè)過程發(fā)生了10次 talkWithDriver()

• 第一個(gè)異步reportOneDeath()消費(fèi)掉bindApplication()所產(chǎn)生的BW_RETURN_ERROR；
• 第二個(gè)同步reportOneDeath()所消耗掉 第一個(gè)異步reportOneDeath()自身殘留的BR_TRANSACTION_COMPLETE；
• bindApplication()所產(chǎn)生的BW_RETURN_ERROR由于被別人所消費(fèi)，導(dǎo)致陷入無盡地等待。

4.3 總結(jié)

真正分析遠(yuǎn)比這復(fù)雜，鑒于篇幅，文章只講解其中一個(gè)場景，不同的Binder Driver以及不同的Framework代碼組合有幾種不同的表現(xiàn)與處理流程。不過最本質(zhì)的問題都是在于在嵌套的binder通信過程，BR_DEAD_REPLY錯(cuò)誤地被其他通信所消耗從而導(dǎo)致的異常。我的解決方案是一旦發(fā)生錯(cuò)誤，則當(dāng)BW_RETURN_ERROR事務(wù)放入到當(dāng)前線程todo隊(duì)列頭部，則保證自己產(chǎn)生的BW_RETURN_ERROR事務(wù)一定會(huì)被自己所正確地消耗，解決異步binder通信在嵌套場景下的無限阻塞的問題，優(yōu)化后的處理流程圖：

當(dāng)然還有第二個(gè)解決方案就是盡可能避免一切binder嵌套，Google在最新的binder driver驅(qū)動(dòng)里面采用將BW_DEAD_BINDER放入proc的todo隊(duì)列來避免嵌套問題，這個(gè)方案本身也OK，但我認(rèn)為在執(zhí)行過程出現(xiàn)了BW_RETURN_ERROR還是應(yīng)該放到隊(duì)列頭部，第一時(shí)間處理error，從而也能避免被錯(cuò)誤消耗的BUG，另外后續(xù)如果binder新增其他邏輯，也有可能會(huì)導(dǎo)致嵌套的出現(xiàn)，那么仍然會(huì)有類似的問題。最近跟Google工程師來回多次溝通過這個(gè)問題，他們?nèi)匀幌Ｍ３置看沃煌鵷hread todo隊(duì)列尾部添加事務(wù)的邏輯，對(duì)于嵌套問題希望通過將其放入proc todo隊(duì)列的方式來解決。對(duì)此，我擔(dān)心后續(xù)擴(kuò)展性方面會(huì)忽略或者遺忘，又引發(fā)binder嵌套問題，Google工程師表示未來添加新功能，也會(huì)杜絕出現(xiàn)嵌套邏輯，保持邏輯與代碼的簡潔。

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

http://gityuan.com/2018/05/12/binder-driver-bug/

總結(jié)

以上是生活随笔為你收集整理的Android Binder Driver缺陷导致定屏问题分析的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。