實務效能偵錯範例:ANR

本節說明如何使用 ProfilingManager 搭配追蹤記錄範例,對應用程式無回應 (ANR) 進行偵錯。

設定應用程式以收集 ANR

首先,請在應用程式中設定 ANR 觸發條件:

public void addANRTrigger() {
  ProfilingManager profilingManager = getApplicationContext().getSystemService(
      ProfilingManager.class);
  List<ProfilingTrigger> triggers = new ArrayList<>();
  ProfilingTrigger.Builder triggerBuilder = new ProfilingTrigger.Builder(
      ProfilingTrigger.TRIGGER_TYPE_ANR);
  triggers.add(triggerBuilder.build());
  Executor mainExecutor = Executors.newSingleThreadExecutor();
  Consumer<ProfilingResult> resultCallback =
      profilingResult -> {
        // Handle uploading trace to your back-end
      };
  profilingManager.registerForAllProfilingResults(mainExecutor, resultCallback);
  profilingManager.addProfilingTriggers(triggers);
}

擷取並上傳 ANR 追蹤記錄後,請在 Perfetto UI 中開啟。

分析追蹤記錄

由於 ANR 觸發了追蹤記錄,因此當系統偵測到應用程式主執行緒無回應時,追蹤記錄就會結束。圖 1 顯示如何前往應用程式的主要執行緒,該執行緒在 UI 中會加上相應標記。

Perfetto UI 導覽至應用程式主執行緒。
圖 1. 前往應用程式的主執行緒。

追蹤記錄的結尾與 ANR 的時間戳記相符,如圖 2 所示。

Perfetto UI 顯示追蹤記錄結尾,並醒目顯示 ANR 觸發位置。
圖 2.ANR 觸發位置。

追蹤記錄也會顯示發生 ANR 時,應用程式正在執行的作業。具體來說,應用程式在 handleNetworkResponse 追蹤記錄切片中執行程式碼。這個切片位於 MyApp:SubmitButton 切片內。使用了 1.48 秒的 CPU 作業時間 (圖 3)。

Perfetto UI 顯示 ANR 發生時,handleNetworkResponse 執行作業耗用的 CPU 作業時間。
圖 3.發生 ANR 時的執行作業。

如果目前只依賴 ANR 發生時的堆疊追蹤進行偵錯,您可能會誤以為 ANR 完全是由 handleNetworkResponse 追蹤記錄切片中執行的程式碼所造成,而該切片在設定檔完成記錄時尚未結束。不過,即使這項作業耗費大量資源,1.48 秒的時間仍不足以觸發 ANR。您需要進一步回溯時間,瞭解在這個方法之前,是什麼原因導致主執行緒遭到封鎖。

如要找出 ANR 的原因,我們首先會查看 UI 執行緒產生的最後一個影格,該影格對應至 Choreographer#doFrame 551275 切片,且在開始 MyApp:SubmitButton 切片 (以 ANR 結束) 之前,沒有造成延遲的主要來源 (圖 4)。

Perfetto UI 顯示 ANR 發生前,UI 執行緒轉譯的最後一個影格。
圖 4.ANR 發生前產生的最後一個應用程式影格。

如要瞭解阻塞情形,請縮小畫面,檢查完整的 MyApp:SubmitButton 切片。您會注意到執行緒狀態中的重要細節,如圖 4 所示:執行緒有 75% 的時間 (6.7 秒) 處於 Sleeping 狀態,只有 24% 的時間處於 Running 狀態。

Perfetto UI 顯示作業期間的執行緒狀態,醒目顯示 75% 的休眠時間和 24% 的執行時間。
圖 5. `MyApp:SubmitButton` 作業期間的執行緒狀態。

這表示 ANR 的主要原因是等待,而非運算。查看個別睡眠記錄,找出規律。

Perfetto UI 顯示 MyAppSubmitButton 追蹤記錄切片中的第一個休眠間隔。
圖 6.
Perfetto UI 顯示 MyAppSubmitButton 追蹤記錄切片中的第二個休眠間隔。
圖 7. `MyAppSubmitButton` 內的第二個休眠時間。
Perfetto UI 顯示 MyAppSubmitButton 追蹤記錄切片中的第三個休眠間隔。
圖 8. 第三次休眠時間在 `MyAppSubmitButton` 內。
Perfetto UI 顯示 MyAppSubmitButton 追蹤記錄切片中的第四個休眠間隔。
圖 9. `MyAppSubmitButton` 內的第四個睡眠時間。

前三個休眠間隔 (圖 6 至 8) 幾乎完全相同,每個間隔約為 2 秒。第四次休眠 (圖 9) 是離群值,時間為 0.7 秒。在運算環境中,剛好 2 秒的持續時間很少是巧合。這強烈暗示了程式設計的逾時,而非隨機的資源爭用。最後一次休眠可能是因為執行緒等待的作業成功,因此結束等待。

這個假設是應用程式多次達到使用者定義的 2 秒逾時,最後成功,導致延遲時間足以觸發 ANR。

Perfetto UI 顯示 MyApp:SubmitButton 追蹤記錄切片期間的延遲摘要,指出多個 2 秒的休眠間隔。
圖 10.`MyApp:SubmitButton` 切片期間的延遲摘要。

如要驗證這一點,請檢查與 MyApp:SubmitButton 追蹤記錄區段相關聯的程式碼:

private static final int NETWORK_TIMEOUT_MILLISECS = 2000;
public void setupButtonCallback() {
  findViewById(R.id.submit).setOnClickListener(submitButtonView -> {
    Trace.beginSection("MyApp:SubmitButton");
    onClickSubmit();
    Trace.endSection();
  });
}

public void onClickSubmit() {
  prepareNetworkRequest();

  boolean networkRequestSuccess = false;
  int maxAttempts = 10;
  while (!networkRequestSuccess && maxAttempts > 0) {
    networkRequestSuccess = performNetworkRequest(NETWORK_TIMEOUT_MILLISECS);
    maxAttempts--;
  }

  if (networkRequestSuccess) {
    handleNetworkResponse();
  }
}

boolean performNetworkRequest(int timeoutMiliseconds) {
  // ...
}


void prepareNetworkRequest() {
  // ...
}

public void handleNetworkResponse() {
  Trace.beginSection("handleNetworkResponse");
  // ...
  Trace.endSection();
}

程式碼證實了這項假設。onClickSubmit 方法會在 UI 執行緒上執行網路要求,並使用硬式編碼的 NETWORK_TIMEOUT_MILLISECS (2000 毫秒)。重要的是,它會在 while 迴圈內執行,最多重試 10 次。

在這個特定追蹤記錄中,使用者的網路連線可能不佳。前三次嘗試失敗,導致三次 2 秒逾時 (總共 6 秒)。第四次嘗試在 0.7 秒後成功,程式碼得以繼續執行 handleNetworkResponse。不過,累積的等待時間已觸發 ANR。

如要避免這類 ANR,請將延遲時間不一的網路相關作業放入背景執行緒,而非在主執行緒中執行。這樣一來,即使連線能力不佳,UI 仍可保持回應,完全消除這類 ANR。