手寫解析微信Matrix性能監控日誌的工具

1. 前言

2018年12月25日，微信團隊自研的APM利器，Matrix正式開源了。

Matrix 是一款微信研發並平常使用的 APM (Application Performance Manage) ，當前主要運行在 Android 平臺上。Matrix 的目標是創建統一的應用性能接入框架，經過對各類性能監控方案快速集成，對性能監控項的異常數據進行採集和分析，輸出相應問題的分析、定位與優化建議，從而幫助開發者開發出更高質量的應用。

在精讀了Matrix的源碼以後，我發出了讚歎和吐槽兩種聲音。值得讚賞的是，這個APM框架的設計思路確實鬼斧神工，有不少值得Android開發者學習的地方，深刻了解它，可以擴寬咱們的編程視野。 使人吐槽的就是，從文檔的豐富性，代碼的可讀性，代碼的註釋量，開源的一條龍服務等方面講，他們作的還不太好。 做爲國內的頂尖開發團隊，這些方面與國外的頂尖開源開發團隊仍是有不小的差距。

目前Matrix的集成確實很方便，參考官方文檔，大概10分鐘左右就能集成到項目中。可是它有一個硬傷，對開發者很不友好，它集成很方便，可是分析和定位問題比較困難，開發者須要搭建一套數據採集和分析系統，大大地增長了開發者的使用門檻。 目前它在github上的star量是8.5k。若是微信團隊能把採集系統和數據分析系統也開源出來，用戶的使用門檻將會大大下降，相信star量也能更上一個臺階。

吐槽歸吐槽。吐槽不是目的。但願國內的開發者能夠更真心實意地作出更好用的開源產品。吐槽完畢，接下來我將聊聊Matrix官方文檔中沒有講到的一些設計細節。真的很驚豔。若是你對Matrix曾經有任何偏見，不妨跟隨我打破偏見，突破微信團隊給咱們設置的使用門檻。

2. Matrix功能簡介

Matrix 當前監控範圍包括：應用安裝包大小，SQLite 操做優化，幀率變化，卡頓，啓動耗時，頁面切換耗時，慢方法，文件讀寫性能，I/O 句柄泄漏， 內存泄漏等。

更多詳細介紹請移步Matrix簡介

本文將着重講解檢測慢方法的實現原理，以及數據格式分析，數據格式是Matrix的重中之重，不管是採集過程生成數據，仍是分析過程解析數據，都須要熟練理解數據格式。其它系列的文章隨着我對Matrix的理解程度加深，也會陸續在公衆號發佈，敬請關注。

3. 慢方法演示

官方Demo，TestTraceMainActivity#testJankiess(View view)模擬在主線程調用方法超過700ms的場景。Matrix中慢方法的默認閾值是700ms。用戶可配置。對應的字段是

//Constants.java

public static final int DEFAULT_EVIL_METHOD_THRESHOLD_MS = 700;

點擊EVIL_METHOD按鈕，會調用testJankiess方法。打印Log以下

乍一看，有點丈二的和尚摸不着頭腦。出現這樣的日誌，說明主線程調用時長超過了700ms。把日誌中content對應的json格式化，獲得以下結果：

{
  "machine":"UN_KNOW",
  "cpu_app":0,
  "mem":1567367168,
  "mem_free":851992,
  "detail":"NORMAL",
  "cost":2262,
  "usage":"0.35%",
  "scene":"sample.tencent.matrix.trace.TestTraceMainActivity",
  "stack":"0,1048574,1,2262\n
            1,117,1,2254\n
            2,121,1,2254\n
            3,124,1,384\n
            4,125,1,165\n
            5,126,1,21\n
            5,127,1,21\n
            5,128,1,19\n
            4,129,1,24\n
            3,130,1,65\n
            4,131,1,21\n
            4,132,1,6\n
            4,133,1,8\n
            3,134,1,1004\n",
  "stackKey":"121|",
  "tag":"Trace_EvilMethod",
  "process":"sample.tencent.matrix",
  "time":1620523013050
}
複製代碼

關於數據格式，官方也有一篇文章介紹，github.com/Tencent/mat…

本文重點關注stack字段。它的功能是上報對應的堆棧。可是堆棧中爲啥是一堆阿拉伯數字呢？先讓咱們從頭提及了。

4.計算方法調用的時間花費

4.1 計算一個方法調用花費的時間

假設有方法A。我想計算它花費的時間。咱們通常會這樣作

public void A() {
  long startTime = SystemClock.uptimeMillis()
  SystemClock.sleep(1000);
  long endTime = SystemClock.uptimeMillis()
  System.out.println("cost time " + (endTime-startTime));
}
複製代碼

對於單個方法咱們能夠這樣作。可是若是我想給Android項目中全部的方法都計算調用花費時，咱們須要用到字節碼插樁技術。在全部的方法開始處和結束處，添加記錄時間的代碼。而Matrix也正是使用插樁技術來計算方法的時間調用的。

項目工程中TestTraceMainActivity的A方法

使用Jadx工具反編譯apk中的TestTraceMainActivity。發現A方法先後增長了AppMethoBeat.i(121)和AppMethoBeat.o(121)

i/o 方法參數121是什麼意思呢？

4.2 121含義講解

gradle插件，在處理方法時，會將方法名與從1開始遞增的數字對應起來。咱們打開app/build/outputs/mapping/debug/methodMapping.txt文件。從圖片咱們能夠看到121對應的方法名是sample.tencent.matrix.trace.TestTraceMainActivity A ()V

前文堆棧中的數字0,1048574,1,2262\n 第二列1048574對應的就是方法名對應的數字。這麼作的好處是，數據採集節省流量。

4.3 獲取調用棧的耗時

有方法調用以下，假設A方法調用耗時1000ms。如何可以肯定調用棧中哪一個子方法的調用最耗時？

public void A() {
  B();
  C();
  D();
}
複製代碼

Matrix框架已經實現了調用棧耗時監測，具體分析我放到後面講解。重點就是後文6.2章節

4.4 獲取主線程耗時

依賴主線程Looper，監控每次dispatchMessage的執行耗時

public static void loop() {
   ...
   for (;;) {
       ...
       // This must be in a local variable, in case a UI event sets the logger
       Printer logging = me.mLogging;
       if (logging != null) {
           logging.println(">>>>> Dispatching to " + msg.target + " " +
                   msg.callback + ": " + msg.what);
       }
       msg.target.dispatchMessage(msg);
       if (logging != null) {
           logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
       }
       ...
   }
}
複製代碼

主線程全部執行的任務都在 dispatchMessage 方法中派發執行完成，咱們經過 setMessageLogging 的方式給主線程的 Looper 設置一個 Printer ，由於 dispatchMessage 執行先後都會打印對應信息。咱們能夠計算出執行先後的時間花費。

5. Matrix如何實現插樁

本文只是簡單介紹Matrix的插樁技術。淺嘗輒止。實現插樁的代碼是com/tencent/matrix/trace/MethodTracer.java，它的內部類TraceMethodAdapter實現了AppMethoBeat.i()和AppMethoBeat.o()的插入功能。

6. 慢方法監測的原理

6.1 手畫調用棧樹

第三節提到的慢方法演示，它的代碼調用以下。

public void testJankiess(View view) {
    A();
}

private void A() {
    B();
    H();
    L();
    SystemClock.sleep(800);
}

private void B() {
    C();
    G();
    SystemClock.sleep(200);
}

private void C() {
    D();
    E();
    F();
    SystemClock.sleep(100);
}

private void D() {
    SystemClock.sleep(20);
}

private void E() {
    SystemClock.sleep(20);
}

private void F() {
    SystemClock.sleep(20);
}

private void G() {
    SystemClock.sleep(20);
}

private void H() {
    SystemClock.sleep(20);
    I();
    J();
    K();
}

private void I() {
    SystemClock.sleep(20);
}

private void J() {
    SystemClock.sleep(6);
}

private void K() {
    SystemClock.sleep(10);
}

private void L() {
    SystemClock.sleep(1000);
}
複製代碼

它對應的methodMapping文件以下：

117,1,sample.tencent.matrix.trace.TestTraceMainActivity testJankiess (Landroid.view.View;)V
121,2,sample.tencent.matrix.trace.TestTraceMainActivity A ()V
122,4,sample.tencent.matrix.battery.TestBatteryActivity onDestroy ()V
123,9,sample.tencent.matrix.sqlitelint.TestSQLiteLintHelper qualityClose (Ljava.io.Closeable;)V
124,2,sample.tencent.matrix.trace.TestTraceMainActivity B ()V
125,2,sample.tencent.matrix.trace.TestTraceMainActivity C ()V
126,2,sample.tencent.matrix.trace.TestTraceMainActivity D ()V
127,2,sample.tencent.matrix.trace.TestTraceMainActivity E ()V
128,2,sample.tencent.matrix.trace.TestTraceMainActivity F ()V
129,2,sample.tencent.matrix.trace.TestTraceMainActivity G ()V
130,2,sample.tencent.matrix.trace.TestTraceMainActivity H ()V
131,2,sample.tencent.matrix.trace.TestTraceMainActivity I ()V
132,2,sample.tencent.matrix.trace.TestTraceMainActivity J ()V
133,2,sample.tencent.matrix.trace.TestTraceMainActivity K ()V
134,2,sample.tencent.matrix.trace.TestTraceMainActivity L ()V
1048574,1,android.os.Handler dispatchMessage (Landroid.os.Message;)V
複製代碼

以上方法調用能夠概括成如下樹形結構：

請注意,該樹形圖，是我直接根據調用次序畫出來的，程序是如何根據調用次序生成調用棧樹呢？

6.2 生成調用棧樹

6.2.1 函數調用記錄在隊列中

編譯期已經對全局的函數進行插樁，在運行期間每一個函數的執行先後都會調用 MethodBeat.i/o 的方法，若是是在主線程中執行，則在函數的執行先後獲取當前距離 MethodBeat 模塊初始化的時間 offset （爲了壓縮數據，存進一個long類型變量中）， 並將當前執行的是 MethodBeat i或者o、mehtod id 及時間 offset，存放到一個 long 類型變量中，記錄到一個預先初始化好的數組 long[] 中 index 的位置（預先分配記錄數據的 buffer 長度爲 100w，內存佔用約 7.6M）。數據存儲以下圖：

//AppMethodBeat.java
private static long[] sBuffer = new long[Constants.BUFFER_SIZE];

//Constants.java
public static final int BUFFER_SIZE = 100 * 10000; // 7.6M
複製代碼

AppMethodBeat.i/o方法最終會調用到

//AppMethodBeat.java
private static void mergeData(int methodId, int index, boolean isIn) {
    if (methodId == AppMethodBeat.METHOD_ID_DISPATCH) {
        sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime;
    }
    long trueId = 0L;
    if (isIn) {
        trueId |= 1L << 63;
    }
    trueId |= (long) methodId << 43;
    trueId |= sCurrentDiffTime & 0x7FFFFFFFFFFL;
    sBuffer[index] = trueId;
    checkPileup(index);
    sLastIndex = index;
}
複製代碼

testJankiess方法調用，經過mergeData方法，最終填充sBuffer以下圖：

6.2.2 主線程調用結束後判斷是否超過閾值

EvilMethodTracer.java dispatchEnd表示主線程執行結束，若是耗時超過閾值，會在MatrixHandlerThread中執行AnalyseTask，分析調用棧的耗時狀況。

6.2.3 分析堆棧

1. 調用TraceDataUtils.structuredDataToStack()方法
2. 調用TraceDataUtils.trimStack()方法
3. 調用TraceDataUtils.getTreeKey()方法

6.2.4 將調用隊列轉換成樹的先序遍歷結果

1. 調用addMethodItem方法，將後序遍歷結果push到棧中

structuredDataToStack()中，若是是out方法，將會出棧，而且push到棧底。獲得結果以下：

若是咱們將隊列反轉過來，對照手畫的樹咱們可知結果是後序遍歷。

126 127 128 125 129 124 131 132 133 130 134 121 117 1048574

2. 調用stackToTree()將隊列轉換成多叉樹。

結果和手畫的樹同樣

3. 調用treeToStack()，得到先序遍歷結果 結果以下

6.2.5 裁剪調用堆棧

Matrix默認最多上傳30個堆棧。若是堆棧調用超過30條，須要裁剪堆棧。裁剪策略以下：

1. 從後往前遍歷先序遍歷結果，若是堆棧大小大於30，則將執行時間小於5*總體遍歷次數的節點剔除掉

2. 最多總體遍歷60次，每次總體遍歷，比較時間增長5ms

3. 若是遍歷了60次，堆棧大小仍是大於30，將後面多餘的刪除掉

6.2.5 堆棧信息生成key

若是某個方法調用時間大於整個主線程調用時長的0.3倍，會將該方法id記錄到list中，最後排序，過濾。生成traceKey。

6.2.6 根據裁剪後的先序遍歷結果生成上報堆棧

reportBuilder就是最終上報的堆棧信息。與文章開頭的日誌信息一致

7. 解析日誌

日誌解析結果以下：

8. 最後

文中如有錯誤，請留言交流。成文不易，寫了一成天。若是以爲還不錯，分享給你的朋友吧。若是須要解析日誌文件的源碼，歡迎關注「字節小站」同名公衆號。