systrace は、Android デバイスのパフォーマンスを分析するための、メインのツールです。ただし、実際には他のツールのラッパーです。具体的には、atrace（ユーザー空間のトレースを制御して ftrace をセットアップするデバイス側の実行可能ファイル）のホスト側ラッパーであり、また、Linux カーネルの主要なトレース メカニズムでもあります。systrace は atrace を使用してトレースを有効化し、次に ftrace バッファを読み取り、それらすべてを自己完結型の HTML ビューアでラップします（新しいカーネルは Linux Enhanced Berkeley Packet Filter（eBPF）をサポートしていますが、下記のドキュメントは Pixel / Pixel XL で使用されていた 3.18 カーネル（eFPF なし）を対象としています）。
systrace は Google Android チームと Google Chrome チームの所有物であり、Catapult プロジェクトの一環としてオープンソースで開発されています。Catapult には systrace 以外にも便利なユーティリティが含まれています。たとえば ftrace には、systrace または atrace で直接有効にできる機能よりも多くの機能があり、パフォーマンスの問題をデバッグするために欠かせない高度な機能を備えています（こうした機能を利用するには root 権限が必要です。また多くの場合、新しいカーネルが必要です）。
systrace の実行
Google Pixel / Google Pixel XL でジッターをデバッグする場合は、まず次のコマンドを実行します。
./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000
GPU およびディスプレイ パイプラインのアクティビティに必要な追加のトレースポイントと組み合わせると、ユーザー入力から画面上にフレームが表示されるまでの過程をトレースできます。バッファサイズを大きな値に設定して、イベントが失われないようにします（バッファを大きくしないと、トレース内の特定の時点以降、一部の CPU にイベントが含まれなくなります）。
systrace の実行中は、すべてのイベントが CPU 上の何かによってトリガーされることに留意してください。
systrace は ftrace 上に構築されており、ftrace は CPU 上で実行されるため、CPU 上の何かが、ハードウェアの変更をログに記録する ftrace バッファを書き込む必要があります。つまり、ディスプレイ フェンスの状態が変化した理由を知りたい場合、遷移の正確な時点で、CPU 上で何が実行されていたか（何が CPU 上で実行されてログの変更をトリガーしたか）を確認できます。この概念は、systrace を使用してパフォーマンスを分析するための基礎となります。
例: 正常に機能しているフレーム
この例では、正常な UI パイプラインの場合の systrace について説明します。この例で取り上げるトレースを実際に参照するには、トレース（このセクションで言及する他のトレースも含まれています）の zip ファイルをダウンロードし、ファイルを解凍して、ブラウザで systrace_tutorial.html ファイルを開きます。この systrace は大きなファイルであることにご注意ください。systrace を日常的に使用していない限り、一度のトレースではこれまでに見たことがないほど多くの情報を含む大規模なトレースであるはずです。
TouchLatency などの一貫性のある周期的なワークロードの場合、UI パイプラインには以下の処理が含まれます。
- SurfaceFlinger の EventThread がアプリの UI スレッドを復帰させ、新しいフレームをレンダリングするときが来たことを知らせます。
- アプリは、CPU リソースと GPU リソースを使用して、UI スレッド、RenderThread、hwuiTasks でフレームをレンダリングします。これが、UI に費やされる容量の大部分です。
- アプリはバインダーを使用して、レンダリングされたフレームを SurfaceFlinger に送信し、SurfaceFlinger はスリープ状態になります。
- SurfaceFlinger の 2 番目の EventThread が SurfaceFlinger を復帰させ、コンポジションとディスプレイ出力をトリガーします。SurfaceFlinger は、実行する作業がないと判断した場合、スリープ状態に戻ります。
- SurfaceFlinger は、Hardware Composer（HWC）/ HardwareComposer 2（HWC2）または GL を使用して、コンポジションを処理します。HWC / HWC2 コンポジションは比較的高速かつ低消費電力ですが、システム オン チップ（SoC）に応じた制限があります。この処理には通常 4～6 ms かかりますが、Android アプリは常にトリプル バッファリングされるため、ステップ 2 と同時に実行されることがあります（アプリは常にトリプル バッファリングされますが、SurfaceFlinger で待機している保留フレームは 1 つのみであるため、ダブル バッファリングと同じに見えます）。
- SurfaceFlinger は、表示する最終出力をベンダー ドライバでディスパッチし、スリープ状態に戻って EventThread の復帰を待機します。
15,409 ms 以降のフレームを見てみましょう。
図 1 は正常なフレームで囲まれた正常なフレームを示しているので、UI パイプラインの仕組みを理解するのに適しています。TouchLatency の UI スレッド行には、時間によって異なる色が表示されています。バーは、スレッドのさまざまな状態を示します。
- グレー: スリープ中。
- 青: 実行可能（実行できるが、スケジューラがまだ実行を選択していない）。
- 緑: アクティブに実行中（スケジューラが実行中と判断）。
- 赤: 割り込み不可スリープ（通常はカーネル内のロックでスリープする）。I/O 負荷を示している可能性があります。パフォーマンスの問題のデバッグで非常に役立ちます。
- オレンジ: I/O 負荷による割り込み不可スリープ。
割り込み不可スリープの原因を表示するには（sched_blocked_reason トレースポイントから可能）、赤い割り込み不可スリープ スライスを選択します。
EventThread の実行中は、TouchLatency の UI スレッドが実行可能になります。復帰した原因を表示するには、青い部分をクリックします。
図 2 は tid 6843（EventThread に対応）によって復帰した TouchLatency の UI スレッドを示しています。UI スレッドが復帰し、フレームをレンダリングして、SurfaceFlinger が使用できるようにキューに登録します。
トレースで binder_driver タグが有効になっている場合は、バインダー トランザクションを選択して、そのトランザクションに関連するすべてのプロセスの情報を表示できます。
図 4 は、15,423.65 ms の時点で、TouchLatency の RenderThread である tid 9579 によって SurfaceFlinger の Binder:6832_1 が実行可能になったことを示しています。バインダー トランザクションの両側に queueBuffer があることも確認できます。
SurfaceFlinger 側の queueBuffer では、TouchLatency からの保留フレームの数が 1 から 2 になります。
図 5 はトリプル バッファリングを示しています。フレームが 2 つ完了しており、アプリは 3 つ目のフレームのレンダリングを開始しようとしています。これは、すでにフレーム落ちが発生しているので、さらにフレーム落ちが発生するのを防ぐ目的で、アプリが保留フレームを 1 つではなく 2 つ保持するためです。
その直後に、SurfaceFlinger のメインスレッドが 2 番目の EventThread によって復帰し、古い保留フレームをディスプレイに出力できるようになります。
SurfaceFlinger は、まず古い保留バッファをラッチします。これにより、保留バッファ数が 2 から 1 に減少します。
バッファをラッチした後、SurfaceFlinger はコンポジションをセットアップし、最終フレームをディスプレイに送信します（これらのセクションのいくつかは mdss トレースポイントの一部として有効になっているため、SoC に含まれていない可能性があります）。
次に、mdss_fb0 が CPU 0 で復帰します。mdss_fb0 は、レンダリングされたフレームをディスプレイに出力するための、ディスプレイ パイプラインのカーネル スレッドです。mdss_fb0 は、トレース内で独立した行として表示されます（下にスクロールすると表示できます）。
mdss_fb0 が復帰して短時間実行され、割り込み不可スリープ状態に入った後、再び復帰します。
例: 正常に機能していないフレーム
この例では、Pixel / Pixel XL のジッターをデバッグする場合の systrace について説明します。この例で取り上げるトレースを実際に参照するには、トレース（このセクションで言及する他のトレースも含まれています）の zip ファイルをダウンロードし、ファイルを解凍して、ブラウザで systrace_tutorial.html ファイルを開きます。
systrace を開くと、次のように表示されます。
ジャンクを探す場合は、SurfaceFlinger の下の FrameMissed 行をチェックします。FrameMissed は、HWC2 によって提供される品質向上のための機能です。他のデバイスの systrace を確認する場合、デバイスで HWC2 が使用されていなければ、FrameMissed 行が存在しない可能性があります。いずれの場合も、FrameMissed は、SurfaceFlinger で非常に標準的なランタイムの 1 つが欠落していることと、vsync でアプリの保留バッファ数（com.prefabulated.touchlatency）が不変であることと相関関係にあります。
図 11 は、15,598.29&nbps;ms でのフレームの欠落を示しています。SurfaceFlinger は vsync 間隔で短時間復帰し、何もせずにスリープ状態に戻りました。これは、SurfaceFlinger がフレームをディスプレイに再送信する価値がないと判断したことを意味します。なぜでしょうか？
このフレームでパイプラインが正常に機能しなかった原因を理解するには、まず上記の正常に機能しているフレームの例を見直して、systrace で正常な UI パイプラインがどのように表示されるかを確認します。確認できたら、欠落したフレームに戻り、時間をさかのぼって検討します。SurfaceFlinger が復帰してすぐにスリープ状態に戻っていることに着目してください。TouchLatency からの保留フレーム数を見ると、フレームが 2 つあります（これは、何が起こったかを理解するのに役立つ良い手がかりです）。
SurfaceFlinger にフレームがあるため、アプリの問題ではありません。また、SurfaceFlinger は正しい時間に復帰しているため、SurfaceFlinger の問題でもありません。SurfaceFlinger とアプリが両方とも正常と思われる場合は、おそらくドライバの問題です。
mdss トレースポイントと sync トレースポイントが有効になっているため、フレームがディスプレイに送信されるタイミングを制御するフェンス（ディスプレイ ドライバと SurfaceFlinger の間で共有される）に関する情報が得られます。これらのフェンスは mdss_fb0_retire の下にリストされています。これは、フレームがディスプレイに表示されていることを示します。これらのフェンスは、sync トレース カテゴリの一部として提供されます。SurfaceFlinger の特定のイベントに対応するフェンスは SOC とドライバ スタックによって異なるため、実際のトレースでフェンス カテゴリの意味を理解するには、SOC ベンダーに問い合わせてください。
図 13 は、予想される 16.7 ms ではなく 33 ms の間表示されたフレームを示しています。このフレームは、スライスの途中で新しいフレームに置き換えられるはずでしたが、置き換えられませんでした。直前のフレームを表示して、原因を探します。
図 14 は、14.482 ms のフレームを示しています。正常でない 2 フレームのセグメントは 33.6 ms でした。これは 2 フレームに対する予想とほぼ同じです（60 Hz の場合、1 フレームにつき 16.7 ms でレンダリングされます）。しかし、14.482 ms は 16.7 ms から隔たりがあり、ディスプレイ パイプになんらかの大きな問題があることを示唆しています。
フェンスの終点を正確に調べて、何がフェンスを制御しているのかを判断します。
ワークキューには、フェンスが変更されたときに実行されていた __vsync_retire_work_handler が含まれています。カーネルソースを見ると、ディスプレイ ドライバの一部であることがわかります。ディスプレイ パイプラインのクリティカル パス上にあると思われるため、できるだけ早く実行する必要があります。実行可能状態が 70 us ほど続いていますが（長いスケジューリング遅延ではありません）、これはワークキューであり、正確にスケジュールされていない可能性があります。
直前のフレームをチェックして、それが原因かどうかを判断します。時間が経つにつれてジッターが増加し、結果的に期限に間に合わなくなることがあります。
kworker 上の実行可能な行は、選択されるとビューアによって白で表示されるため識別できませんが、統計情報により、ディスプレイ パイプラインのクリティカル パスの一部に 2.3 ms のスケジューラ遅延が発生しており、これが問題であることがわかりました。先に進む前に、ディスプレイ パイプラインのクリティカル パスのこの部分を、ワークキュー（SCHED_OTHER CFS スレッドとして実行される）から専用の SCHED_FIFO kthread に移動することにより、遅延を解決します。この機能には、ワークキューが提供できない（そもそも目的としていない）タイミング保証が必要です。
これがジャンクの原因でしょうか。断定はできません。診断が容易なケース（たとえば、カーネルのロック競合によって表示に不可欠なスレッドがスリープ状態になる場合）を除き、一般的にトレースでは問題の原因は特定されません。このジッターがフレーム落ちの原因でしょうか。それは確かです。フェンス時間は 16.7 ms のはずでしたが、フレーム落ちに至ったいくつかのフレームで、それとは異なるフェンス時間が見られました。ディスプレイ パイプラインの結合密度からすると、フェンスのタイミング付近でジッターが発生し、フレーム落ちにつながった可能性があります。
この例では、__vsync_retire_work_handler をワークキューから専用の kthread に移動するという解決策をとりました。その結果、ジッターが大幅に改善され、弾むボールのテストではジャンクが減少しました。その後のトレースでは、フェンス時間は 16.7 ms に非常に近い値になっています。