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 のみを実行する手順は次のとおりです。

  1. バッファサイズとして、トレースに十分な大きさの値を設定します。
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
    
  2. トレースを有効にします。
    echo 1 > /sys/kernel/tracing/tracing_on
    
  3. テストを実行してから、トレースを無効にします。
    echo 0 > /sys/kernel/tracing/tracing_on
    
  4. トレースをダンプします。
    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 が同じディレクトリに書き込まれます。

イベントを関連付ける

多くの場合、Catapult 可視化と ftrace ログを同時に確認することによって有用な情報を得られます。たとえば、一部の ftrace イベント(特にベンダー固有のイベント)は Catapult によって可視化されません。ただし、Catapult のタイムスタンプは、トレースの最初のイベントに対する、または atrace によってダンプされた特定のタイムスタンプに対する相対値です。一方、未加工の ftrace タイムスタンプは Linux カーネルの特定の絶対クロックソースに基づいています。

Catapult イベントから特定の ftrace イベントを検索する手順は次のとおりです。

  1. 生の ftrace ログを開きます。systrace の比較的新しいバージョンのトレースは、デフォルトで圧縮されています。
    • --no-compress フラグ付きで systrace をキャプチャした場合、html ファイルの BEGIN TRACE で始まるセクションとして出力されます。
    • それ以外の場合は、Catapult ツリーtracing/bin/html2trace)から html2trace を実行してトレースを解凍します。
  2. Catapult の可視化で相対タイムスタンプを探します。
  3. トレースの先頭で tracing_mark_sync を含む行を探します。次のようになります。
    <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
    

    この行が存在しない場合(または atrace なしで ftrace を使用した場合)、時間情報は ftrace ログの最初のイベントからの相対値となります。
    1. 相対タイムスタンプ(ミリ秒単位)を parent_ts(秒単位)の値に加えます。
    2. その新しいタイムスタンプで検索します。

これらの手順を行うことにより、目的のイベントに(または少なくとも非常に近いところに)到達します。

動的 ftrace を使用する

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

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

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

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

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


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

lockstat を使用する

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

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


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

  1. トレースを有効にします。
    echo 1 > /proc/sys/kernel/lock_stat
    
  2. テストを実行します。
  3. トレースを無効にします。
    echo 0 > /proc/sys/kernel/lock_stat
    
  4. トレースをダンプします。
    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 の定義とデフォルト実装をご覧ください。