今日頭條 ANR 優化實踐系列分享 - 實例剖析集錦

簡述：

在前文，咱們用了較多的篇幅介紹了ANR 設計原理及影響因素，並根據不一樣場景進行了分類，如：當前消息嚴重耗時，歷史消息耗時嚴重，業務異常密集執行，進程內資源搶佔，進程間資源搶佔等場景。爲了應對系統監控能力不足以及應用側獲取信息受限的狀況，咱們在應用側實現了一套消息調度監控工具，重點監控主線程的「過去，如今和未來」，同時結合相關日誌對 ANR 問題的分析思路進行了總結。

爲了便於你們更好的理解上述知識，接下來咱們將結合工做中遇到的一些比較有表明性的問題，並按照前文歸因分類，由淺入深進行實例解剖，下面就來看看這幾類問題，咱們是如何藉助系統日誌和監控工具進行分析及定位的。

案例一：當前業務耗時嚴重

主線程 Trace 堆棧：

分析過程：

分析堆棧：

根據前文講到的問題分析思路，首先觀察 Trace 主線程堆棧，從上面堆棧，能夠看到正在業務邏輯，可是當前這個業務邏輯是否耗時呢？若是耗時較長，是否是受到系統調度影響呢？帶着這些疑問，咱們來看一下系統側的表現。

分析系統&進程負載：

觀察不一樣時段系統負載： 在 ANR Info 中咱們搜索 Load 關鍵字，發現 ANR 前 1，前 5，前 15 分鐘(Load:7.45 / 6.92 / 6.84)，系統 CPU 總體負載並不高。

觀察進程 CPU 使用率： 進一步觀察 CPU usage from 0 ms to 8745ms later，看到 ANR 以後 (later：表示發生 ANR 後一段時間各進程 CPU 佔比，ago 表示：ANR 以後一段時間，各進程 CPU 佔比)的這段時間，應用主進程 CPU 佔比達到 161%，並且在 user，kernel 佔比分佈上，kernel 比例高達 103%！ 經過前文的介紹，咱們知道對應用來講 kernel 空間 CPU 佔比較高，說明應用側應該發生了大量的系統調用，對普通應用來講，發生系統調用的多數場景都是文件 IO 操做。

觀察線程： 繼續觀察上圖，能夠看到應用進程內部的線程 CPU 佔用，能夠看到主線程的 CPU 佔比 93%，其中 kernel 佔用 69%，明顯高於用戶空間 23%，說明 ANR 以後的這 8S 多，主線程依然在進行大量系統調用。

系統側結論： 經過觀察系統負載和各個進程的 CPU 使用狀況，咱們發現系統總體負載比較正常，可是咱們的主進程 CPU 佔比明顯偏高，而且集中在主線程。

業務耗時：

根據上面的分析，咱們將思路再次回到主線程，進一步觀察 Trace 堆棧，發現上面有一個明顯的系統調用(read)，難道是本次系統調用致使的 kernel 佔比較高嗎？那麼當前邏輯在 ANR 發生前已經持續了多久呢？分析到這裏，若是沒有進一步的監控，或者業務不承認當前業務邏輯耗時，那麼事情到這裏可能就要告一段落，或者須要在業務層添加監控埋點進行復現了，可是若是每次遇到這類問題都要添加埋點，那麼將是一個很是糟糕的事情。

別忘了，在前面介紹 ANR 問題分析思路時，咱們還有一個殺手鐗(參見：監控工具 Raster)，經過這個監控工具能夠看到很清晰的看到：歷史消息耗時，當前消息持續時間以及消息隊列未調度消息 Block 耗時。結合上面這個問題，咱們看到了本次主線程消息調度狀況，參見下圖：

經過還原的時序圖，能夠清晰看到 ANR 以前，主線程消息調度及耗時基本正常，沒有發現明顯耗時嚴重的消息，可是觀察正在調度的消息，其 Wall duration 超過 9000ms，而且 Cpu duration 長達 4800ms+，說明該消息耗時很是嚴重。並且上圖灰色部分顯示第一個消息，被 Block 了 9S 以上，所以能夠進一步的說明該消息被 Block 的時長，基本都是當前正在執行的消息致使。

問題結論：

經過上面這些分析信息和實際數據，咱們能夠得出以下結論：發生 ANR 問題時，系統負載良好。發生問題前，應用主線程消息調度狀態良好，可是當前正在調度的消息耗時嚴重，致使了後續消息未能及時響應，引發了 ANR。

帶着這些結論，在和業務對接時便會清晰高效不少。這種場景，屬於比較常規和常見的問題，也是大部分同窗排查問題的分析思路，過程相對輕鬆。接下來，咱們再看另外一種場景的 ANR 問題。

案例二：歷史消息耗時嚴重

下面分析的這個案例，是你們常常遇到的，也是引發不少人困惑的一種場景：發生 ANR 時，Trace 堆棧落在了 NativePollOnce。根據咱們的理解，這個場景通常表示當前線程處於空閒或 JNI 執行完以後，進行上下文切換的過程，相關邏輯比較清晰。

但是平常遇到的問題，有不少 Case 都屬於這類場景，若是僅僅依靠系統日誌讓咱們很難進一步分析。下面就看看咱們是如何應對這類問題的：

主線程 Trace 堆棧：

分析思路：

分析堆棧：

看到上面的 Trace 堆棧，基本無從下手，線程狀態以及線程 utm,stm 時長都沒有明顯異常，可是線上確實有大量的 ANR 問題落在這個場景，難度在某種極端狀況下虛擬機這部分邏輯耗時嚴重？可是從理論上來講這些假設確實不存在的。既然堆棧沒有太多信息，咱們就移步到系統層面，看看是否有線索可尋。

分析系統&進程負載：

觀察系統負載： 在 ANR Info 中查看Load關鍵字，發現系統在前 1 分鐘，前 5 分鐘，前 15 分鐘各個時段負載並不算高，可是最近 1 分鐘 CPU 負載爲 11.81，比前 5，15 分鐘都高，說明負載有加劇趨勢。

觀察進程 CPU 分佈： 進一步觀察 CPU usage from 0 ms to 5599 later 關鍵字，看到 ANR 以後這 5S 多的時間，咱們應用主進程 CPU 佔比達到 155%，並且在 user，kernel 層面 CPU 佔比分佈上，user 佔比 124%，明顯很高，這時直覺告訴咱們，當前進程應該有問題。

觀察系統 CPU 分佈：

進一步分析系統負載，發現總體 CPU 使用率並不高。user 佔比 17%，kernel 佔比 7.5%，iowait 佔比 0.7%，說明這段時間系統 IO 並不繁忙，總體也符合預期。

系統側結論： 經過觀察系統負載和各個進程的 CPU 使用狀況，發現系統環境比較正常，可是咱們的主進程 CPU 佔比明顯偏高，但因本次 Anr Info 中未獲取到進程內部各線程 CPU 使用率，須要回到應用側進一步分析。

應用側分析：

根據上面的分析，咱們將方向轉回到當前進程，經過對比 Trace 中各線程耗時(utm+stm)，發現除了主線程以外，其它部分子線程耗時(utm+stm)沒有明顯異常，所以基本排除了進程內部子線程 CPU 競爭致使的問題，所以問題進一步聚焦到主線程。

接下來再將目光聚焦在主線程消息調度狀況，經過監控工具觀察主線程的歷史消息，當前消息以及待調度消息，以下圖：

經過上圖能夠看到當前消息調度 Wall Duration 爲 46ms。在ANR 以前存在一個索引爲 46 的歷史消息耗時嚴重(wall duration:10747ms)，同時還有一個索引爲 32 的歷史消息耗時也比較嚴重(wall duration:10747ms)。

進一步觀察消息隊列第一個待調度消息，發現其實際 block 時長爲 9487ms，所以咱們排除了索引爲 32 的歷史消息，認爲索引爲 46 的消息耗時是致使後續消息未能及時調度的主要緣由。

在鎖定索引爲 46 的歷史消息以後，接下來利用監控工具中的消息堆棧採樣監控，發現該消息執行過程，屢次堆棧採樣均命中建立 Webview 邏輯，原來業務在 UI 繪製過程直接實例化 Webview！(涉及到業務代碼，採用堆棧詳情不在此展現)

問題結論：

經過上面的分析並利用監控工具，咱們能夠很清晰看到發生 ANR 問題時，NativePollOnce 場景耗時並不長，致使本次 ANR 的主要緣由是歷史消息在 UI 繪製過程當中同步建立 Webview，致使耗時嚴重。可是期間系統超時監控並無觸發，待主線程繼續調度後續消息時，系統監控客戶端響應超時，捕獲了主線程正在執行的邏輯。

這類場景在線上線下都大量存在，可是從 ANR 設計原理和 Trace 採集流程來看，不少並不耗時的消息在調度過程當中都成爲了「替罪羊」。

案例三：業務異常密集執行

接下來分析的這個 Case，在多個產品都有遇到，僅從堆棧上面看，也是常常遇到並困惑咱們的，現象和上面分析的案例有些相似，即業務邏輯很簡單，實際耗時不多，可是常常出如今各類 ANR Trace 上面，只是依照堆棧信息，就把這個問題草率的分配給相應業務方去解決，業務同窗大機率也是一頭霧水，不知道從何下手。

可是若是按照上面兩類問題的分析思路，可能也會陷入困惑，這時若是換個思路，可能會是另外一番景象，下面就來看看咱們是如何分析的。

ANR 現場堆棧：

問題分析：

分析堆棧：

根據前文分析思路，先觀察 Trace 主線程堆棧，從上面堆棧，能夠看到業務邏輯，第一反應就是業務耗時？按照經驗，咱們仍是習慣性的再去看看系統日誌，進一步縮小或鎖定方向。

分析 CPU 負載：

觀察系統負載： 在 ANR Info 中搜索 Load 關鍵字，看到系統在各個時段(前 1，5，15 分鐘)負載並不高，可是有加劇趨勢。

觀察進程 CPU 分佈： 進一步觀察"CPU usage from 0 ms to 9460ms later"期間各個進程 CPU 佔比狀況，看到這段時間目標應用的主進程 CPU 佔比達到 153%，並且在 user，kernel 佔比分佈上，user 佔比高達 127%，存在明顯異常。Kernel 佔比 25%，也有些偏高。與此同時，咱們進一步觀察 kswapd，mmc 進程 CPU 使用率，發現佔用率不是過高，說明當前系統的總體內存和 IO 並無太嚴重問題。

觀察系統 CPU 分佈： 爲了進一步驗證系統 IO 及內存負載是否正常，接下來再觀察一下系統總體 CPU 使用和分佈，發現 iowait 佔比 7.5%，相對來講有些偏高。

進程 CPU 再觀察： 與此同時，咱們在 ANR Info 裏面還發現了一個關鍵信息，看到了另外一個時段問題進程內部主要線程的 CPU 佔用狀況，經過下圖咱們能夠看到主線程 CPU 佔用 95%，屬於明顯偏高。

系統側分析結論：經過上面的分析，基本能夠得出以下結論：發生問題時，系統 CPU，Mem 負載比較正常，IO 負載有些偏高，發生 ANR 問題的應用進程 CPU 使用率存在異常，並且集中在主線程。

業務耗時：

根據上面的分析，已經將排查方向鎖定在主線程 CPU 使用率較高，接下來觀察該線程的 utm+stm，發現累計耗時(1752+128)*10ms=18.8S。對比本次進程啓動時長才 22S，說明進程啓動後，主線程基本是在滿負荷執行！並且主線程的 CPU 響應能力很是不錯！

至此咱們再次確認主線程存在嚴重耗時，難道又是當前消息或某個歷史消息耗時嚴重？因而快速切換到消息調度監控，一探究竟。

可是看到上面的消息調度監控時序圖，發現當前消息執行時長才 300ms，並非咱們期待的耗時很嚴重哪一種場景，進一步觀察 ANR 以前歷史消息調度，也沒有看到有單次耗時嚴重的消息。繼續觀察上圖待調度消息，發現確實被嚴重 Block。既然主線程沒有看到嚴重耗時，系統負載也比較正常，那麼主線程 CPU 使用率爲什麼會這麼高呢，這個狀況與預期不符，不符合常理啊！

觀察 Block 消息： 以前咱們介紹Raster 工具時，介紹該工具不只能夠記錄歷史消息，標記嚴重耗時，關鍵消息以外。還有一個做用就是獲取消息隊列待調度的消息，因而咱們繼續觀察這些被 Block 的消息，發現了一個很是奇怪的現象（因爲時序圖只能在鼠標停留時展現單個消息詳情，所以直接截取原始數據)，以下圖：

**經過對比，發現消息隊列待調度的消息中，除了第一個消息以外，其他的 200 多個消息(爲了便於展現，目前只獲取最多前 300 個)，居然是同一個 Handler 對象(hash:1173da0)的消息，再進一步對比發現當前正在調度的也是該 Handler 對象的消息。

這個狀況引發了咱們的注意，順着這個思路，繼續翻看歷史調度信息，發現每條歷史記錄 (儘管存在多條消息耗時較少被聚合的場景，可是咱們會保留最後一個消息的 msg string 信息) 的last msg 也是相同的 handler 對象，以下圖。

這麼多消息都來自同一個 Handler，這麼密集的在主線程執行，每條記錄 cpu 耗時都在 290ms 左右，每條記錄監控統計期間調度了 5 條消息。分析到這裏，咱們基本就有答案了，頗有多是當前業務發生異常，致使不停的向主線程發送消息，頻繁密集的消息依次執行，嚴重阻塞了後續消息調度。

問題結論：

帶着上面這些分析信息和監控數據，咱們得出以下結論：應用在啓動以後，業務邏輯發生異常，瞬間產生大量消息，儘管單次消息執行耗時並不嚴重，可是這些消息在主線程密集執行，嚴重影響了後續消息調度，進而致使後續消息響應超時。

對於這個問題，當咱們把相關數據和結論反饋給業務同窗時，業務同窗進一步分析業務邏輯，發現當前邏輯確實存在隱患，改進以後，該 ANR 問題就此獲得解決。

這種場景屬於典型的業務邏輯異常形成的問題，若是沒有監控工具由點到面的聚合和展現，單獨分析某一次消息耗時，不管如何是找不到問題緣由的。

案例四：進程內IO負載異常

上面重點介紹了主線程內部環境致使問題的相關案例，介紹當前消息耗時嚴重，歷史消息耗時嚴重，以及消息密集這幾種類型的分析思路，接下來再分析一個進程內 IO 搶佔的案例，下面就來看看如何層層撥雲揭霧，尋找真相的。

主線程 Trace 堆棧：

問題分析：

堆棧分析：

上面這個 Trace 信息，也是無從下手，堆棧自己是一個很清晰的系統邏輯，可是現實中確實也有大量 ANR Trace 落在這個場景，難道是系統進入 epoll_wait 以後，沒有被及時喚醒？可是從理論上來講這些假設不存在。既然堆棧信息沒有太明顯，咱們就把方向轉移到系統側，看看是否有線索。

系統&進程負載分析：

觀察系統負載： 在 ANR Info 中咱們搜索 Load 關鍵字，發現系統各個時段(前 1，5，15 分鐘)負載明顯很高，而且最近 1 分鐘負載爲 71，又明顯高於前 5，15 分鐘，說明有系統負載進一步加劇！

觀察進程 CPU 分佈： 進一步觀察 CPU usage from 0 ms to 21506 later 關鍵字，看到ANR 以後這段時間，內核線程 kworker 的 CPU 佔比明顯偏高，累計佔比超過 45%！其它系統或應用進程 CPU 使用率廣泛偏低。 經過前文介紹咱們知道 kworker 屬於內核線程，當 IO 負載太重時會在該線程有所體現。進一步觀察 kswapd0 線程 cpu 使用率，發現只有 2%，而 kswapd0 主要應用在內存緊張的場景，說明這段時間系統內存負載基本正常。經過上面這些信息解讀，能夠大體推測最近一段時間系統負載太高，應該是 IO 請求致使，至於系統內存壓力尚可接受，接下來咱們繼續求證。

系統 CPU 分佈：

觀察進一步分析系統總體負載，發現 user 佔比只有 5.4%，kernel 佔比 11%，可是 iowait 佔比高達 57%！明顯高於 user，kernel 使用率，說明這段時間系統 IO 負載很是嚴重。

而這個 IO 佔比較高，也進一步實錘了咱們上面的「觀察進程 CPU 分佈」的結論。那麼是哪一個應用致使的呢？遺憾的，受限於系統日誌獲取能力，依靠現有的信息並無明顯看到異常進程，那麼 IO 發生在哪裏，是否和當前進程有關呢？因而咱們將思路再次回到應用內部。

應用側分析：

經過上面的分析，咱們基本鎖定了是 IO 負載太重致使的問題，接下來便要進一步排查是不是當前進程內部存在異常，因而咱們對比了各個線程的耗時(utm+stm)狀況：

經過上圖線程耗時對比能夠清晰的發現，DBHelper-AsyncOp-New 線程不管是 utm 時長，仍是 stm 時長，都明顯超過其它線程，而 stm 高達 2915！ 這個耗時超出了咱們的預期，實際場景中咱們認爲主線程才 CPU 消耗大戶，其它線程都是配角。下面咱們再看一下線程詳情：

進一步查看該線程堆棧，發現存在明顯的 IO 操做，並且子線程優先級(nice=0)相對較高，stm(2915)+utm(1259)高達 4000+，換算成時長至關於 CPU 真實執行超過了 40S！

對比主線程耗時(utm:1035，stm:216)，以及進程啓動時長(4 分 18 秒)，能夠更好證實了 DBHelper 線程存在異常，stm 明顯過長，說明存在大量系統調用，結合該線程業務，能夠很快就猜到是 IO 讀寫引發的問題了。由於該線程自己就是負責應用內部數據庫清理功能的。

通過上面的分析以後，下面來看一下主線程調度時序圖，看看 IO 負載太重對主線程有多大影響。

消息調度時序圖分析

經過上圖，能夠清晰看到 ANR 消息以前，有多個歷史消息耗時存在明顯異常，並且 Wall duration 與 Cpu duration 耗時比例差距較大，部分消息 cpu 時長更是小於 1ms(單位 ms，0 則表示小於 1ms)，說明在此期間主線程總體調度受到很大影響，並且這些消息內部涉及 IO 訪問的邏輯將會受到更大影響。

同時結合咱們現場 checkTime 機制，發現 checkTime 調度明顯存在嚴重 delay 狀況。

問題結論：

帶着上面這些分析信息和數據，咱們能夠得出以下結論：經過層層分析咱們能夠發現，發生ANR時的當前消息耗時近2S，但並非root case，主線程出現多個歷史消息耗時，但也不是root case，真正致使本次ANR的緣由是DBHelper-AsyncOp線程在過去一段時間進行了長時間的IO操做，嚴重影響了主線程乃至進程自己的CPU調度，致使後續消息響應不及時，觸發系統超時(ANR)。

對於該類問題，除了應用自己優化以外，也與一些機型設備差別有關，例如不一樣機型 IO 性能自己就存在很大差別，所以理論上沒法完全解決。同時不管是進程內部仍是其餘進程進行 IO 密集操做，均可能引發系統 IO 負載太重，進而致使系統乃至全部進程調度受到影響，對於該類問題只能進一步的優化相關邏輯，下降 IO 訪問頻率，減小主線程 IO 訪問等等。

這類問題，在線上比較常見，可是在開發同窗的線下測試過程，性能廣泛符合預期，針對線上用戶，應用場景錯綜複雜，絕非線下能模擬，而且針對不一樣手機設備，不一樣芯片平臺，甚至磁盤可用空間的差別，其 IO 性能也表現的千差萬別而這些小几率的問題，在數億萬用戶環境中，會頻頻出現。

案例五：其它進程及系統負載異常

前面咱們分析的幾類問題，基本都是應用進程內部因素致使的問題，如主線消息耗時，消息密集執行，子線程 IO 資源搶佔等等。線上環境中，除了進程或主線線程自身因素致使的問題外，還有一些是外部因素致使的問題，如其它進程或系統負載太重，進而影響當前進程正常調度。下面咱們就來看一看這類問題是如何分析的。

主線程 Trace 堆棧：

問題分析：

堆棧分析：

看到上面這個 Trace 信息，一樣是熟悉的味道，發生 ANR 時，系統正處於 epoll wait 狀態，線程 utm 及 stm 耗時並不算長，累計(376+340)*10=7160ms。觀察到這裏基本沒有看到太多有效信息。接下來繼續把方向轉移到系統側，看看是否有線索可循。

系統&進程負載分析：

觀察系統負載： 在 ANR Info 中搜索 Load 關鍵字，看到系統在各個時段(前 1，5，15 分鐘)負載比較高，分別爲 37.09，39.37，49.44，呈現加劇趨勢。

觀察進程 CPU 分佈： 進一步觀察"CPU usage from 2401 ms to -22043ms ago"期間，各個進程 CPU 佔比狀況，看到這段時間目標進程 cpu 使用率很低，只有 17%。看到其它關鍵進程或線程，如 Kswapd0 線程，cpu 佔比 20%，對於該線程來講，其出現則表示系統內存比較緊張了，並且看到了與其相關的 kworker，mmcqd 線程 cpu 佔比也比較高。這些線程同時出現，足以說明當前系統環境發生了比較大的問題。

而系統資源緊張，通常是由於某個或多個進程出現內存泄漏或大量 IO 讀寫致使，結合上面 Top 進程的 CPU 佔比，com.youku.phone 以及 com.android.contacts 進程可疑性最大。而發生 ANR 問題的 com.ss.android.article.news 進程其 CPU 佔比只有 17%。

觀察系統 CPU 分佈：

經過上圖信息能夠看到，系統 CPU 總體使用率達到 54%，kernel 佔比 15%，iowait 佔比高達 24%，有些偏高。說明系統負載確實存在異常，其結論與咱們上面分析的基本一致。

固然在這裏比較遺憾的是，由於是線上問題，咱們沒法經過拿到系統以及其它進程更多信息，不然能夠更加清晰的看到發生異常的是哪一個進程， 可是接下來要進一步排除是當前進程致使的系統負載問題，咱們將視野再次回到應用側。

應用側分析：

經過上面的分析，咱們基本鎖定了是內存負載太重致使的問題，接下來便要進一步排查是不是當前進程內部存在異常，因而咱們對比了各線程的耗時(utm+stm)狀況：

經過上圖能夠看到，排名第一的是主線程，其 utm+stm=700，換算成系統時長，700*10=7000ms，可是對比觀察進程啓動時長，發現進程已經啓動 108S，咱們知道對應進程來講，啓動的前 1~2 分鐘，主線程是最爲繁忙的，大量的業務和系統消息須要在主線程進行執行。同時咱們進一步對比系統負載正常的狀況，進程啓動 2 分鐘時主線程 CPU 執行時長明顯大於當前時長。

下面咱們再來看一下系統負載太重，對主線程消息調度的影響，以下圖：

經過上圖，能夠清晰看到 ANR 消息以前，有多個歷史消息耗時存在明顯異常，並且 Wall duration 與 Cpu duration 耗時比例差距較大，從側面也反映了在此期間主線程總體調度受到較大影響。

超時 Service 消息： 從上圖能夠清晰看到第一個待調度消息，其 Block 時長超過 18S 之多，接近於前面諸多耗時消息之和。同時從下圖能夠清晰看到發生 ANR 的這個 service 消息在消息隊列排在第 8，消息 block 時長爲 18482ms。

在前文應用四大組件超時歸類中提到 Service 超時時長分別爲 20S 或 200S，如今該消息在應用側 block 時長爲 18482ms，那就說明剩下 1S 多的時間，耗費在系統 AMS 服務發送到客戶端 Binder 線程接收過程，不然沒有達到 20S 超時，是不會觸發系統超時的。所以也進一步說明了系統調度性能存在問題。

問題小結

帶着上面這些分析信息和相關數據，咱們能夠得出以下結論：在進程啓動前，系統負載已經很重，整個系統調度性能受到較大的影響，儘管發生 ANR 時當前堆棧耗時較長，但並非 root case，多個歷史耗時嚴重的消息也不是 root case，而致使本次 ANR 的應該是 com.youku.phone 或 com.android.contacts 進程，在過去一段時間進行大量系統資源訪問，形成系統負載加劇，嚴重影響了其餘進程 CPU 調度，致使主線程消息處理不及時，觸發系統超時(ANR)

對於該類問題，由於是其它進程致使系統資源緊張，進而影響了當前進程，所以咱們沒法從根本上解決，固然可以很好的分析並找出緣由，也是對待問題的一種態度吧。

案例六：跨進程死鎖

在前面更多從應用側介紹了 ANR 案例的分析思路，接下來看看如何藉助更多系統日誌分析這類問題。固然，這類問題若是發生在線上，會由於應用側沒法獲取跨進程 Trace 的緣由，可能會被誤歸類爲 IPC 耗時場景。

主線程 Trace 堆棧：

問題分析：

堆棧分析：

根據前面講到的問題分析思路，先觀察 Trace 主線程堆棧，從上面堆棧，能夠看到業務邏輯發生 Binder 調用被 Block 的狀況，可是此次拿到的是完整的 Trace 日誌，那麼接下來就沿着 Binder 請求邏輯，看一下響應進程的狀態。

服務進程分析：

首先查找客戶端主線程在和哪一個 Binder 線程進行通訊，搜索代理接口setAppCallback(Android 命名習慣，代理端和服務端函數命名基本保持一致），發現是 Nfc 的 Binder_3 線程響應了客戶端請求：

可是進一步觀察堆棧信息，發現 Binder_3 線程被當前進程的主線程 Block，那麼沿着這個線索看看主線程狀態：

觀察主線程狀態，發現此刻主線程也在執行 Binder 通訊，請求createBeamShareData，一樣根據命名習慣，繼續搜索關鍵字createBeamShareData，看看此次請求是哪一個進程在響應，結果發現是 ANR 所在進程的 Binder_6 線程響應此請求。

經過觀察 Binder_6 線程的堆棧和狀態，發現該線程處於 await 狀態，明顯是在等待其它線程通知喚醒！分析到這裏，就須要你們結合 Read the Fuck Code 的精神進一步分析業務邏輯了，在研究一番業務邏輯以後，發現喚醒此線程的業務邏輯，已經經過 Handler 發送到主線程，正等待主線程執行呢，可是若是時序處理的不恰當，就會出現主線程還沒來得及執行這個消息，就去監聽 NFC 狀態，進而引發了連鎖反應。至此找到了依賴鏈路：

經過上圖能夠清晰的看到本次 ANR 緣由：跨進程死鎖。

總結：

咱們按照前文 ANR 影響因素及歸類分別選取了一個線上案例，並進行分析總結。回過頭來看，第一類問題按照多數人的"解題思路"可能會很快的找到答案。在面對第二類問題時，若是沒有監控工具就可能掉入「Trace 陷阱」了。第三類問題並不常見，可是在公司多個產品都有遇到過，由於這類問題更加隱蔽，若是依靠現有系統日誌只能鎖定方向，以後須要耗費大量的時間去添加埋點分析定位，可是經過咱們的監控工具直觀展現並暴露了更多細節，爲成功定位問題扮演了關鍵角色。後面兩類由於資源搶佔的致使線程調度不及時的問題，經過監控工具很好的還原了 ANR 以前消息調度狀況，更加清晰的證明了資源競爭對主線程的影響。

掌握了上述幾類問題的分析思路，相信能夠幫助你們應對工做中遇到大部分問題，可是所謂「林子大了，什麼鳥都有」，下一篇將會介紹「barrier致使主線程假死」，「Service執行時序顛倒」等更加棘手的案例，敬請期待。

Android 平臺架構團隊

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

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