パフォーマンス デバッグの実践的な例: 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);
}
ProfilingManagerJavaSnippets.java

ANR トレースをキャプチャしてアップロードしたら、Perfetto UI で開きます。

トレースを分析する

ANR によってトレースがトリガーされたため、トレースはアプリのメインスレッドで応答なしが検出されたときに終了したことがわかります。図 1 は、UI 内で適切にタグ付けされたアプリのメインスレッドに移動する方法を示しています。

図 1. アプリのメインスレッドへのナビゲーション。

図 2 に示すように、トレースの末尾は ANR のタイムスタンプと一致します。

図 2. ANR トリガーの場所。

トレースには、ANR が発生したときにアプリが実行していたオペレーションも表示されます。具体的には、アプリは handleNetworkResponse トレース スライスでコードを実行しました。このスライスは MyApp:SubmitButton スライス内にありました。CPU 時間は 1.48 秒でした（図 3）。

図 3. ANR 発生時の実行。

ANR の発生時のスタック トレースのみに依存してデバッグを行うと、プロファイルの記録が終了したときに終了していなかった handleNetworkResponse トレース スライス内で実行されていたコードに ANR の原因がすべてあると誤って判断する可能性があります。ただし、1.48 秒はコストの高いオペレーションではありますが、それだけで ANR をトリガーするには不十分です。このメソッドの前にメインスレッドをブロックしたものを理解するには、さらに時間を遡って確認する必要があります。

ヒント: 実行時間の長いオペレーションを特定し、重要なユーザー ジャーニーを特定するために、カスタム トレース スライスを追加することをおすすめします。

ANR の原因を探すための出発点として、Choreographer#doFrame 551275 スライスに対応する UI スレッドによって生成された最後のフレームの後に、ANR で終了した MyApp:SubmitButton スライスが開始される前に大きな遅延の原因がないことを確認します（図 4）。

図 4. ANR の前に生成された最後のアプリフレーム。

閉塞を理解するには、ズームアウトして MyApp:SubmitButton スライス全体を調べます。図 4 に示すように、スレッドの状態には重要な詳細があります。スレッドは 75% の時間（6.7 秒）を Sleeping 状態で費やし、Running 状態では 24% の時間しか費やしていません。

図 5. `MyApp:SubmitButton` オペレーション中のスレッドの状態。

これは、ANR の主な原因が計算ではなく待機であったことを示しています。個々の睡眠発生を調べてパターンを見つけます。

図 6. `MyAppSubmitButton` 内の最初のスリープ時間。

図 7. `MyAppSubmitButton` 内の 2 回目のスリープ時間。

図 8. `MyAppSubmitButton` 内の 3 回目のスリープ時間。

図 9. `MyAppSubmitButton` 内の 4 回目の睡眠時間。

最初の 3 つの睡眠間隔（図 6 ～ 8）はほぼ同じで、それぞれ約 2 秒です。外れ値の 4 回目の睡眠（図 9）は 0.7 秒です。コンピューティング環境で 2 秒という期間が偶然であることはほとんどありません。これは、ランダムなリソース競合ではなく、プログラムされたタイムアウトを示唆しています。最後のスリープは、待機していたオペレーションが成功したため、スレッドが待機を終了したことが原因である可能性があります。

この仮説は、アプリがユーザー定義の 2 秒のタイムアウトに複数回ヒットし、最終的に成功したため、ANR をトリガーするのに十分な遅延が発生したというものです。

図 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) {
  // ...
}

  // ...
}

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

このコードは、この仮説を確認します。onClickSubmit メソッドは、ハードコードされた NETWORK_TIMEOUT_MILLISECS（2,000 ミリ秒）を使用して UI スレッドでネットワーク リクエストを実行します。重要なのは、最大 10 回再試行する while ループ内で実行されることです。

この特定のトレースでは、ネットワーク接続が不安定だった可能性があります。最初の 3 回の試行が失敗し、2 秒のタイムアウトが 3 回発生しました（合計 6 秒）。4 回目の試行は 0.7 秒後に成功し、コードは handleNetworkResponse に進むことができました。ただし、累積待機時間がすでに ANR をトリガーしています。

注: トレース分析で仮説（「これはネットワーク タイムアウトである」など）が導き出されたものの、トレースデータがそれを証明するのに十分でない場合は、反復アプローチを使用します。疑わしいロジックの周辺に新しいトレース スライスを追加し、新しいフィールド データを収集して仮説を検証します。

このタイプの ANR を回避するには、レイテンシが変動するネットワーク関連のオペレーションをメインスレッドで実行するのではなく、バックグラウンド スレッドに配置します。これにより、接続が不安定な場合でも UI の応答性を維持し、このクラスの ANR を完全に排除できます。