本文講解非同步Android 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

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工具等十八般武藝都用過一輪了，已經沒有更多的資訊可以挖掘了，快沒有頭緒了，這個問題幾乎要成為無頭公案。

相關推薦