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

前言：

在前文，咱們對ANR 設計原理及影響因素進行了介紹，並對影響 ANR 的不一樣場景進行歸類。可是依靠現有的系統日誌，不足以完成複雜場景的問題歸因，並且有些信息從應用側沒法獲取，這就致使不少線上問題更加棘手。所以咱們在應用側探索了新的監控能力，以彌補信息獲取不足的短板。同時對平常分析過程當中用到日誌信息和分析思路進行總結，以幫忙你們更好的掌握分析技巧，下面咱們就來看看相關實現。

Raster 監控工具

俗話說：「工欲善其事，必先利其器」，平常分析 ANR 問題也是如此，一個好的監控工具不只能夠幫助咱們在解決常規問題時達到錦上添花的效果，在面對線上複雜隱蔽的問題時，也能爲咱們打開視野，提供更多線索和思路。

工具介紹：

該工具主要是在主線程消息調度過程進行監控，並按照必定策略聚合，以保證監控工具自己對應用性能和內存抖動影響降至最低。同時對應用四大組件消息執行過程進行監控，便於對這類消息的調度及耗時狀況進行跟蹤和記錄。另外對當前正在調度的消息及消息隊列中待調度消息進行統計，從而在發生問題時，能夠回放主線程的總體調度狀況。此外，咱們將系統服務的 CheckTime 機制遷移到應用側，應用爲線程 CheckTime 機制，以便於系統信息不足時，從線程調度及時性推測過去一段時間系統負載和調度狀況。

所以該工具用一句話來歸納就是：由點到面，回放過去，如今和未來。

因其實現原理和消息聚合後的效果，直觀展現主線程調度過程長短不一的耗時片斷，猶如一道道光柵，故將該工具命名爲 Raster[ˈræstər]。

監控工具由來

舉個例子：

例以下圖，是線下遇到的 ANR 問題，從手機端獲取的 Trace 日誌，能夠看到從主線程堆棧上基本得不到太多有效信息。 繼續從 Trace 中分析其它信息，包含了各個進程的虛擬機和線程狀態信息，以及 ANR 以前或以後一段時間，CPU 使用率比較高的進程乃至系統負載(CPU，IO)的相關信息等等，以下圖： 可是從這些信息中，相信不少同窗都很難再進一步分析，由於這些信息只是列舉了當前各個進程或線程的狀態，並無很好的監控和記錄影響這些指標的過程。而現實中這類場景的問題，天天都在線上大量發生。那麼針對這種狀況該如何更好的解決呢？下面就來介紹一下咱們是如何應對的。

消息調度監控

在Android 系統的 ANR 設計原理及影響因素一文中，咱們講到，ANR 問題不少場景都是歷史消息耗時較長並不斷累加後致使的，可是在 ANR 發生時咱們並不知道以前都調度了哪些消息，若是能夠監控每次消息調度的耗時並記錄，當發生 ANR 時，獲取這些記錄信息，並能計算出當前正在執行消息的耗時，是否是就能夠清晰的知道 ANR 發生前主線程都發生了什麼？按照這個思路，整理出以下示意圖： 可是經過上面示意圖並結合實際業務場景，咱們發現，對於大多數業務消息，單次耗時都不多，若是每一個消息都單獨記錄，要想跟蹤記錄 ANR 前 10S 甚至更長時間範圍內的全部消息，可能須要成千上萬條記錄，這個顯然是不合理的，並且這麼多的消息也不方便咱們後續查看。

消息聚合分類

聯想到實際業務場景不少狀況都是耗時較少的消息，而在排查這類問題過程耗時較少的消息基本是能夠直接忽略的，所以咱們是否是能夠對這類消息按照必定條件進行聚合，將一段時間之內的消息進行累加計算，若是累計耗時超過咱們規定的閾值，那麼就將這些消息的數量和累計耗時合併成一條記錄，如 16 個消息累計耗時恰好超過 300ms，則生成一條記錄。以此類推存儲 100 條的話，就能監控到 ANR 發生前 30S 主線程的調度歷史了(實際多是大於 15S，至於爲什麼是這個範圍，咱們會在後面說明)，如此一來就能夠較好的解決大量記錄和頻繁更新帶來的內存抖動問題。

根據上面的思路，咱們對消息監控及記錄又進一步的進行聚合優化和關鍵消息過濾。總結來看，分爲如下幾種類型：

多消息聚合：

該場景主要用於主線程連續調度多個消息，而且每一個消息耗時都不多的狀況下，將這些消息耗時累加，直到這些消息累計耗時超過設置的閾值，則彙總並生成一條記錄，並在這條記錄中標明本次聚合總共調度了多少個消息。按照消息聚合的思路，發生問題時主線程消息調度示意圖以下： Count 表示本條記錄包含了多少個消息；Wall 表示本輪消息執行的累計耗時

消息聚合拆分：

針對上面多消息聚合策略，會存在一些特殊狀況，例如在將多個消息進行累計統計過程當中，若是前 N 次消息調度結束後，累計耗時都沒有超過閾值，可是調度完下一個消息以後，發現累計耗時超過閾值，而且還明顯超出，如設置閾值是 300ms，可是前 N 個消息累計 200ms，加上本次消息累計耗時達到了 900ms，那麼這種狀況，咱們明顯知道是最後一次消息耗時嚴重，所以須要將本次消息單獨記錄，並標記其耗時和相關信息，同時將以前 N 次消息調度耗時和消息數聚合在一塊兒並單獨記錄，這種場景至關於一次生成 2 條記錄。

爲了考慮監控工具對性能的影響，咱們只在每輪統計須要保存時，更新線程 cpu 執行時間，若是發生消息聚合拆分的場景，會默認前一條記錄的 cpu 時間爲-1，由於本條記錄並非咱們重點關注的，因此會把本輪統計的 cpu 時間所有歸到後一條消息。

在一些極端場景下，如本輪監控第一個消息執行耗時爲 1ms，可是加上本次消息耗時，累計超過 600ms，所以兩次消息累計耗時遠大於設定的閾值 300ms，那麼就須要對本次耗時嚴重的消息單獨記錄，而前面那個 1ms 的消息也須要被單獨進行記錄。相似情形如此反覆，就會出現上面說的保存 100 條記錄，總體監控可回溯的時長區間存在波動的狀況。該場景的示意圖以下： Count 表示本條記錄包含了多少個消息；Wall 表示本輪消息執行的累計耗時

關鍵消息聚合：

除了上面單次耗時嚴重的消息須要拆分並單獨記錄以外，還有一類消息也須要咱們單獨標記，以達到更好的識別，那就是可能會引發 ANR 的應用組件，如 Activity，Service，Receiver，Provider 等等，爲了監控這幾種組件的執行過程，咱們須要對 ActivityThread.H 的消息調度進行監控，當發現上面這些組件有關的消息在執行時，無論其耗時多少，都對其進行單獨記錄，並將以前監控的一個或多個消息也保存爲一條記錄。該場景的示意圖以下： Count 表示本條記錄包含了多少個消息；Wall 表示本輪消息執行的累計耗時

IDLE 場景聚合：

熟悉消息隊列的同窗都知道，主線程是基於消息隊列的方式進行調度，在每次消息調度完成以後都會從消息隊列讀取下一個待調度的消息，若是消息隊列沒有消息，或者下一個消息沒有到設定的調度時間，而且也沒有 IDLE 消息等待調度，那麼主線程將會進入 IDLE 狀態，以下示意圖： 正是由於上面的調度邏輯，使得主線程在消息調度過程當中會屢次進入 IDLE 狀態，而這個過程也涉及到線程上下文切換(如：Java 環境切換到 Native 環境)，會去檢測是否有掛起請求，因此對調用頻繁的接口來講，會在 ANR 發生時被命中，理論上調用越頻繁的接口被命中的機率越大，以下圖堆棧： 可是上面這種場景的 IDLE 停留時長可長可短，若是按照徹底上面那幾類消息聚合策略，多個消息連續聚合的話，可能會把這類場景也給聚合進來，必定程度形成干擾，這顯然不是咱們想要的，爲此須要進一步優化，在每次消息調度結束後，獲取當前時間，在下次消息調度開始前，再次獲取當前時間，並統計距離上次消息調度結束的間隔時長，若是間隔較長，那麼也須要單獨記錄，若是間隔時間較短，咱們認爲能夠忽略，並將其合併到以前統計的消息一塊兒跟蹤，到這裏就完成了各種場景的監控和歸類。該場景的示意圖以下： Count 表示本條記錄包含了多少個消息；Wall 表示本輪消息執行的累計耗時

耗時消息堆棧採樣：

在上面重點講述了主線程消息調度過程的監控和聚合策略，便於發生 ANR，在線下進行回放。可是那些耗時較長的消息，僅僅知道其耗時和消息 tag 是遠遠不夠的，由於每一個消息內部的業務邏輯對於咱們來講都是黑盒，各個接口耗時也存在不少不肯定性，如鎖等待、Binder 通訊、IO 等系統調用。

所以須要知道這些耗時消息內部接口的耗時狀況，咱們選取了 2 種方案進行對比：

第一種方案：是對每一個函數進行插樁，在進入和退出過程統計其耗時，並進行聚合和彙總。該方案的優勢是能夠精確的知道每一個函數的真實耗時，缺點是很影響包體積和性能，並且不利於其餘產品高效複用。

第二種方案，在每一個消息開始執行時，觸發子線程的超時監控，若是在超時以後本次消息還沒執行結束，則抓取主線程堆棧，並繼續對該消息設置下一次超時監控，直到該消息執行結束並取消本輪監控。若是在觸發超時以前已經執行完畢，則取消本次監控並在下次消息開始執行時，再次設置超時監控，可是由於大部分消息耗時都不多，若是每次都頻繁設置和取消，將會帶來性能影響，所以咱們對此進行優化，採用系統 ANR 超時監控相同的時間對齊方案，具體來講就是：

以消息開始時間加上超時時長爲目標超時時間，每次超時時間到了以後，檢查當前時間是否大於或等於目標時間，若是知足，則說明目標時間沒有更新，也就是說本次消息沒結束，則抓取堆棧。若是每次超時以後，檢查當前時間小於目標時間，則說明上次消息執行結束，新的消息開始執行並更新了目標超時時間，這時異步監控需對齊目標超時，再次設置超時監控，如此往復。

根據上面的思路，整理流程圖以下： 須要注意的是，消息採樣堆棧的超時時長不可設置過短，不然頻繁抓取堆棧對主線程性能影響較大，同時也不能設置太長，不然會由於採樣太低致使數據置信度下降。具體時長根據每一個產品複雜度靈活調整便可。

監控正在調度消息及耗時：

除了監控 ANR 發生以前主線程歷史消息調度及耗時以外，也須要知道 ANR 發生時正在調度的消息及其耗時，以便於在看到 ANR 的 Trace 堆棧時，能夠清晰的知道當前 Trace 邏輯到底執行了多長時間，幫忙咱們排除干擾，快速定位。藉助這個監控能夠很好的回答你們，ANR 發生時當前 Trace 堆棧是否耗時以及耗時多久的問題，避免陷入「Trace 堆棧」誤區。

獲取 Pending 消息：

同時除了監控主線程歷史消息調度及耗時以外，也須要在 ANR 發生時，獲取消息隊列中待調度的消息，爲咱們分析問題時提供更多線索，如：

• 消息隊列中待調度消息是否被 Block 以及被 Block 時長，根據 Block 時長能夠推測主線程的繁忙程度；
• 能夠觀察消息隊列中是否存在發生 ANR 的應用組件消息，如 Service 消息，以及其在待調度消息隊列中的位置和 Block 時長；
• 能夠觀察消息隊列中都有哪些消息，這些消息是否有必定規律，如大量重複消息，若是有大量重複消息，則說明頗有可能與該消息相關的業務邏輯發生異常，頻繁和主線程交互(後面的案例分析中咱們也會有介紹)。

以前咱們講到，對於一次消息調度，它的耗時能夠從兩個維度進行統計，即 Wall Duration 和 Cpu Duration，經過這兩個維度的統計，能夠幫助咱們更好的推測一次嚴重耗時，是執行大量業務邏輯仍是處於等待或被搶佔的狀況，若是是後者，那麼能夠看到這類消息的 Wall Duration 和 Cpu Duration 比例會比較大，固然如何更好更全面的區分一次消息耗時是等待較多仍是線程調度被搶佔，咱們將會在後面結合其餘參考信息進行介紹。

完整示意圖

在這裏咱們再把 Cpu Duration 耗時也給統計以後，那麼整個有關主線程完整的消息調度監控功能就基本完成了。示意圖以下： 經過這個消息調度監控工具，咱們就能夠很清晰的看到發生 ANR 時，主線程歷史消息調度狀況。當前正在調度消息耗時，以及消息隊列待調度消息及相關信息。並且利用這個監控工具，一眼便知 ANR 發生時主線程 Trace 實際耗時狀況，所以很好解決了部分同窗對當前堆棧是否耗時以及耗時多久的疑問。

從上面介紹能夠看出，爲了重點標記單次耗時消息和關鍵消息，咱們使用了多種聚合策略，所以監控過程記錄的信息可能會表明不一樣類型的消息，爲了便於區分，咱們在可視化展現時加上 Type 標識，便於區別。

應用示例：

例以下圖，從 Trace 日誌能夠看到，ANR 發生時主線程被 Block 在 Binder 通訊過程，可能不少同窗第一反應是 WMS 服務沒有及時響應 Binder 請求致使的問題 可是再結合下面的消息調度監控來覈實一下，咱們發現當前調度的消息 Wall duration 只有 44ms，而在該消息以前有兩次歷史消息耗時比較嚴重，分別爲 2166ms，3277ms，也就是說本次 Binder 調用耗時並不嚴重，真正的問題是前面 2 次消息耗時較長，影響了後續消息調度，只有同時解決這 2 個消息耗時嚴重問題，該 ANR 問題纔可能解決。 若是沒有消息調度監控工具，上去就盲目的分析當前邏輯調用的 IPC 問題，可能就犯了方向性的錯誤，掉入「Trace 堆棧」陷阱中。

接下來再來看一個發生在線上的另一個實例，從下圖能夠看到主線程正在調度的消息耗時超過 1S，可是在此以前的另外一個歷史消息耗時長達 9828ms。繼續觀察下圖消息隊列待調度的消息狀態(灰色示意)，能夠看到第一個待調度的消息被 Block 了 14S 之久。由此咱們能夠知道 ANR 消息以前的這個歷史消息，纔是致使 ANR 的罪魁禍首，固然這個正在執行的消息也須要優化一下性能，由於咱們在前面說過：「發生 ANR 時，沒有一個消息是無辜的」。 正是由於有了上面這些監控能力，讓咱們在平常面對 Trace 日誌中的業務邏輯是否耗時以及耗時多久的困惑，瞬間就會變得清晰起來。

Checktime

Checktime 背景介紹：

Checktime 是 Android 系統針對一些系統服務(AMS，InputService 等)中高頻訪問的接口，執行時間的監控，當這類接口真實耗時超過預期值將會給出提示信息，此類設計爲了在真實環境監測進程被調度和響應能力的一種結果反饋。

具體實現是，在每一個函數執行前和執行後分析獲取當前系統時間，並計算差值，若是該接口耗時超過其設定的閾值，則會觸發"slow operation"的信息提醒，部分代碼實現以下： Checktime 邏輯很簡單，用當前系統時間減去對比時間，若是超過 50ms，則給出 Waring 日誌提示。 咱們在分析線下問題，或者在系統層面分析這類問題時，常常會在 logcat 中看到這類消息，可是對於線上的三方應用來講，由於權限問題沒法獲取系統日誌，只能本身實現了。

線程 Checktime：

瞭解完系統 Checktime 設計思路及實現以後，咱們就能夠在應用層實現相似的功能了，經過藉助其它子線程的週期檢測機制，在每次調度前獲取當前系統時間，而後減去咱們設置延遲的時間，便可獲得本次線程調度前的真實間隔時間，如設置線程每隔 300ms 調度一次，結果發現實際響應時間間隔有時會超過 300ms，若是誤差越大，則說明線程沒有被及時調度，進一步反映系統響應能力變差。

經過這樣的方式，即便在線上環境獲取不到系統日誌，也能夠從側面反映不一樣時段系統負載對線程調度影響，以下圖示意，當連續發生屢次嚴重 Delay 時，說明線程調度受到了影響。

小結：

經過上述監控能力，咱們能夠清晰的知道 ANR 發生時主線程歷史消息調度以及耗時嚴重消息的採樣堆棧，同時能夠知道正在執行消息的耗時，以及消息隊列待中調度消息的狀態。同時經過線程 CheckTime 機制從側面反映線程調度響應能力，由此完成了應用側監控信息從點到面的覆蓋。可是在面對 ANR 問題時，只有這個監控，是遠遠不夠的，須要結合其餘信息總體分析，以應對更爲複雜的系統環境。下面就結合監控工具來介紹一下 ANR 問題的分析思路。

ANR 分析思路：

在介紹分析思路以前，咱們先來講一下分析這類問題須要用到哪些日誌，固然在不一樣的環境下，獲取信息能力會有很大差異，如線下環境和線上環境，應用側和系統角度都有差別。這裏咱們會將咱們平常排查問題經常使用的信息都介紹一下，便於你們更好的理解，主要包括如下幾種：

• Trace 日誌
• AnrInfo
• Kernel 日誌
• Logcat 日誌
• Meminfo 日誌
• Raster 監控工具

對於應用側來講，在線上環境可能只能拿到當前進程內部的線程堆棧(取決於實現原理，參見：Android 系統的 ANR 設計原理及影響因素)以及 ANR Info 信息。

在系統側，幾乎能獲取到上面的全部信息，對於這類問題獲取的信息越多，分析定位成功率就越大，例如能夠利用完整的 Trace 日誌，分析跨進程 Block 或死鎖問題，系統內存或 IO 緊張程度等等，甚至能夠知道硬件狀態，如低電狀態，硬件頻率(CPU，IO，GPU)等等。

關鍵信息解讀：

在這裏咱們把上面列舉的日誌進行提取並解讀，以便於你們在平常開發和麪對線上問題，根據當前獲取的信息進行參考。

Trace 信息

在前文Android 系統的 ANR 設計原理及影響因素中，咱們講到了在發生 ANR 以後，系統會 Dump 當前進程以及關鍵進程的線程堆棧，狀態(紅框所示關鍵信息，稍後詳細說明)，示例以下： 上面的日誌包含不少信息，這裏將經常使用的關鍵信息進行說明，以下：

• 線程堆棧：

  • 這個比較好理解，也就是發生 ANR 時，線程正在執行的邏輯，可是不少場景下，獲取的堆棧耗時並不長，緣由詳見Android 系統的 ANR 設計原理及影響因素。

• 線程狀態：

  • 見上圖「state=xxx」，表示當前線程工做狀態，Running 表示當前線程正在被 CPU 調度，Runnable 表示線程已經 Ready 等待 CPU 調度，如上圖 SignalCatcher 線程狀態。Native 態則表示線程由 Java 環境進入到 Native 環境，可能在執行 Native 邏輯，也多是進入等待狀態。Waiting 表示處於空閒等待狀態。除此以外還有 Sleep，Blocked 狀態等等。

• 線程耗時：

見上圖「utmXXX，stmXXX」，表示該線程從建立到如今，被 CPU 調度的真實運行時長，不包括線程等待或者 Sleep 耗時，其中線程 CPU 耗時又能夠進一步分爲用戶空間耗時(utm)和系統空間耗時(stm)，這裏的單位是 jiffies，當 HZ=100 時，1utm 等於 10ms。

• utm： Java 層和 Native 層非 Kernel 層系統調用的邏輯，執行時間都會被統計爲用戶空間耗時。

• stm： 即系統空間耗時，通常調用 Kernel 層 API 過程當中會進行空間切換，由用戶空間切換到 Kernel 空間，在 Kernel 層執行的邏輯耗時會被統計爲 stm，如文件操做，open,write,read 等等。

• core：最後執行這個線程的 cpu 核的序號。

• 線程優先級：

  • nice： 該值越低，表明當前線程優先級越高，理論上享受的 CPU 調度能力也越強。對於應用進程(線程)來講，nice 範圍基本在 100~139。隨着應用所在先後臺不一樣場景，系統會對進程優先級進行調整，廠商可能也會開啓 cpu quota 等功能去限制調度能力。

• 調度態：

  • schedstat： 參見「schedstat=( 1813617862 14167238 546 )」，分別表示線程 CPU 執行時長(單位 ns)，等待時長，Switch 次數。

AnrInfo 信息

除了 Trace 以外，系統會在發生 ANR 時獲取一些系統狀態，如 ANR 問題發生以前和以後的系統負載以及 Top 進程和關鍵進程 CPU 使用率。這些信息若是在本地環境能夠從 Logcat 日誌中拿到，也能夠在應用側經過系統提供的 API 獲取(參見：Android 系統的 ANR 設計原理及影響因素)，Anr Info 節選部分信息以下： 對於上圖信息，主要對如下幾部分關鍵信息進行介紹：

• ANR 類型(longMsg)：

  • 表示當前是哪一種類型的消息或應用組件致使的 ANR，如 Input，Receiver，Service 等等。

• 系統負載(Load)：

表示不一樣時間段的系統總體負載，如："Load：45.53 / 27.94 / 19.57"，分佈表明 ANR 發生前 1 分鐘，前 5 分鐘，前 15 分鐘各個時間段系統 CPU 負載，具體數值表明單位時間等待系統調度的任務數(能夠理解爲線程)。若是這個數值太高，則表示當前系統中面臨 CPU 或 IO 競爭，此時，普通進程或線程調度將會受到影響。若是手機處於溫度太高或低電等場景，系統會進行限頻，甚至限核，此時系統調度能力也會受到影響。

此外，能夠將這些時間段的負載和應用進程啓動時長進行關聯。若是進程剛啓動 1 分鐘，可是從 Load 數據看到前 5 分鐘，甚至前 15 分鐘系統負載已經很高，那很大程度說明本次 ANR 在很大程度會受到系統環境影響。

• 進程 CPU 使用率：

如上圖，表示當前 ANR 問題發生以前(CPU usage from XXX to XXX ago)或發生以後(CPU usage from XXX to XXX later)一段時間內，都有哪些進程佔用 CPU 較高，並列出這些進程的 user，kernel 的 CPU 佔比。固然不少場景會出現 system_server 進程 CPU 佔比較高的現象，針對這個進程須要視狀況而定，至於 system_server 進程 CPU 佔比爲什麼廣泛較高，參見：Android 系統的 ANR 設計原理及影響因素。 minor 表示次要頁錯誤，文件或其它內存被加載到內存後，可是沒有被映射到當前進程，經過內核訪問時，會觸發一次 Page Fault。若是訪問的內容尚未加載到內存，那麼會觸發 major，因此對比能夠看到，major 的系統開銷會比 minor 大不少。

• 關鍵進程：

  • kswapd： 是 linux 中用於頁面回收的內核線程，主要用來維護可用內存與文件緩存的平衡，以追求性能最大化，當該線程 CPU 佔用太高，說明系統可用內存緊張，或者內存碎片化嚴重，須要進行 file cache 回寫或者內存交換(交換到磁盤)，線程 CPU 太高則系統總體性能將會明顯降低，進而影響全部應用調度。

  • mmcqd： 內核線程，主要做用是把上層的 IO 請求進行統一管理和轉發到 Driver 層，當該線程 CPU 佔用太高，說明系統存在大量文件讀寫，固然若是內存緊張也會觸發文件回寫和內存交換到磁盤，因此 kswapd 和 mmcqd 常常是同步出現的。

• 系統 CPU 分佈：

以下圖，反映一段時間內，系統總體 CPU 使用率，以及 user，kernel，iowait 方向的 CPU 佔比，若是發生大量文件讀寫或內存緊張的場景，則 iowait 佔比較高，這個時候則要進一步觀察上述進程的 kernel 空間 CPU 使用狀況，並經過進程 CPU 使用，再進一步對比各個線程的 CPU 使用，找出佔比最大的一個或一類線程。

Logcat 日誌：

在 log 日誌中，咱們除了能夠觀察業務信息以外，還有一些關鍵字也能夠幫咱們去推測當前系統性能是否遇到問題，以下圖， 「Slow operation」，「Slow delivery」 等等。

Slow operation

Android 系統在一些頻繁調用的接口中，分別在方法先後利用 checktime 檢測，以判斷本次函數執行耗時是否超過設定閾值，一般這些值都會設置的較爲寬鬆，若是實際耗時超過設置閾值，則會給出「Slow XXX」提示，表示系統進程調度受到了影響，通常來講系統進程優先級比較高，若是系統進程調度都受到了影響，那麼則反映了這段時間內系統性能頗有可能發生了問題。

Kernel 日誌：

對於應用側來講，這類日誌基本是拿不到的，可是以下是在線下測試或者從事系統開發的同窗，能夠經過 dmesg 命令進行查看。對於 kernel 日誌，咱們主要分析的是 lowmemkiller 相關信息，以下圖：

Lowmemkiller：

從事性能(內存)優化的同窗對該模塊都比較熟悉，主要是用來監控和管理系統可用內存，當可用內存緊張時，從 kernel 層強制 Kill 一些低優先級的應用，以達到調節系統內存的目的。而選擇哪些應用，則主要參考進程優先級(oom_score_adj)，這個優先級是 AMS 服務根據應用當前的狀態，如前臺仍是後臺，以及進程存活的應用組件類型而計算出來的，例如：對於用戶感知比較明顯的前臺應用，優先級確定是最高的，此外還有一些系統服務，和後臺服務(播放器場景)優先級也會比較高。固然廠商也對此進行了大量的定製(優化)，以防止三方應用利用系統設計漏洞，將自身進程設置過高優先級進而達到保活目的。

消息調度時序圖：

如上圖，在咱們分析完系統日誌以後，會進一步的鎖定或縮小範圍，可是最終咱們仍是要回歸到主線程進一步的分析 Trace 堆棧的業務邏輯以及耗時狀況，以便於咱們更加清晰的知道正在調度的消息持續了多長時間，可是不少狀況當前 Trace 堆棧並非咱們期待的答案，所以須要進一步的確認 ANR 以前主線程的調度信息，評估歷史消息對後續消息調度的影響，便於咱們尋找「真兇」。

固然，有時也須要進一步的參考消息隊列中待調度消息，在這些消息裏面，除了能夠看到 ANR 時對應的應用組件被 Block 的時長以外，還能夠了解一下都有哪些消息，這些消息的特徵有時對於咱們分析問題也會提供有力的證據和方向。

分析思路

在上面咱們對各種日誌的關鍵信息進行了基本釋義，下面就來介紹一下，當咱們平常遇到 ANR 問題時，是如何分析的，總結思路以下：

• 分析堆棧，看看是否存在明顯業務問題(如死鎖，業務嚴重耗時等等)，若是無上述明顯問題，則進一步經過 ANR Info 觀察系統負載是否太高，進而致使總體性能較差，如 CPU，Mem，IO。而後再進一步分析是本進程仍是其它進程致使，最後再分析進程內部分析對比各個線程 CPU 佔比，找出可疑線程。

• 綜合上述信息，利用監控工具收集的信息，觀察和找出 ANR 發生前一段時間內，主線程耗時較長的消息都有哪些，並查看這些耗時較長的消息執行過程當中採樣堆棧，根據堆棧聚合展現，進一步的對比當前耗時嚴重的接口或業務邏輯。

以上分析思路，進一步細分的話，能夠分爲如下幾個步驟：

• 一看 Trace：

  • 死鎖堆棧： 觀察 Trace 堆棧，確認是否有明顯問題，如主線程是否與其餘線程發生死鎖，若是是進程內部發生了死鎖，那麼恭喜，這類問題就清晰多了，只需找到與當前線程死鎖的線程，問題便可解決。

  • 業務堆棧： 觀察經過 Trace 堆棧，發現當前主線程堆棧正在執行業務邏輯，你找到對應的業務同窗，他認可該業務邏輯確實存在性能問題，那麼恭喜，你頗有可能解決了該問題，爲何只是有可能解決該問題呢？由於有些問題取決於技術棧或框架設計，沒法在短期內解決。若是業務同窗反饋當前業務很簡單，基本不怎麼耗時，而這種場景也是平常常常遇到的一類問題，那麼就可能須要藉助咱們的監控工具，追溯歷史消息耗時狀況了。

  • IPC Block 堆棧： 觀察經過 Trace 堆棧，發現主線程堆棧是在跨進程(Binder)通訊，那麼這個狀況並不能立即下定論就是 IPC block 致使，實際狀況也有多是剛發送 Binder 請求不久，以及想要進一步的分析定位，這時也須要藉助咱們的自研監控工具了。

  • 系統堆棧： 經過觀察 Trace，發現當前堆棧只是簡單的系統堆棧，想要搞清楚是否發生嚴重耗時，以及進一步的分析定位，如咱們常見的 NativePollOnce 場景，那麼也須要藉助咱們的自研監控工具進一步確認了。

• 二看關鍵字：Load，CPU，Slow Operation，Kswapd，Mmcqd，Kwork，Lowmemkiller 等等

剛纔咱們介紹到，上面這些關鍵字是反應系統 CPU，Mem，IO 負載的關鍵信息，在分析完主線程堆棧信息以後，還須要進一步在 ANRInfo，logcat 或 Kernel 日誌中搜索這些關鍵字，並根據這些關鍵字當前數值，判斷當前系統是否存在資源(CPU，Mem，IO)緊張的狀況。

• 三看系統負載分佈：觀察系統總體負載：User,Sys,IOWait

經過觀察系統負載，則能夠進一步明確是 CPU 資源緊張，仍是 IO 資源緊張。若是系統負載太高，必定是有某個進程或多個進程引發的反之。系統負載太高又會影響到全部進程調度性能。經過觀察 User，Sys 的 CPU 佔比，能夠進一步發分析當前負載太高是發生在應用空間，仍是系統空間，如大量調用邏輯(如文件讀寫，內存緊張致使系統不斷回收內存等等)，知道這些以後，排查方向又會進一步縮小範圍。

• 四看進程 CPU：觀察 Top 進程的 CPU 佔比

從上面分析，在咱們知道當前系統負載太高，是發生在用戶空間仍是內核空間以後，那麼咱們就要經過 Anrinfo 的提供的進程 CPU 列表，進一步鎖定是哪一個(些)進程致使的，這時則要進一步的觀察每一個進程的 CPU 佔比，以及進程內部 user，sys 佔比。

• 在分析進程 CPU 佔比過程，有一個關鍵的信息，要看統計這些進程 CPU 太高的場景是發生在 ANR 以前的一段時間仍是以後一段時間，以下圖表示 ANR 以前 4339ms 到 22895ms 時間內進程的 CPU 使用率。

• 五看 CPU 佔比定線程 ：對比各線程 CPU 佔比，以及線程內部 user 和 kernel 佔比

在經過系統負載(user,sys,iowait)鎖定方向以後，又經過進程列表鎖定目標進程，那麼接下來咱們就能夠從目標進程內部分析各個線程的(utm,stm)，進一步分析是哪一個線程有問題了。

在 Trace 日誌的線程信息裏能夠清晰的看到每一個線程的 utm，stm 耗時。至此咱們就完成了從系統到進程，再到進程內部線程方向的負載分析和排查。固然，有時候可能致使系統高負載的不是當前進程，而是其餘進程致使，這時一樣會影響其餘進程，進而致使 ANR。

• 六看消息調度鎖定細節 ：

  • 在分析和明確系統負載是否正常，以及負載太高是哪一個進程引發的結論以後，接下來便要經過咱們的監控工具，進一步排查是當前消息調度耗時致使，歷史消息調度耗時致使，仍是消息過於頻繁致使，同時經過咱們的線程 CheckTime 調度狀況分析當前進程的 CPU 調度是否及時以及影響程度，在鎖定上述場景以後，再進一步分析耗時消息的採樣堆棧，纔算找到解決問題的終極之鑰，固然耗時消息內部可能存在一個或多個耗時較長的函數接口，或者會有多個消息存在耗時較長的函數接口，這就是咱們前文中提到：「發生 ANR 時，沒有一個消息是無辜的。」

更多信息：

除了上面的一些信息，咱們還能夠結合 logcat 日誌分析 ANR 以前的一些信息，查看是否存在業務側或系統側的異常輸出，如搜索「Slow operation」，"Slow delivery"等關鍵字。也能夠觀察當前進程和系統進程是否存在頻繁 GC 等等，以幫忙咱們更全面的分析系統狀態。

總結：

上面咱們重點介紹了基於主線程消息調度的監控工具，實現了"由點到面"的監控能力，以便於發生 ANR 問題時，能夠更加清晰直觀的總體評估主線程的「過去，如今和未來」。同時結合平常實踐，介紹了在應用側分析 ANR 問題常常用到的日誌信息和分析思路。

目前，Raster 監控工具由於其很好的提高了問題定位效率和成功率，成爲 ANR 問題分析利器，並融合到公司性能穩定性監控平臺，爲公司衆多產品普遍使用。接下來咱們將利用該工具並結合上面的分析思路，講一講實際工做中遇到不一樣類型的 ANR 問題時，是如何快速分析和定位問題的。

Android 平臺架構團隊

咱們是字節跳動 Android 平臺架構團隊，以服務今日頭條爲主，面向 GIP，同時服務公司其餘產品，在產品性能穩定性等用戶體驗，研發流程，架構方向上持續優化和探索，知足產品快速迭代的同時，保持較高的用戶體驗。 若是你對技術充滿熱情，想要迎接更大的挑戰和舞臺，歡迎加入咱們，北京，深圳均有崗位，感興趣發送郵箱：tech@bytedance.com ，郵件標題：姓名 - GIP - Android 平臺架構。