今日頭條 ANR 優化實踐系列 - Barrier 致使主線程假死

簡述：

前文，咱們經過線上案例對影響 ANR 問題的六大場景進行剖析，這幾類場景基本覆蓋了線上大部分問題，詳見ANR 案例分析集錦。同時咱們選取了較多 NativePollOnce 場景的案例，便於你們更好理解，ANR 時看到的 NativePollOnce 場景的問題，並非致使 ANR 的根本問題。java

下面要介紹的這類問題，Trace 現場依然是 NativePollOnce 信息，但與前幾類問題不一樣的是，這類問題真的發生在 NativePollOnce 場景，接下來就看看究竟是什麼緣由致使的。markdown

主線程 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 分佈：async

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

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

應用側分析：

根據上面的分析，咱們將方向再回到當前進程，經過對比各線程 cpu 耗時(utm+stm)，並無看到某個線程存在明顯異常。主線程 CPU 執行時長 utm:187，stm:57，基本正常。post

在分析對比完線程 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 平臺架構。

歡迎關注「字節跳動技術團隊」