ftraceとperf probeの環境構築

Linuxカーネル内の関数のコールグラフを表示したり、ソースコードの行指定をして変数の値を出力したりするといったようなトレーシングをするために、トレーサーを利用する。 Linuxカーネルのトレーサーには、ftraceやperf、eBPFなどがある。Choosing a Linux Tracer (2015)

今回は、ftrace(trace-cmd)とperf probeを動作させるために環境構築したときのログをメモしておく。 ここでは、さくらのクラウドUbuntu Server 18.04.2 LTS 64bitのISOイメージを基に構築したインスタンス上で、ftraceとperfの環境を構築する。

ftrace(trace-cmd)

まず、はじめに、必要なパッケージをインストールする。

# apt install trace-cmd

次に、trace-cmd listで利用可能なトレーサーにfunctionfunction_graphがあることを確認する。

# trace-cmd list -t
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

trace-cmdの動作確認のために、関数コールグラフの出力を ss コマンドを利用して確認する。

# trace-cmd record -p function_graph -l tcp_diag_dump -l tcp_diag_get_info ss -tanp 1>/dev/null
  plugin 'function_graph'
CPU0 data recorded at offset=0x448000
    4096 bytes in size
# trace-cmd report
cpus=1
              ss-12700 [000] 2219157.460551: funcgraph_entry:                   |  tcp_diag_dump() {
              ss-12700 [000] 2219157.460563: funcgraph_entry:        0.105 us   |    tcp_diag_get_info();
              ss-12700 [000] 2219157.460565: funcgraph_entry:        0.061 us   |    tcp_diag_get_info();
              ss-12700 [000] 2219157.460567: funcgraph_entry:        0.056 us   |    tcp_diag_get_info();
              ss-12700 [000] 2219157.460601: funcgraph_entry:        0.451 us   |    tcp_diag_get_info();
              ss-12700 [000] 2219157.460611: funcgraph_exit:       + 51.468 us  |  }
              ss-12700 [000] 2219157.460618: funcgraph_entry:        0.211 us   |  tcp_diag_dump();
              ss-12700 [000] 2219157.460720: funcgraph_entry:                   |  tcp_diag_dump() {
              ss-12700 [000] 2219157.460722: funcgraph_entry:        0.102 us   |    tcp_diag_get_info();
              ss-12700 [000] 2219157.460771: funcgraph_exit:       + 50.640 us  |  }
              ss-12700 [000] 2219157.460774: funcgraph_entry:        0.265 us   |  tcp_diag_dump();

perf probe

次に、perf probeを動作させる。まずはパッケージのインストールから。

# apt install linux-tools-$(uname -r)

ここでは、sock_alloc_fileという関数の35行目の時点でのname.name変数の値を表示させることを目指す。 普通に実行すると、次のようなカーネルイメージを読み込めないエラーがでる。

# perf probe --add "sock_alloc_file:35 name.name:string"
Failed to find the path for kernel: Invalid ELF file
  Error: Failed to show lines.

straceを挟んで実行すると、カーネルの実行バイナリをvmlinuxを読み込もうとしていることわかったが、/boot以下にはvmlinuzファイルしかない。 perfは圧縮されたカーネルイメージであるvmlinuzからはシンボルを読み取れない*1ため、vmlinuxファイルを用意する。

デバッグシンボル付きのカーネルイメージを取得するため、Debug Symbol Packages - Ubuntu Wiki にしたがい、デバッグシンボルパッケージ用のaptリポジトリを追加する。

次に、次のコマンドでカーネルイメージパッケージをインストールすると、/usr/lib/debug/boot/vmlinux-4.15.0-45-genericにvmlinuxファイルがインストールされる。

# apt install linux-image-$(uname -r)-dbgsym

その後、再度perf probeを実行すると、今度は次のようなソースコードを発見できていないエラーがでる。

# sudo perf probe --add "sock_alloc_file:35 name.name:string"
Specified source line is not found.
  Error: Failed to show lines.

Linuxカーネルソースコードを落としてくる必要がある。 ここでは、パッケージからソースコードをインストールする。

# apt install linux-source-4.15.0
# mkdir -p /usr/src/linux-4.15.0
# tar xjf /usr/src/linux-source-4.15.0/linux-source-4.15.0.tar.bz2 -C /usr/src/linux-4.15.0/ --strip 1

その後、perf probe -sオプションでソースコードディレクトリを指定すると、イベントの追加に成功する。

# perf probe  -s /usr/src/linux-4.15.0/ --add "sock_alloc_file:35 name.name:string"
Added new event:
  probe:sock_alloc_file (on sock_alloc_file:35 with name=name.name:string)

You can now use it in all perf tools, such as:

        perf record -e probe:sock_alloc_file -aR sleep 1

sock_alloc_file関数から、socket作成処理をキャプチャするために、次のコマンドでnginxプロセスを指定して記録処理を待ち受けておき、別ホストからabコマンドでHTTPリクエストを投げる。 perfはイベントをサンプリングして記録するため、abコマンドなどで複数回投げてやるとよい。*2

# perf record -e probe:sock_alloc_file -aR -p function_graph --pid 21326
Warning:
PID/TID switch overriding SYSTEM^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.021 MB perf.data (104 samples) ]

最後に、次のように、perf reportで結果を出力する。name変数の値として、'TCP'と表示されていることがわかる。

# perf report | cat
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 104  of event 'probe:sock_alloc_file'
# Event count (approx.): 104
#
# Overhead  Trace output
# ........  .............................
#
   100.00%  (ffffffff8182ed93) name="TCP"


#
# (Cannot load tips.txt file, please install perf!)
#

ここまで動かすのに意外とハマってしまった。

参考

*1:https://perf.wiki.kernel.org/index.php/Tutorial#Options_controlling_kernel_reporting

*2:printデバッグのようなことをするだけならSystemTapのほうがいいかもしれない