今日頭條 ANR 優化實踐系列 - Barrier 導致主執行緒假死

簡述：

前文，我們通過線上案例對影響 ANR 問題的六大場景進行剖析，這幾類場景基本覆寫了線上大部分問題，詳見ANR 案例分析集錦，同時我們選取了較多 NativePollOnce 場景的案例，便于大家更好理解，ANR 時看到的 NativePollOnce 場景的問題，并不是導致 ANR 的根本問題，

下面要介紹的這類問題，Trace 現場依然是 NativePollOnce 資訊，但與前幾類問題不同的是，這類問題真的發生在 NativePollOnce 場景，接下來就看看到底是什么原因導致的，

主執行緒 Trace 堆疊：

分析思路：

針對該類問題，當看到這個資訊時，第一判斷依然是主執行緒歷史訊息耗時嚴重，或者系統負載過重導致的問題，因為作業日常分析了太多這類場景的 ANR 問題，而且最后的結論也證明都與此場景無關，但分析這個問題時，進一步拆解大盤指標發現一段時間內 ANR 增加的量級，基本全部落在這個場景，這不太符合我們的預期，但是鑒于 Trace 資訊有限，只好把目光轉移到系統側，看看是否有線索，

分析系統&行程負載：

觀察系統負載： 在 ANR Info 中查看 Load 關鍵字，發現系統在前 1 分鐘，前 5 分鐘，前 15 分鐘各個時段負載并不高，

觀察行程 CPU 分布： 進一步觀察"CPU usage from 0 ms to 24301 later"，看到 ANR 之后這 24S 多的時間，應用主行程 CPU 占使用率只有 15%，但是 com.meizu.mstore 應用 CPU 使用率達到 92%，user 與 kenel 比例分別為 71%，20%，與此同時 kswapd,mmc-cmdqd 等內核執行緒 CPU 使用率并不高，說明系統負載總體正常，如果根據我們前面案例分析得出的結論來看，這種場景難道是 com.meizu.mstore 行程嚴重搶占 CPU 導致的？帶著這個疑惑，繼續觀察系統 CPU 分布，

觀察系統 CPU 分布：

進一步分析系統負載，發現整體 CPU 使用率稍微有些高，user 占比 37%，kernel 占比 24%，iowait 占比 6.9%，說明這段時間系統 IO 確實有些繁忙，

系統側結論： 通過觀察系統負載和各個行程的 CPU 使用情況，發現系統環境比較正常，但是 com.meizu.mstore 行程 CPU 占比偏高，而且 kernel 層 cpu 使用率(20%)較高，與系統 iowait (6.9%)占用較高可能存在一定關聯，那么 IO 負載較高對當前應用有多大影響呢？我們回到應用側進一步分析，

應用側分析：

根據上面的分析，我們將方向再回到當前行程，通過對比各執行緒 cpu 耗時(utm+stm)，并沒有看到某個執行緒存在明顯例外，主執行緒 CPU 執行時長 utm:187，stm:57，基本正常，

在分析對比完執行緒 CPU 耗時之后，將目光再次聚焦到Raster 監控工具的調度時序圖上面，

通過該時序圖，觀察以下三類資訊特征：ANR 前的歷史訊息，正在執行的訊息，被 Block 的訊息：

歷史訊息： 主執行緒并不存在單次歷史訊息耗時嚴重的現象，

當正在執行的訊息：正在執行的訊息 Wall Duration 為 21744ms，CPU Duration 為 100ms，也就是說大量的時間發生在等待的場景，結合該場景，如果期間是因為執行 Idle Task 導致的耗時嚴重或長時間 Wait，那么 ANR 抓取的堆疊應該有 IdleTask 相關資訊才對，因此首先排除了是 Idle Task 耗時嚴重導致的問題，

被 Block 訊息：從上圖可以看到， 第一個待調度的訊息被 block 時長為 22343ms，其 block 時長基本等于當前正在執行訊息的 Wall Duration 時長，也就說明了本場景大量訊息 blcok 是受到了當前正在執行的訊息影響，

分析到這里我們就有些困惑了，ANR 發生時當前正處于 NativePollOnce 場景，但是前面我們多次在案例分析中提到，進入 NativePollOnce 場景的條件是：訊息佇列沒有立刻調度的訊息時，會有條件的進入 wait 狀態，等到超時或者新訊息加入時會喚醒該執行緒并執行，但是從上圖可以看到訊息佇列中存在大量待調度訊息，而且很多訊息都被 block 了 20 多 S，既然這么多訊息可以被調度，那么系統為何還是一直在 NativePollOnce 環境中呢？難道真的是底層發生了問題，導致無法喚醒當前執行緒？

帶著這個疑惑，我們陸續分析了同段時間內其他用戶上報的問題，發現存在同樣的現象：NativePollOnce 場景的 WallDuration 普遍較長，有的甚至超過了 100S，但是 Cpu 時長很短，如下圖：

為此我們第一反應是系統出問題了？但是進一步對比來看，該類現象只在某個版本之后明顯增加，而之前的版本并沒有這類現象，如果是廠商更新 rom 導致的問題，應該影響全版本，甚至會影響所有應用，但事實并非如此，因此這與我們的推測并不符合，無法自圓其說，

按照我們的理解，如果直接進入 NativePollOnce 場景并且一直沒有喚醒的話，那么 CPU Duration 應該會很少，并不應該是這樣表現(CPU Duration 達到或超過 100ms)，

定向監控：

考慮到國內廠商對 Rom 定制化的習慣，為了確認上面監控的 Cpu 耗時是否是廠商在底層定制產生的耗時，我們在 Native 層通過 Hook 代理對 nativePollOnce 介面進行了監測，

在線上小范圍驗證和復現，通過觀察這類 ANR 問題時的執行緒調度時序圖，最終找到一個 NativePollOnce 停留時長高達 100S 的案例，如下圖：

通過上圖(TYPE=5)可以發現，ANR 發生前，主執行緒在訊息調度結束與下次訊息調度開始前，發生多次長時間停留的現象，而且期間都存在一定的 Cpu 耗時，但是遠小于 Wall duration，與此同時查看本次進行 epoll_wait 期間，NativePollOnce 是否是一直沒有回傳，通過監控輸出的日志，發現如下現象：

在對齊監控時序圖與上圖日志時間戳之后，看到 Java 層呼叫 looper.next()獲取下一個訊息程序中，Native 層 NativePollOnce 介面呼叫了多次，而且每次進入 epollwait 時傳入的引數 timeout 為-1，分析到這里有些疑惑了，這并不是我們預期的一直 wait 場景啊，引數-1 代表什么意思呢？繼續向下看，

MessageQueue 代碼分析：

既然 ANR 這段時間，執行多次 NativePollOnce，就說明其它執行緒已經多次將主執行緒多次從 epoll wait 狀態喚醒，但是訊息佇列已經有大量待調度的訊息，為何主執行緒還依然停留在 looper.next()內部呢？分析到這里只好再次回到上層代碼繼續分析，這個引數-1 是哪里設定的，

從上圖可以看到，每當訊息執行結束后，獲取下個訊息之前會先主動呼叫一次 NativePollOnce，但是 nextPollTimeoutMillis 默認為 0，并不是底層介面代理時看到的-1，那么這個-1 是哪里傳入的呢？繼續向下看，

通過上圖可以看到，只有一個地點將 nextPollTimeoutMillis 設定為-1，但是通過注釋可以清晰的看到提示"msg=mMessage"，沒有訊息？這與現實嚴重不符啊，ANR 發生時，訊息佇列明顯有很多訊息待執行，這里卻提示"msg=mMessage"，

通過進一步觀察上述邏輯發現，該提示發生在 else 分支，如果進入到該分支，那么則說明 msg 物件獲取為空，但是在上面明明看到賦值程序"msg=mMessage"，而且當前這種場景 mMessage 肯定不為 null，畢竟在 ANR 時獲取的待調度訊息也是通過 mMessage 遍歷得到的，

既然 mMessage 不是 null，那么就說明"msg=mMessage"肯定不是 null，但是到了下面卻為 null，說明在此程序肯定被某個邏輯給重新賦值了，繼續分析，

通過上圖可以看到只有這個場景可能將 msg 重新賦值，那么這部分邏輯是做什么的呢？

Barrier 機制介紹：

看到上面的注釋瞬間明白了，原來是 Barrier 機制，是 Android 系統用來保障部分系統訊息高優調度的一種機制，實作原理很簡單：會在每次訊息回傳前，檢測該訊息是否是 barrier 訊息，barrier 訊息的典型特征就是 msg.target 物件為 null，如下圖：

如果是 Barrier 訊息，那么將對訊息佇列中的訊息進行遍歷，找到第一個異步訊息，然后將其賦值給 msg，但是如果遍歷了所有的訊息都沒有找到異步訊息，那么最后一個訊息 msg.next 肯定為 null，此時 msg 會被置為 null，并退出回圈，

上圖為異步訊息的設定和判斷是否是異步訊息的介面實作，我們日常創建的 Message 是不會設定該屬性的，只有系統在某些特殊場景，如 UI 重繪，為了保障互動體驗，會在請求 vsync 信號前，先發送一個 barrier 訊息，然后等到 barrier 訊息執行時，遍歷 vsync 訊息并將其強制調整到頭部，以保證該類訊息的回應能力：barrier 訊息設定和移除，實作邏輯如下：

通過上面實作可以看到，barrier 訊息是不會主動移除的，需要設定 barrier 訊息的業務訊息得到回應后主動移除該訊息，否則 barrier 訊息會一直存在！

分析到這里就可以很好的解釋為何在 MessageQueue.next()介面內部多次呼叫 NativePollOnce 了，一定是當前的 mMessage 是個 barrier 訊息，但是與其關聯的業務訊息一直沒有出現，或者執行之后沒有同步移除該訊息，導致該 barrier 訊息一直處于訊息佇列頭部，每次獲取下一個訊息時，都被 barrier 攔截和并遍歷異步訊息，如果有異步訊息則回應，沒有異步訊息則通過 nativePollOnce 進行等待，從而阻塞了正常訊息的調度和回應！

進一步梳理 MessageQueue.next 介面執行邏輯，通過下圖就可以清晰的看到我們在 Native 層 Hook 時看到 nextPollTimeMills 傳參-1 的場景是怎么設定的，

那么結合本類 ANR 問題，訊息佇列第一個待調度的訊息是不是 barrier 訊息呢？我們再次找到上面分析的案例，通過監控時序圖觀察第一個被 block 的訊息，

通過上圖可以清晰的看到，當前訊息 target 物件為 null，正是 barrier 訊息！破案了！

連鎖反應：

按照上面的分析，如果 barrier 訊息沒有及時移除，那么每次通過 MessageQueue.next()查詢時，只能過濾并回傳帶有異步屬性的訊息，如用戶點擊訊息 input，vsync 訊息等等， 即使用戶互動和 UI 重繪訊息可以正常執行，但是大量業務訊息無法執行，這就導致了 UI 展示可能存在例外或功能例外，并且應用 service，receiver 等訊息并沒有異步屬性，因此也會被 block，最終造成回應超時發生 ANR！

結合當前問題，我們發現該用戶在第一次 ANR 不久之后再次發生 ANR，主執行緒 Trace：

第二次 ANR 時，對應的調度時序圖如下：

通過當前用戶連續 2 次 ANR 的訊息調度監控時序圖可以看到，本次 ANR 時，之前的歷史訊息記錄沒有發生任何變化，也就是說第一個 ANR 發生后確實沒有再調度其他訊息，但 2 次 ANR 的 WallTime 間隔超過 40S，也就是說這 40S 時間里，主執行緒確實一直 Block 在當前場景！

在訊息調度時序圖上進一步對比分析，發現兩次 ANRCase，主執行緒當前正在執行訊息的 Cpu Time 時長卻發生了變化，即從 100ms 增加 450ms，那么這個資料是否置信嗎？

結合這兩次 ANR，分別分析一下 ANR Trace 主執行緒 utm+stm 的耗時(見上圖 2 次 Trace 堆疊)：

發生第一次 ANR 時執行緒狀態及 utm,stm 耗時：

 state=S schedstat=( 2442286229 338070603 5221 ) utm=187 stm=57 core=5 HZ=100

發生第二次 ANR 時執行緒狀態及 utm,stm 耗時：

| state=S schedstat=( 2796231342 442294098 6270 ) utm=202 stm=77 core=5 HZ=100

用第二次發生 ANR 時的 utm+stm 減去第一次 ANR 時的 utm+stm，即 202+77-(187+57)=35ms，這個值對應的是 cpu 時間片，utm,stm 單位換算成時間單位為 1 比 10ms，即 35*10=350ms，這個值恰好等于 Raset 監控工具統計到的兩次 Cputime 差值：450ms-100ms=350ms，

說明在此期間訊息佇列增加了多個訊息，因為每次增加一個訊息，主執行緒都會從 epollwait 場景喚醒，然后回到 java 環境對訊息佇列進行遍歷，判斷是否有異步訊息，如果沒有找到，則再次進入 epollwait 狀態，如此反復，從而導致了上述現象！

問題初定位：

通過上面的層層分析，我們知道了是 barrier 同步機制出現了問題，導致訊息調度發生例外，即：在 barrier 訊息沒有被移除之前，主執行緒只能處理 asyncronous 屬性的訊息，這類訊息通常是用來重繪的 vsync 訊息，以及回應用戶互動的 input 訊息，但是正常的業務訊息及其他系統訊息則無法正常調度，如 Serivce，Receiver 具體超時行為的訊息，因此導致了 ANR，

定位及修復：

在定位到原因之后，接下來就是找到問題并解決問題，具體什么樣的改動會引起這里問題了，通過分析我們知道既然是 Barrier 訊息同步的問題，那么我們可以在設定 barrier 和移除 barrier 的程序加入監控，判斷哪里設定了 barrier 訊息，但是沒有同步移除，通過 Java hook 代理了 MessageQueue 的 postSyncBarrier 和 removeSyncBarrier 介面，進行 Barrier 訊息同步監測，遺憾的是線下并沒有復現，

因此只能再次回到代碼層面，對相關改動進行分析，最終在一筆需求提交中發現了線索，

邏輯調整前： 先移除將要強制調度的并設定了異步屬性的訊息，再強制調度該訊息，以保證該訊息不受 barrier 訊息之前的訊息 block，進而提高回應能力，

if (hasMsg) {
    ......
    handler.removeCallbacks(message.getCallback()); //先移除
    handler.dispatchMessage(cloneMsg); //再強制調度該訊息
    ......
}

邏輯調整后： 先強制調度該訊息，然后再將該訊息從佇列中移除，

    ......
        handler.dispatchMessage(newMessage); //先強制調度
       handler.removeCallbacks(message.getCallback());  //從佇列中移除訊息
    ......
    }

但是時序調整后存在一定隱患，即在強制呼叫 DoFrame 訊息期間，業務可能會再次觸發 UI 重繪邏輯，產生 barrier 訊息并發出 vsync 請求，如果系統及時回應 vsync，并產生 DoFrame 訊息，那么呼叫 removeCallbacks 介面會一次性清除訊息佇列中所有的 DoFrame 訊息，即：移除了訊息佇列之前的 DoFrame 訊息和下次待調度的 DoFrame 訊息，但是與下次 DoFrame 訊息同步的 barrier 訊息并沒有被移除，

那么為什么會移除多個訊息呢？這就要從handler.removeCallbacks 的實作說起了，

進一步查看 messageQueue.removeMessages 介面實作，發現該介面會遍歷訊息佇列中符合當前 runnable 以及 object 的訊息，但是上面傳遞的 Object 物件是 null，因此就相當于移除了當前 Handler 物件下面所有相同 runnable 物件的訊息！

因為強制重繪和時序調整的問題，導致了訊息佇列中同時存在 2 個 UI doFrame 訊息，并在強制執行之后被同時移除，從而導致一個無人認領的 barrier 訊息一直停留在訊息佇列 ！

其它場景：

此外，除了上面遇到的場景會導致這類問題之外，還有一種場景也可能會導致這類問題，即:UI 異步重繪，盡管 Android 系統禁止異步重繪，并利用 checkThread 機制對 UI 重繪進行執行緒檢查，但是百密一疏，如果開啟硬體加速，在 AndroidO 及之后的版本會間接呼叫 onDescendantInvalidated 觸發 UI 重繪，該邏輯躲過了系統 checkThread 檢查，將會造成執行緒并發隱患，如下圖，如果并發執行則會導致前一個執行緒的 mTraversalBarrier 被覆寫，從而導致 vsync 訊息與 barrier 出現同步問題，

查看 Android Q 原始碼，看到 onDescendantInvalidated 內部加上了 checkThread，但被注釋掉了！解釋如下：修復攝像頭后重新啟用或者通過 targetSdk 檢查？好吧，或許是忘記這個 TODO 了，

總結：

至此，我們完成了該類問題的分析和最終定位，綜合來看該類問題因 Trace 場景(NativePollOnce)和問題本身的高度隱蔽性，給排查和定位帶來了極大挑戰，如果單純依靠系統提供的日志，是很難發現 MessageQueue.next()內部發生了例外，這里我們通過 Raster 監控工具，還原了問題現場，并提供了重要線索，現在總結來看，該類問題其實具有很明顯的特征，表現在以下幾個方面：

• 問題場景 ANR Trace 集中聚合在 NativePollOnce，此程序 Wall duration 持續很長，并且屏蔽了后續所有正常訊息調度，看起來像主線被凍結一樣，

• 通過 Raster 監控工具可以清晰的看到，訊息佇列中如果第一個待訊息 target 為 null，即為 barrier 訊息，可以通過后續訊息 block 時長評估影響程度，

• 出現該類問題時，因為正常訊息無法被調度，如 Service，Receiver 訊息，將會導致應用連續發生 ANR，直到用戶主動 Kill 該行程，

后續：

接下來的文章中，我們將會介紹系統服務與客戶端 binder 通信程序中，因為時序顛倒引起的 ANR 問題，因為是系統機制出現了 bug，理論上所有應用都會受到影響，問題表現同樣很隱蔽，那么這類問題到底是什么樣的表現呢？敬請期待，

優化實踐更多參考：

今日頭條 ANR 優化實踐系列(1)-設計原理及影響因素

今日頭條 ANR 優化實踐系列(2)-監控工具與分析思路

今日頭條 ANR 優化實踐系列(3)-實體剖析集錦

Android 平臺架構團隊

我們是位元組跳動 Android 平臺架構團隊，以服務今日頭條為主，面向 GIP，同時服務公司其他產品，在產品性能穩定性等用戶體驗，研發流程，架構方向上持續優化和探索，滿足產品快速迭代的同時，追求極致的用戶體驗，

如果你對技術充滿熱情，想要迎接更大的挑戰和舞臺，歡迎加入我們，北京，深圳均有崗位，感興趣發送郵箱：tech@bytedance.com ，郵件標題：姓名 - GIP - Android 平臺架構，

點擊閱讀原文，快來加入我們吧！