簡述：

前文，我們通過線上案例對影響 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 該進程。