systrace 統計方法耗時

雲音樂技術團隊發表於2022-06-07
本文作者：Fangx3

Android是單執行緒模型，使用者的按鍵事件、螢幕觸控及 UI 繪製都在 UI 執行緒中處理。單執行緒意味著序列執行，如果某一個操作耗時了就會導致後續的操作都得等待，這個時候使用者的第一感知就是卡了。所以在排查卡頓的時候有一個最簡單的辦法就是找出耗時長的方法。

如何統計方法耗時？

在開發的時候想統計一個方法的耗時最簡單的方法就是在方法的開始和結束位置打個時間戳，兩個時間戳相減就是這個方法的耗時。

fun take() {
  val start = System.currentTimeMillis()
  //..
  service.take();
  //...
  val end = System.currentTimeMillis()
  val const = end - start
}

上面的方法能統計到我們應用程式碼的耗時，但是無法統計到 Android 的系統方法耗時。
其實 Android 系統已經在一些關鍵鏈路上已經埋入了一些點位，但是它的實現不是像我們這樣埋入時間戳，而是通過Trace類來實現的，而 Trace 類也支援我們應用層呼叫插入自定義的點位，在通過 Android 提供的systrace工具，抓取處理 Trace 類打的點位資訊。最終生成一個 Html 檔案，通過 Chrome 可以直觀的檢視一個完整鏈路的耗時情況。

systrace 在開發階段確實是一個調優的利器，但是它有兩個明顯的限制導致這個利器無法線上上使用：

  • 需要連線 PC 端，通過執行命令的方式開啟 Trace 功能，
  • 需要開發者手動加入Trace.beginSection和Trace.endSection，這就變成了需要開發預判耗時位置手動加入 Trace 函式，但是線上環境無法預判哪裡會耗時。

所以如果能夠解決上面兩個問題就能將 systrace 這個利器用於線上問題排查了。

脫離 PC 端執行 systrace

這裡簡單畫下 systrace 的工作原理：
image.png

從上面的圖上可以看到 systrace 抓的資料可以分為兩類：

  • Java 層和 Native 層發生的函式呼叫資訊
  • 核心態的事件資訊

其中 Java 層和 Native 層的函式呼叫資訊就是我們通過呼叫 Trace 類的方法收集起來的資訊(也是這次我們需要關心的資料)，資料資訊會記錄到trace_marker中；
而核心態的時間資訊是通過 Linux 提供的 ftrace 功能，通過啟用不同的事件節點，在核心執行時根據節點使能狀態，會往 ftrace 緩衝中打點記錄事件。
最終 systrace 通過回撈上述兩個資料整合生成一份 Html 檔案。

從上圖中可以看到 systrace 通過 Atrace 來設定 Tag ，如果能夠找到需要抓取的型別資訊的對應 Tag ，並且直接在端上進行設定，在將 trace_marker 中的資料撈取出來，就可以擺脫 PC 端的限制。

端上設定 Tag
public static void beginSection(@NonNull String sectionName) {
  if (isTagEnabled(TRACE_TAG_APP)) {
    if (sectionName.length() > MAX_SECTION_NAME_LEN) {
      throw new IllegalArgumentException("sectionName is too long");
    }
    nativeTraceBegin(TRACE_TAG_APP, sectionName);
  }
}

上面是系統 Trace 類中的 beginSecion 方法，首先會判斷對應的 Tag 是否可用，可用時才會呼叫 native 層的 TraceBegin 方法寫入資料。
而isTagEnabled的實現如下：

public static boolean isTagEnabled(long traceTag) {
  long tags = sEnabledTags;
  if (tags == TRACE_TAG_NOT_READY) {
    tags = cacheEnabledTags();
  }
  return (tags & traceTag) != 0;
}

private static long cacheEnabledTags() {
  long tags = nativeGetEnabledTags();
  sEnabledTags = tags;
  return tags;
}

看到這裡在想是不是通過反射修改sEnabledTags的值就可以開啟Trace功能了呢？
通過實踐可以發現，僅修改 sEnabledTags 還是無法開啟 Trace 功能，因此可以大概猜測在 native 層應該也是有類似的判斷，具體的 native 程式碼在/system/core/libcutils/trace-dev.c(Android O版本程式碼)檔案下

static inline void atrace_begin(uint64_t tag, const char* name)
{
    if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) {
        void atrace_begin_body(const char*);
        atrace_begin_body(name);
    }
}

可以看到這裡邏輯和 Java 中的處理類似，也是先判斷 Tag 是否可用，如果可用才執行寫入資料邏輯，繼續看下atrace_is_tag_enabled的實現，

static inline uint64_t atrace_is_tag_enabled(uint64_t tag)
{
    return atrace_get_enabled_tags() & tag;
}
static inline uint64_t atrace_get_enabled_tags()
{
    atrace_init();
    return atrace_enabled_tags;
}

可以看到這裡是獲取了atrace_enabled_tags欄位的值在進行與操作，而 Trace 類中的 sEnabledTags 也是通過nativeGetEnabledTags方法獲取到的這個值。因此我們應該修改下 native 層的這個值就可以開啟 Trace 功能了。

這裡參考了 Facebook 的 profilo 的方案，通過dlopen獲取 libcuitls.so 對應的控制程式碼，通過從對應 symbol 中找到atrace_enabled_tags的指標，從而設定 atrace_enabled_tags 來開啟 Trace 功能。

std::string lib_name("libcutils.so");
std::string enabled_tags_sym("atrace_enabled_tags");

if (sdk < 18) {
  lib_name = "libutils.so";
  enabled_tags_sym = "_ZN7android6Tracer12sEnabledTagsE";
}
if (sdk < 21) {
  handle = dlopen(lib_name.c_str(), RTLD_LOCAL);
} else {
  handle = dlopen(nullptr, RTLD_GLOBAL);
}

atrace_enabled_tags = reinterpret_cast<std::atomic<uint64_t> *>(dlsym(handle, enabled_tags_sym.c_str()));

atrace_enabled_tags 在不同版本上其符號名不一樣，所以這裡需要作下版本區分。
查詢具體的符號名稱可以通過objdump工具檢視，在 Mac 上可以使用binutils工具提供的gobjdump工具來檢視。
像上面的 atrace_enabled_tags 的符號在 Android 版本18以下，我們就可以直接通過 gobjdump 工具檢視獲得：
image.png
但是有時候一個符號名稱可能會被 mangle ，在檢視時不是太直觀和確認是否是我們需要的符號名稱，可以在通過c++filt工具 demangle 這個符號從而得到一個比較直觀的符號名稱，方便我們確認。
image.png

到這裡我們就拿到了 atrace_enabled_tags 符號對應的指標，在修改成具體的對應的 Tag 值，同時通過反射同步修改 Trace 類中的sEnabledTags值，就開啟了 Trace 功能。這裡要設定的 Tag 可以具體看下系統提供的 Trace 類，裡面具體定義了所有的 Tag 值，我們可以通過對這些 Tag 值的或操作來得到一個最終需要設定的 int 型別的值。

資料回撈

經過上面的步驟我們可以不用在 PC 端執行 systrace 指令碼的方式開啟 Trace 功能，但是從上面的實現原理圖上可以看到資料最終是寫在trace_marker中，而這個是在核心態中，應用層是無法直接讀取的。在查詢 Trace 開啟對應的 Tag 的過程中可以看到在 native 程式碼中還有定義了：

int  atrace_marker_fd     = -1;

通過檢視程式碼可以發現這個欄位就是對應的trace_marker 的檔案描述符。
而我們在呼叫 Trace.beginSection 寫入的時候最終是會呼叫到 native 層的atrace_begin_body 方法

void atrace_begin_body(const char* name)
{
    char buf[ATRACE_MESSAGE_LENGTH];

    int len = snprintf(buf, sizeof(buf), "B|%d|%s", getpid(), name);
    if (len >= (int) sizeof(buf)) {
        ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name);
        len = sizeof(buf) - 1;
    }
    write(atrace_marker_fd, buf, len);
}

可以看到最終的寫入過程其實就是呼叫了write方法實現的。

我們可以和上面獲取 atrace_enabled_tags 一樣的方式拿到 trace_marker 的檔案描述符對應的指標，這樣有了檔案描述符，在通過 hook 系統的 write 方法，在 write 方法中通過檔案描述符判斷是否是往 trace_marker 中寫入內容，如果是的話可以將內容直接儲存到我們自定義的一個檔案中，實現資料回撈。

但是從上面程式碼中可以看到最終寫入到 trace_marker 中的內容是 "B|pid|name"這樣一串資料，如果只是這樣一串內容的資料還是無法被 systrace 工具識別解析的，因此我們還需要按照下面的格式進行資料補全。

<執行緒名> - <執行緒id>  [000] ...1 <時間-秒>: tracing_mark_write: <B|E>|<程式id>|<TAG>

將資料儲存檔案匯出後，可以通過 systrace 工具提供的--from-file引數將檔案轉為 Html 檔案，就可以通過Chrome 開啟檢視了。
最新的 SDK Platform Tools 已經移除了 systrace 工具，這裡可以直接通過 Perfetto 直接開啟匯出的檔案，不需要在將檔案進行轉換。
通過端上開啟 Trace 之後抓的資料效果最終如下，可以看到 Android 系統中埋的點和我們自己新增的點的資料都能抓取到。
image.png

預判耗時？

systrace 的另一個痛點是需要開發手動插入 Trace.beginSection 和 Trace.endSection 方法，這就意味著需要開發預判哪裡的函式耗時。但是大部分情況下可能並不知道哪裡可能會產生耗時，特別是線上環境，根本無法判斷哪裡會產生耗時。既然無法預判，那就全部增加，但是這個對一個大專案來說工作量巨大，沒有實操性。因此這裡通過函式插樁的方式在每個方法中加入 Trace 的方法。

在插樁時如果只是設定方法名稱，最終生成的檔案可讀性較差，不利於進行資料分析，但是如果插入方法的全限定名稱 Trace.beginSection 方法中對 sectionName 的長度有限制，因此這裡參考了騰訊的 martix 的實現生成 methodId ，插入的時候插入一個 methodId ，這樣可以避免 beginSection 方法的長度限制。
image.png
最終的效果如上圖。

操作幾次後會發現最後生成的檔案中會有一些 Did not Finish 的資料
image.png
前後資料分析之後，發現是這些地方拋了異常走了異常流程導致 Trace 資料沒有閉合。因此在插樁的時候還需要在拋異常的 catch 程式碼塊中也插入 Trace.endSection，完成資料閉合。

總結

藉助系統提供的 Trace 功能幫我們生成一個完整的呼叫鏈路資訊，利於開發進行問題排除；在端上開啟 systrace 功能擺脫了 PC 的限制，方便我們在各種環境下進行資料抓取，能幫助我們發現一些偶現或隱藏的耗時卡頓問題。

參考資料

本文釋出自網易雲音樂技術團隊，文章未經授權禁止任何形式的轉載。我們常年招收各類技術崗位，如果你準備換工作，又恰好喜歡雲音樂，那就加入我們 grp.music-fe(at)corp.netease.com！

相關文章