Google は、黒人コミュニティに対する人種平等の促進に取り組んでいます。取り組みを見る

systrace について

注意: systrace を使用したことがない場合は、まず systrace の概要を読むことを強くおすすめします。

systrace は、Android デバイスのパフォーマンスを分析するための、メインのツールです。しかし、実際には他のツールのラッパーです。具体的には、atrace(ユーザー空間のトレースを制御し、Linux カーネルのメインのトレース メカニズム ftrace を設定する、デバイス側の実行ファイル)のホスト側のラッパーです。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 で直接有効にできる機能よりも多くの機能があり、パフォーマンスの問題をデバッグするために重要な、高度な機能が含まれています(こうした機能にはルート権限が必要です。多くの場合、新しいカーネルが必要です)。

systrace の実行

Pixel / Pixel XL でジッターをデバッグする場合は、次のコマンドで開始します。

    ./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000
    

GPU とディスプレイ パイプラインのアクティビティに必要な追加のトレースポイントと組み合わせると、ユーザー入力から画面上に表示されるフレームまでをトレースできます。バッファサイズを大きく設定して、イベントが失われないようにします(イベントが失われた場合、通常、トレース内のある時点以降にイベントを含まない CPU が現れます)。

systrace を使用する場合は、すべてのイベントが CPU 上の何かによってトリガーされることにご注意ください。

注: ハードウェア割り込みは CPU によって制御されず、ftrace の何かをトリガーしますが、トレースログへの実際のコミットは割り込みハンドラによって行われます。たとえば他の不良ドライバが割り込みを無効にしている間に割り込みが届いた場合、遅延している可能性があります。重要な要素は CPU です。

systrace は ftrace 上に作成され、ftrace は CPU 上で実行されるため、CPU 上の何かが、ハードウェアの変更を記録する ftrace バッファを書き込む必要があります。つまり、ディスプレイ フェンスの状態が変わった理由を知りたいとき、遷移の正確な時点で、CPU 上で何が実行されていたのかを確認できます(CPU 上で実行されている何かがログの変更をトリガーした)。この概念は、systrace を使用してパフォーマンスを分析するための基礎となります。

例: 機能しているフレーム

この例では、通常の UI パイプラインの systrace について説明します。まず、トレース(このセクションで言及している他のトレースも含みます)の zip ファイルをダウンロードし、ファイルを解凍して、ブラウザで systrace_tutorial.html ファイルを開きます。この systrace は大きなファイルであることにご注意ください。1 回のトレースでこれまで見たこともないほど多くの情報を含む、はるかに大きなトレースになる可能性があります。

TouchLatency などの一貫性のある周期的なワークロードの場合、UI パイプラインには下記が含まれます。

  1. SurfaceFlinger の EventThread がアプリの UI スレッドを復帰させ、新しいフレームをレンダリングする時間であることを知らせます。
  2. アプリが CPU リソースと GPU リソースを使用して、UI スレッド、RenderThread、hwuiTasks のフレームをレンダリングします。これが、UI に費やされる容量の大部分です。
  3. アプリが、レンダリングされたフレームをバインダー経由で SurfaceFlinger に送信し、スリープ状態になります。
  4. SurfaceFlinger の 2 番目の EventThread が、SurfaceFlinger を復帰させ、合成と表示出力をトリガーします。SurfaceFlinger は、実行する作業がないと判断するとスリープ状態に戻ります。
  5. SurfaceFlinger が、HWC / HWC2 または GL を介して合成を処理します。HWC / HWC2 合成は高速で低電力ですが、SOC に応じて制限があります。通常は 4~6 ms かかりますが、Android アプリは常にトリプル バッファリングされるため、ステップ 2 と重複することがあります(アプリは常にトリプル バッファリングされていますが、SurfaceFlinger で待機している保留フレームは 1 つのみであるため、ダブル バッファリングと同じように見えます)。
  6. SurfaceFlinger が、表示する最終出力をベンダー ドライバ経由でディスパッチし、スリープ状態に戻って EventThread wakeup を待ちます。

15,409 ms から始まるフレームを見てみましょう。

図 1. 通常の UI パイプライン、EventThread 実行中。

図 1 は通常のフレームで囲まれた通常のフレームであるため、UI パイプラインの仕組みを理解するのに適しています。TouchLatency の UI スレッド行には、異なる時間に異なる色が含まれます。バーは、スレッドのさまざまな状態を示します。

  • グレー: スリープ中。
  • : 実行可能(実行できるがスケジューラがまだ実行を選択していない)。
  • : アクティブに実行中(スケジューラが、実行中であると判断)。

    : 割り込みハンドラは通常の CPU ごとのタイムラインには表示されないため、スレッドのランタイムの一部で実際に割り込みハンドラまたは softirq を実行している可能性があります。トレースの irq セクション(プロセス 0 の下)を確認して、標準スレッドではなく割り込みが実行されているかどうかを確認します。

  • : 割り込み不可スリープ(通常、カーネル内のロックでスリープします)。I/O 負荷を示すことがあります。パフォーマンスの問題のデバッグで非常に役立ちます。
  • オレンジ: I/O 負荷による割り込み不可スリープ。

割り込み不可スリープの理由を表示するには(sched_blocked_reason トレースポイントから使用可能)、赤い割り込み不可スリープ スライスを選択します。

EventThread の実行中、TouchLatency の UI スレッドが実行可能になります。復帰した原因を確認するには、青い部分をクリックします。

図 2. TouchLatency の UI スレッド。

図 2 は tid 6843 によって復帰した TouchLatency UI スレッドを示しており、これは EventThread に対応しています。UI スレッドが復帰します。

図 3. UI スレッドが復帰し、フレームをレンダリングし、キューに登録して SurfaceFlinger で使用できるようにします。

トレースで binder_driver タグが有効になっている場合は、バインダー トランザクションを選択して、そのトランザクションに関連するすべてのプロセスの情報を表示できます。

図 4. バインダー トランザクション。

図 4 は、15,423.65 ms で TouchLatency の RenderThread である tid 9579 によって、SurfaceFlinger の Binder:6832_1 が実行可能になることを示しています。バインダー トランザクションの両側に queueBuffer もあります。

SurfaceFlinger 側の queueBuffer では、TouchLatency からの保留フレームの数は 1 から 2 になります。

図 5. 保留フレームは 1 から 2 になります。

図 5 はトリプル バッファリングを示しています。フレームが 2 つ完了しており、アプリはすぐに 3 つ目のレンダリングを開始します。これは、すでにフレーム落ちが発生しているので、さらにフレーム落ちが発生しないように、アプリが保留フレームを 1 つではなく 2 つ維持するためです。

その後すぐに、SurfaceFlinger のメインスレッドが 2 番目の EventThread によって復帰し、古い保留フレームをディスプレイに出力できるようになります。

図 6. SurfaceFlinger のメインスレッドが 2 番目の EventThread によって復帰します。

SurfaceFlinger はまず古い保留バッファをラッチし、保留バッファ数を 2 から 1 に減らします。

図 7. SurfaceFlinger はまず古い保留バッファをラッチします。

バッファをラッチした後、SurfaceFlinger は合成を設定し、最終フレームをディスプレイに送信します(これらのセクションのいくつかは、mdss トレースポイントの一部として有効になっているため、SOC には存在しない可能性があります)。

図 8. SurfaceFlinger は合成を設定し、最終フレームを送信します。

次に、mdss_fb0 が CPU 0 で復帰します。mdss_fb0 は、レンダリングされたフレームをディスプレイに出力するための、ディスプレイ パイプラインのカーネル スレッドです。mdss_fb0 はトレース内でそれ自体の行として表示されます(下にスクロールすると表示されます)。

図 9. mdss_fb0 が CPU 0 で復帰します。

mdss_fb0 が復帰し、少しの間実行され、割り込み不可スリープ状態に入ってから、再び復帰します。

: ここから先は最終的な作業が mdss_fb0、割り込み、ワークキューの各機能に分割されるため、トレースはさらに複雑になります。そのレベルの詳細が必要な場合は、SOC のドライバ スタックの正確な特性を参照してください(Pixel XL で生じることは役に立たない可能性があるため)。

例: 機能していないフレーム

この例では、Pixel / Pixel XL ジッターのデバッグに使用する systrace について説明します。まず、トレース(このセクションで言及している他のトレースも含みます)の zip ファイルをダウンロードし、ファイルを解凍して、ブラウザで systrace_tutorial.html ファイルを開きます。

systrace を最初に開いたとき、次のように表示されます。

図 10. Pixel XL で実行されている TouchLatency(mdss トレースポイントと kgsl トレースポイントを含め、ほとんどのオプションが有効になっています)。

ジャンクを探す場合は、SurfaceFlinger の下の FrameMissed 行を確認します。FrameMissed は、Hardware Composer 2(HWC2)が提供する QOL の改善です。2016 年 12 月現在、HWC2 は Pixel / Pixel XL でのみ使用されています。他のデバイスの systrace を表示している場合、FrameMissed 行は存在しないことがあります。いずれの場合も FrameMissed は、SurfaceFlinger で非常に標準的なランタイムの 1 つが欠落していることと、vsync でアプリの保留バッファ数(com.prefabulated.touchlatency)が不変であることに相関します。

図 11. FrameMissed と SurfaceFlinger の相関。

図 11 は、15,598.29 ms で欠落したフレームを示しています。SurfaceFlinger は vsync 間隔で一時的に復帰し、何も行わずにスリープ状態に戻りました。これは、フレームをディスプレイに再送する価値がないと SurfaceFlinger が判断したことを意味します。なぜでしょうか。

このフレームでパイプラインがどのように壊れたのかを理解するには、まず前述の機能しているフレームの例を見直して、systrace で通常の UI パイプラインがどのように表示されるかを確認します。準備ができたら欠落したフレームに戻り、さかのぼって考えます。SurfaceFlinger が復帰してすぐにスリープ状態に戻っています。TouchLatency からの保留フレーム数を表示すると、フレームが 2 つあります(起こっていることの理解に役立つ良い手がかりです)。

図 12. SurfaceFlinger が復帰してすぐにスリープ状態になります。

SurfaceFlinger にフレームがあるため、アプリの問題ではありません。さらに、SurfaceFlinger は正しい時間に復帰しているため、SurfaceFlinger の問題ではありません。SurfaceFlinger とアプリの両方が正常に見える場合は、おそらくドライバの問題です。

mdss トレースポイントと sync トレースポイントが有効になっているため、フレームが実際にディスプレイに送信されるタイミングを制御するフェンス(ディスプレイ ドライバと SurfaceFlinger の間で共有されます)に関する情報を取得できます。対象のフェンスは mdss_fb0_retire にリストされています。これは実際にフレームがディスプレイに表示されていることを示します。これらのフェンスは、sync トレース カテゴリの一部として提供されます。SurfaceFlinger の特定のイベントに対応するフェンスは SOC とドライバ スタックによって異なるため、SOC ベンダーと連携してトレース内のフェンス カテゴリの意味を把握してください。

図 13. mdss_fb0_retire フェンス。

図 13 は、予想した 16.7 ms ではなく 33 ms で表示されたフレームを示しています。スライスの途中で新しいフレームに置き換えられるべきでしたが、置き換えられませんでした。前のフレームを表示して、気になるものを探します。

図 14. 壊れたフレームの前のフレーム。

図 14 は、14.482 ms のフレームを示しています。壊れた 2 フレーム セグメントは 33.6 ms でした。これは 2 フレームの予想とほぼ同じです(60 Hz、1 フレーム 16.7 ms でレンダリングします)。しかし、14.482 ms は 16.7 ms よりはるかに長いため、ディスプレイ パイプになんらかの大きな問題があることがわかります。

フェンスの終点を正確に調べて、何がフェンスを制御しているのかを判断します。

図 15. フェンスの終点を調べます。

ワークキューには、フェンスが変更されたときに実行されている __vsync_retire_work_handler が含まれています。カーネルソースを見ると、これがディスプレイ ドライバの一部であることがわかります。これは明らかにディスプレイ パイプラインのクリティカル パス上にあるため、できるだけ早く実行する必要があります。70 us 程度実行可能ですが(長いスケジューリング遅延ではありません)、これはワークキューであり、正確にスケジュールされていない可能性があります。

前のフレームを確認して、それが原因かどうかを判断します。時間が経つにつれてジッターが増加し、最終的に間に合わなくなることもあります。

図 16. 前のフレーム。

kworker 上の実行可能な行は、ビューアが選択されると白くなるため表示されていませんが、統計情報によると、ディスプレイ パイプラインのクリティカル パスの一部に 2.3 ms のスケジューラ遅延が発生しており、問題です。これは他の作業を行う前に、ディスプレイ パイプライン クリティカル パスのこの部分を、ワークキュー(SCHED_OTHER CFS スレッドとして実行されます)から専用の SCHED_FIFO kthread に移動することで、修正する必要があります。この機能には、ワークキューでは提供できない(意図されていない)タイミング保証が必要です。

これがジャンクの原因でしょうか。一概には言えません。カーネルロック競合が原因で表示に不可欠なスレッドがスリープ状態になるなど診断しやすい場合を除き、トレースでは通常、何が問題なのか直接わかるわけではありません。このジッターがフレーム落ちの原因だったのでしょうか。そのとおりです。フェンス時間は 16.7 ms である必要がありますが、フレーム落ちまでのフレームでは、時間が大きく異なります(19 ms のフェンスの後に 14 ms のフェンスがあります)。ディスプレイ パイプラインの結合の度合いを考慮すると、フェンスのタイミング付近でジッターが発生し、最終的にフレーム落ちにつながた可能性があります。

この例では、__vsync_retire_work_handler をワークキューから専用の kthread に変換するという解決策をとりました。その結果、ジッターが大幅に改善され、弾むボールのテストではジャンクが減少しました。その後のトレースでは、フェンスのタイミングが 16.7 ms に非常に近くなっています。