ftrace を使用する

ftrace は、Linux カーネル内で発生していることを把握するためのデバッグツールです。以下のセクションでは、ftrace の基本機能、atrace（カーネルイベントをキャプチャします）での ftrace の使用方法、動的 ftrace について詳しく説明します。

systrace で使用できない ftrace の高度な機能については、ftrace のドキュメント（<kernel tree>/Documentation/trace/ftrace.txt）をご覧ください。

atrace でカーネルイベントをキャプチャする

atrace（frameworks/native/cmds/atrace）は ftrace を使用してカーネルイベントをキャプチャします。次に、systrace.py（または Catapult のより新しいバージョンでは run_systrace.py）が adb を使用してデバイス上で atrace を実行します。atrace は以下の処理を行います。

プロパティ（debug.atrace.tags.enableflags）を設定してユーザーモードのトレースをセットアップします。
適切な ftrace sysfs ノードに書き込むことで、必要な ftrace 機能を有効にします。ただし、ftrace がサポートしている機能は他にもあるため、sysfs ノードを自分でいくつか設定してから atrace を使用することもできます。

起動時トレースを除き、プロパティに適切な値を設定するには atrace を使用してください。このプロパティはビットマスクであり、適切なヘッダー（Android リリース間で変更される可能性があります）を調べる以外に、正しい値を判断するおすすめの方法はありません。

ftrace イベントを有効にする

ftrace sysfs ノードは /sys/kernel/tracing にあり、トレースイベントは /sys/kernel/tracing/events 以下の各カテゴリに分類されています。

カテゴリごとにイベントを有効にするには、次のコマンドを使用します。

echo 1 > /sys/kernel/tracing/events/irq/enable

イベントごとにイベントを有効にするには、次のコマンドを使用します。

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

sysfs ノードへの書き込みによって追加のイベントが有効になっている場合、それらのイベントは atrace でリセットされません。Qualcomm デバイス開発での一般的なパターンは、kgsl（GPU）と mdss（ディスプレイパイプライン）のトレースポイントを有効にしてから、atrace または systrace を使用するというものです。

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

atrace または systrace を使用せずに ftrace を使用することもできます。これは、カーネルのみのトレースを行う場合（またはユーザーモードのトレースプロパティを手動で書き込むのに時間がかかっている場合）に便利です。ftrace のみを実行する手順は次のとおりです。

バッファサイズとして、トレースに十分な大きさの値を設定します。
```
echo 96000 > /sys/kernel/tracing/buffer_size_kb
```

トレースを有効にします。

echo 1 > /sys/kernel/tracing/tracing_on

テストを実行してから、トレースを無効にします。
```
echo 0 > /sys/kernel/tracing/tracing_on
```

トレースをダンプします。

cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output

trace_output はトレースをテキスト形式で出力します。Catapult を使用して可視化するには、GitHub から Catapult リポジトリを取得し、trace2html を実行します。

catapult/tracing/bin/trace2html ~/path/to/trace_file

デフォルトでは、trace_file.html が同じディレクトリに書き込まれます。

動的 ftrace を使用する

systrace と標準の ftrace では不十分な場合、最後の手段として動的 ftrace を使用します。動的 ftrace は起動後にカーネルコードを書き換えるため、セキュリティ上の理由から製品版カーネルでは使用できません。ただし、2015 年と 2016 年に問題となった困難なパフォーマンスバグはすべて、最終的に動的 ftrace を使用することにより根本原因が突き止められました。これは、割り込み不可スリープをトリガーする関数を実行するたびにカーネル内でスタックトレースを取得できるため、割り込み不可スリープのデバッグには特に効果的です。また、割り込みとプリエンプションを無効にしてセクションをデバッグすることもでき、問題を検証するのに非常に便利です。

動的 ftrace を有効にするには、カーネルの defconfig を編集します。

CONFIG_STRICT_MEMORY_RWX を削除します（存在する場合）。3.18 以降と arm64 の場合は存在しません。
CONFIG_DYNAMIC_FTRACE=y、CONFIG_FUNCTION_TRACER=y、CONFIG_IRQSOFF_TRACER=y、CONFIG_FUNCTION_PROFILER=y、CONFIG_PREEMPT_TRACER=y を追加します。
新しいカーネルを再ビルドして起動します。
次のコマンドを実行して、使用可能なトレーサーを確認します。
```
cat /sys/kernel/tracing/available_tracers
```
コマンドが function、irqsoff、preemptoff、preemptirqsoff を返すことを確認します。
次のコマンドを実行して、動的 ftrace が機能していることを確認します。
```
cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
```

これらの手順を完了すると、動的 ftrace、関数プロファイラ、irqsoff プロファイラ、preemptoff プロファイラを使用できるようになります。これらは強力ですが複雑であるため、使用する前に ftrace ドキュメントで関連するトピックについて確認しておくことを強くおすすめします。irqsoff と preemptoff は主に、ドライバが長時間にわたって割り込みまたはプリエンプションを無効にしたままであることの確認に使用できます。

関数プロファイラは、パフォーマンスの問題に最適なオプションであり、関数が呼び出されている場所を調べるためによく使用されます。

問題を表示: HDR 写真 + 回転ビューファインダー

この問題は、Pixel XL を使用して HDR+ 写真を撮影した後、すぐにビューファインダーを回転させると毎回ジャンクが発生する、というものです。関数プロファイラを使用することによって 1 時間未満で問題をデバッグできました。この例について確認するには、トレースの zip ファイルをダウンロードし（このセクションで言及している他のトレースも含まれます）、ファイルを解凍して、ブラウザで trace_30898724.html ファイルを開きます。

cameraserver プロセス内の複数のスレッドが、ion_client_destroy で割り込み不可スリープ状態にあることをトレースが示しています。これは高コストの関数ですが、ion クライアントには多くの割り当てが必要なため、呼び出しはごく少なくする必要があります。当初、原因は Halide の Hexagon コードにあると考えられましたが、実際にはこのコードだけではありませんでした（ion 割り当てごとに新しいクライアントを作成し、割り当てが解放されるとそのクライアントを破棄していましが、これは非常に高コストでした）。すべての Hexagon 割り当てを 1 つの ion クライアントに移行することで状況は改善されましたが、ジャンクは修正されませんでした。

ここで、何が ion_client_destroy を呼び出しているのかを知る必要があります。そのため、関数プロファイラを使用します。

コンパイラによって関数の名前が変更されることがあるため、次のコマンドを使用して ion_client_destroy が存在することを確認します。
```
cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
```
存在することを確認したら、ftrace フィルタとして使用します。
```
echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
```

関数プロファイラを有効にします。

echo function > /sys/kernel/tracing/current_tracer

フィルタ関数が呼び出されるたびにスタックトレースを有効にします。
```
echo func_stack_trace > /sys/kernel/tracing/trace_options
```

バッファサイズを増やします。

echo 64000 > /sys/kernel/tracing/buffer_size_kb

トレースを有効にします。
```
echo 1 > /sys/kernel/tracing/trace_on
```
テストを実行し、トレースを取得します。
```
cat /sys/kernel/tracing/trace > /data/local/tmp/trace
```

トレースを表示して、非常に多くのスタックトレースを確認します。

    cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
    cameraserver-643   [003] ...1    94.192997: <stack trace>
 => ftrace_ops_no_ops
 => ftrace_graph_call
 => ion_client_destroy
 => ion_release
 => __fput
 => ____fput
 => task_work_run
 => do_notify_resume
 => work_pending

ion ドライバの調査に基づき、なんらかのカーネルドライバではなく、/dev/ion を指す fd をクローズするユーザー空間関数によって ion_client_destroy が大量に送られていることがわかりました。Android コードベースで \"/dev/ion\" を検索すると、複数のベンダードライバが Hexagon ドライバと同じことをしており、新しい ion 割り当てが必要になるたびに /dev/ion をオープン / クローズしている（新しい ion クライアントの作成と破棄をしている）ことがわかりました。プロセスの全期間中に 1 つの ion クライアントを使用するように変更すると、バグが修正されました。

関数プロファイラのデータが十分に具体的でない場合は、ftrace トレースポイントと関数プロファイラを組み合わせることができます。ftrace イベントは、通常とまったく同じ方法で有効にでき、トレースとインターリーブされます。これは、デバッグする特定の関数で時折長い割り込み不可スリープが発生する場合に便利です。ftrace フィルタを目的の関数に設定し、トレースポイントを有効にしてトレースします。trace2html で結果のトレースを解析し、目的のイベントを探してから、未加工のトレースでその近辺のスタックトレースを取得できます。

lockstat を使用する

場合によっては ftrace だけでは不十分で、カーネルロックの競合と思われる状況をデバッグしなければならないこともあります。もう一つ、試してみる価値のあるカーネルオプションとして、CONFIG_LOCK_STAT があります。これはカーネルサイズをほとんどのデバイスでの限界以上に大きくしてしまうため、Android デバイスで機能させるのは難しく、あくまでも最後の手段です。

ただし、lockstat はデバッグロックのインフラストラクチャを使用します。これは他の多くのアプリでも有用です。デバイス開発に取り組むにあたっては、対象デバイスを問わずこのオプションを機能させるなんらかの方法を見つける必要があります。「LOCK_STAT を有効にできれば、5 日間ではなく 5 分間でこの問題について確認または反論できるのに」と思うときが必ずくるためです。

問題を表示: コアが SCHED_FIFO 以外で最大負荷になったときの SCHED_FIFO でのストール

この問題は、すべてのコアが SCHED_FIFO 以外のスレッドで最大負荷になると、SCHED_FIFO スレッドがストールする、というものです。VR アプリでは fd の重大なロック競合を示すトレースがありましたが、使用中の fd を簡単には特定できませんでした。この例について確認するには、トレースの zip ファイルをダウンロードし（このセクションで言及している他のトレースも含まれます）、ファイルを解凍して、ブラウザで trace_30905547.html ファイルを開きます。

ftrace 自体がロック競合の原因であり、優先度の低いスレッドが ftrace パイプへの書き込みを開始し、ロックを解除する前にプリエンプトされているものと仮定しました。これは最悪のケースのシナリオであり、ftrace マーカーに書き込む非常に優先度の低いスレッドと、すべて搭載されたデバイスのシミュレートに CPU を使う優先度の高いスレッドとが混在していたために、悪化しました。

ftrace を使用してデバッグできなかったため、LOCK_STAT が動作していることを確認してから、その他のトレースをアプリからすべてオフにしました。その結果、ftrace を実行していないときにはロックトレースに競合が示されなかったため、ロック競合の原因が実際に ftrace にあることがわかりました。

config オプションでカーネルを起動できる場合、ロックトレースは ftrace の場合と同様です。

トレースを有効にします。
```
echo 1 > /proc/sys/kernel/lock_stat
```
テストを実行します。
トレースを無効にします。
```
echo 0 > /proc/sys/kernel/lock_stat
```

トレースをダンプします。

cat /proc/lock_stat > /data/local/tmp/lock_stat

結果の出力の解釈については、lockstat のドキュメント（<kernel>/Documentation/locking/lockstat.txt）をご覧ください。

ベンダートレースポイントを使用する

アップストリームトレースポイントを先に使用しますが、ベンダートレースポイントが必要になる場合もあります。

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

トレースポイントは HAL サービスによって拡張可能であり、デバイス固有のトレースポイントまたはカテゴリを追加できます。トレースポイントは、perfetto、atrace / systrace、デバイス上のシステムトレースアプリに統合されています。

トレースポイントまたはカテゴリを実装するための API は次のとおりです。

listCategories()generates (vec<TracingCategory> categories);
enableCategories(vec<string> categories) generates (Status status);
disableAllCategories() generates (Status status);

詳細については、AOSP の HAL の定義とデフォルト実装をご覧ください。