カーネル起動時トレース

Linuxカーネルの起動処理は、様々なことが行われるのにそれをデバッグする方法はprintkだったり、逆にkgdbを外部デバッガから繋いだりと、結構な手間がかかっていました。カーネルが起動してしまえば、ftraceにperf, BPF, systemtapと複数の手段が使えるのに、起動時のデバッグは細かいことが出来ません。これは、起動時に指定できるオプションが大雑把になるのが大きな理由の一つでした。シェル芸ではないですが、1行プログラミングだけで様々なことをするのは大変です。

そこで導入されたのがExtra Boot Configuration (bootconfig)です。Bootconfigについては前回の記事を参考にしてください。
ここではカーネルコマンドラインのトレースオプションと、Bootconfigによって拡張されたBoot-time trace（CONFIG_BOOTTIME_TRACING）について説明をしていきます。

カーネルコマンドラインのトレースオプション

カーネルコマンドラインから与えられるトレースオプションについてはkernel-parameters.txtで*[FTRACE]*を検索すれば大体引っかかります。

トレースオプションの設定(trace_options=)
トレースイベントだけをprintkバッファへ出力(tp_printk)
トレースイベントを有効化(trace_events=)
トレーサを有効化(ftrace=)
関数トレーサのフィルタ(ftrace_filter=, ftrace_notrace=, ftrace_graph_filter=, ftrace_graph_notrace=)
kprobeイベントの追加(kprobe_events=)
その他のオプション(alloc_snapshot, traceoff_on_warning, etc.)

カーネルコマンドラインの実例

これらのオプションを使って、実際に以下の条件でトレースの設定をしてみましょう。

イベントをprintkに出力する
sym-addr（アドレスだけでなくシンボルも表示する）オプションを付ける
globalトレースクロックを利用（全CPUで同じ時刻にする）
OOPSがでたらftraceをダンプする
トレースバッファサイズは1MB
initcall, irq, exceptionのイベントグループをトレースする
set_memory_roとset_memory_rxを引数2つ付きでトレースする

これはgrub.confなどで次のように指定できます。

linux
/boot/vmlinuz-5.1 root=UUID=5a026bbb-6a58-4c23-9814-5b1c99b82338 ro quiet splash tp_printk trace_options=”sym-addr” trace_clock=global ftrace_dump_on_oops trace_buf_size=1M trace_event=”initcall:*,irq:*,exceptions:*” kprobe_event="p:kprobes/memory_ro set_memory_ro $arg1 $arg2;p:kprobes/memory_rw set_memory_rw $arg1 $arg2"

カーネルコマンドラインの問題

先程の実例でお分かりいただけたでしょうか。そうです。トレースオプションをコマンドラインで指定すると、とても長くなってしまうのです。

また、コマンドラインオプションでは基本的な機能は存在しているのですが、tracefsを経由して指定できる機能、例えばイベントごとの条件フィルタや、条件をトリガにしたアクションの指定、異なるインスタンス（トレースバッファ）の利用、合成イベントの作成やヒストグラムの作成などは行なえません。

そこでBoot-time tracingの出番です。

Linux Boot-time Tracing

Boot-time tracingはLinux-5.6から導入された新しい起動時トレースの機能（インタフェース）で、bootconfigを利用することでコンパクトにftraceの機能を実装しています。

Boot-time tracingのオプション

Boot-time tracingのオプションは、"kernel"で始まる先程のカーネルコマンドラインのオプションをそのまま使うものと、"ftrace"で始まる新しいオプションで構成されています。Bootconfigを使えば一つのファイルにそのまま記述出来るので、カーネルコマンドラインのオプションでカバーされているものは最大限使います。
詳細なオプションについてはboottime-trace.rstを参照してもらうとして、ここではいくつか主要なものを上げます。

ちなみに表中、.instance.インスタンス名をスキップすると、トップレベル（デフォルト）のインスタンスに対して設定が行われます。

ftrace.[instance.インスタンス名.]tracing_on = 0|1: 指定したインスタンスのトレースのON/OFFを指定します。
ftrace.[instance.インスタンス名.]buffer_size = SIZE: 指定したインスタンスのトレースバッファのサイズを指定します。（例: "1MB", "512KB"など）
ftrace.[instance.インスタンス名.]events = イベントパターン１[, イベントパターン２...]: 指定したインスタンスでトレースするイベントのパターンを指定します。パターンは複数指定可能です。
ftrace.[instance.インスタンス名.]tracer = トレーサ: 指定したインスタンスで有効にするトレーサ(function, wakeup, blkなど)を指定します。注意：*function_graph*だけはデフォルトインスタンスでしか使えません。
ftrace.[instance.インスタンス名.]event.グループ名.イベント名.enable: グループ名とイベント名で指定したイベントを、指定したトレースインスタンスで有効にします。
ftrace.[instance.インスタンス名.]event.グループ名.イベント名.actions = アクション１[, アクション２...]: 指定したイベントが発生した時に実行するアクションを指定します。（例：traceon, snapshotなど）

Boot-time tracingの例

例えば、最初に上げた例は下記のように書けます。

kernel {
    tp_printk    # Show trace event in printk buffer
    ftrace_dump_on_oops # Dump ftrace log on oops
}

ftrace {
    options = "sym-addr"
    trace_clock = global
    buf_size = 1MB
    # Enable initcall, IRQ, and exception trace events
    events = initcall:*, irq:*, exceptions:*

    # Add kprobe events on set_memory_ro/rw to trace memory attributes
    event.kprobes {
        memory_ro {
            probes = "set_memory_ro $arg1 $arg2"
            enable
        }
        memory_rw {
            probes = "set_memory_rw $arg1 $arg2"
            enable
        }        
    }

これだと何を指定しているかが分かりやすいですね。
コメントも書き込めるため、更に読みやすくなりました。

他にも、例えば特定の関数の中だけで関数コールグラフを作りたい場合は次のように書けます。

ftrace {
        tracing_on = 0                  # Disable tracing by default
        tracer = "function_graph"       # Set a function call graph ready
        event {
                kprobes.pci_proc_init_begin {   # Add a kprobe event
                        probes = "pci_proc_init"
                        actions = "traceon"     # Enable tracing at call
                }
                kprobes.pci_proc_init_end {
                        probes = "pci_proc_init%return"
                        actions = "traceoff"    # Disable tracing at return
                }
        }
}

関数コールグラフを設定しながらデフォルトではOFFにしておき、指定した関数の入り口でONにし、出口で再びOFFにすることで、特定の関数の内部でだけコールグラフが生成されます。

更に別の事例として、initcall関数のヒストグラムを作ることを考えてみましょう。

# Make a histogram in the "initcall_hist" instance.
ftrace.instance.initcall_hist.event {
        synthetic.initcall_latency {    # Add a synthetic event
                fields = "unsigned long func", "u64 lat"
                # Make a histogram from function address and latency
                actions = "hist:keys=func.sym,lat:vals=lat:sort=lat"
        }
        initcall.initcall_start {
                # Save timestamp in ts0
                actions = "hist:keys=func:ts0=common_timestamp.usecs"
        }
        initcall.initcall_finish {
                # Make a latency from ts0 and timestamp, and call initcall_latency event.
                actions =
                "hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(initcall.initcall_start).initcall_latency(func,$lat)" 
        }
}

イベントごとにアクションを作り、そこでタイムスタンプの差分を計算して、新たに生成したsynthetic event（synthetic.initcall_latency）に送ります。このイベントで入力された値からヒストグラムを生成するという設定ファイルになります。
実のところ、これはヒストグラムを生成するアクションの指定が長過ぎるため、bootconfigでも少し読みにくくなってしまっています。将来的にはもう少しマシなsyntaxをサポートすることになりそうです。

サポートツール

Boot-time tracing機能を使えば、割と読みやすく書きやすい形でカーネルの起動時トレースを設定することが出来ることが分かったかと思います。
ただ、ftraceに慣れていない人が、いきなりこのような設定ファイルを書くのには抵抗があると思います。そういうニーズに対して、Linuxカーネルにはftrace2bconf.shとbconf2ftrace.shという強力な助っ人が（/tools/bootconfig/scripts/以下に）用意されています。

ftrace2bconf.sh

ftrace2bconf.shはその名の通り、ftrace(/sys/kernel/[debug/]tracing)で設定した情報を読み出し、bootconfigのファイルを生成してくれるツールです。
ユーザは試行錯誤してftraceの設定を行った後、このスクリプトを動かせば、その設定を反映するためのbootconfigファイルを得ることが出来ます。（ただし、いくつかのオプションはサポートしていません。例えばインスタンス単位でのイベント有効化パターンや関数トレースのフィルタリングパターンなどは、ftraceで設定した後パターンが分解されてしまうことからサポートしていません。）
このツールの実行にはrootユーザ権限が必要になります。またftrace全体のスキャンを繰り返すので多少時間がかかると思います。

$ sudo ./ftrace2bconf.sh 
ftrace.options =  sym-addr
ftrace.buffer_size = 1024KB
ftrace.events =  kprobes:vfs_read
ftrace.event.kprobes.vfs_read.probes += kernel_read arg1=$arg1 arg2=$arg2
ftrace.event.kprobes.vfs_read.filter = common_pid < 200

bconf2ftrace.sh

bconf2ftrae.shは、指定されたbootconfigファイルに書かれたとおり「ftraceに設定するシェルスクリプト」を生成します。直接設定しないのは、ユーザがレビュー出来るようにするためです。ただし--applyオプションを渡せば直接ftraceに設定を行います。ユーザはこれを使って、自分の書いたbootconfigファイルがエラーなく設定できるかどうかを確認することが出来ます。
例えば前記のヒストグラムを作成するbootconfigファイルを読み込ませると次のような出力が得られます。

$ ./bconf2ftrace.sh boottime-inithist.bconf 
echo 'initcall_latency unsigned long func; u64 lat; ' >> /sys/kernel/tracing/synthetic_events
echo 'hist:keys=func.sym,lat:vals=lat:sort=lat' >> /sys/kernel/tracing/events/synthetic/initcall_latency/trigger
echo 'hist:keys=func:ts0=common_timestamp.usecs' >> /sys/kernel/tracing/events/initcall/initcall_start/trigger
echo 'hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(initcall.initcall_start).initcall_latency(func,$lat)' >> /sys/kernel/tracing/events/initcall/initcall_finish/trigger

こうして出来上がったBootconfigファイルは、前回の記事で書いたように、bootconfigコマンドを使ってinitrd/initramfsイメージに追加し、カーネルコマンドラインに"bootconfig"オプションを付けることで利用できます。

$ sudo bootconfig -a boottime-inithist.bconf /boot/initrd.img

起動時トレースの実行タイミング

起動時トレースの初期化タイミングは、オプションの種類とカーネルバージョンによって少し違っています。

"kernel"で始まるオプション

"kernel"で始まるオプションはカーネルコマンドラインオプションを経由してftraceに渡されます。ftraceはメモリサブシステムが初期化された後の非常に早い段階でこれらのオプションを有効にします。

start_kernel()

        trap_init();
        mm_init();

        ftrace_init();

        /* trace_printk can be enabled here */
        early_trace_init();

ただし、kprobe_eventsオプションだけはtracefsが初期化された後の段階で有効になります¹。

"ftrace"で始まるオプション

"ftrace"で始まるオプションは、ftraceのトレーサの一つであるboot-time tracingで処理されます。この処理は他のインスタンスやトレースイベントなどの初期化が終わってからでないと行えないため、"kernel"で始まるオプションよりも後の段階で有効になります。
具体的には、Linux-5.9まではtracefsの初期化などが終わってからになるため、fs-initcallの後で実行されます。これにより、多くの組み込みドライバよりも早い段階で有効になりますが、ファイルシステムや一部のサブシステム、アーキテクチャ依存の初期化コードなどはトレースできません。

Linux-5.10からはカーネル内部の処理を見直し、tracefsの初期化と内部データの初期化を分離したため、core-initcallの最後に処理が行われるようになりました。これにより、postcore-initcall以降の多くのinitcallをトレースすることが出来るようになりました。

まとめ

この記事ではLinuxカーネルの起動時トレースについて以下のようなことを紹介しました。

カーネル起動時トレースには元々カーネルコマンドラインで指定するオプションがある
- カーネルコマンドラインに多くのオプションを渡すのは読みにくいし書きにくい
Bootconfigが入ったことでBoot-time tracingという新しい起動時トレース機能が使えるようになった
- 設定をファイルに書けるし、ツリー構造で書けて読みやすい
- カーネルコマンドラインオプションもまとめて書ける

この他にも小ネタとして、初期化処理を早くしたせいでarm64のkprobesが壊れたけど、最終的に実装方式を変えたら高速に動くようになった、みたいな話もありますが、それはまた別の話にしましょう。

これはバグっぽい・・・修正しないとだ。 ↩