BCC/BPFでシステムコールとかをいい感じにトレースする
この記事は KMC Advent Calendar 2017 の7日目の記事です。 昨日の記事は id:dnek さんの Unityで漢字パズルアプリを作ったよ(Android/iOS) でした。
シンプルだけどこだわって作っている感じがしてすごくよいですね。 (自分の作ったゲームはゲーム性へのこだわりが足りなくて微妙なのしかないので)
さて、今日はインフラ的なレイヤーの話をします。
自由にメトリクスを取りたい！！
パフォーマンスの改善や障害対応を行うために、「fsync のレイテンシの分布が知りたい」「dentry cache のヒット率が知りたい」「IOオペレーションのサイズの分布が知りたい」といった、OS の低レイヤーの情報を集めたくなることがあります。 top, vmstat, sar などのコマンドを使ってメトリクスを得るのが普通ですが、OS が予め用意したメトリクスしか見ることができず、必ずしも知りたい情報が得られるとは限りません。
例えば、dentry cache は /proc/sys/fs/dentry-state を見るとどれぐらい使われているかは分かるんですが、ヒット率が何％ぐらいかは全然わかりません。
こういうときに自分で自由に kernel 内の情報を収集できれば便利です。
そんなあなたに BCC
最近の Linux では kprobes と BPF を使ってカーネル内関数をトレースすることができます。 BCC は、kprobes と BPF を wrap して Python と C言語で便利にトレースプログラムを書けるようにしたものです。
BCC の雰囲気をつかむためには Examples 眺めてみるのがおすすめです。 「そんな情報取れるの！？」ってレベルで色々トレースしています。
例えば、biosnoop はブロックデバイスIOのレイテンシや、そのIOを発生させたプロセスのPIDなどを表示するプログラムです。
動かしてみるとこんな感じになります：
$ sudo /usr/share/bcc/tools/biosnoop [sudo] password for nojima: TIME(s) COMM PID DISK T SECTOR BYTES LAT(ms) 0.000000000 prometheus 33872 sda W 120713576 12288 0.48 0.002180000 jbd2/sda2-8 362 sda W 60254856 524288 1.65 0.002844000 jbd2/sda2-8 362 sda W 60255880 299008 2.31 0.041397000 jbd2/sda2-8 362 sda W 60256464 4096 0.29 1.804266000 ? 0 R -1 8 0.15 2.638785000 kworker/u480:1 55782 sda W 13633792 4096 2.34 2.638831000 kworker/u480:1 55782 sda W 1050648 8192 2.40 2.638857000 kworker/u480:1 55782 sda W 1059752 106496 2.42 2.638892000 kworker/u480:1 55782 sda W 22022984 16384 2.45 2.638914000 kworker/u480:1 55782 sda W 22022952 4096 2.47 2.638945000 kworker/u480:1 55782 sda W 22023120 12288 2.49 2.638990000 kworker/u480:1 55782 sda W 22023160 16384 2.54
prometheus が何か書き込んでいることが見て取れます。
また、ext4dist は ext4 へのオペレーションのレイテンシの分布を出力するプログラムです。 手元のVMで走らせてみると↓のようになりました。 この環境では fsync のレイテンシには２つの山があり、速い方だと 0.1ms～0.5ミリ秒程度、遅い方だと 30ms～130ms 程度だということがわかります。
$ sudo /usr/share/bcc/tools/ext4dist
Tracing ext4 operation latency... Hit Ctrl-C to end.
(中略)
operation = 'fsync'
usecs : count distribution
0 -> 1 : 1 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 0 | |
64 -> 127 : 0 | |
128 -> 255 : 177 |******* |
256 -> 511 : 98 |**** |
512 -> 1023 : 1 | |
1024 -> 2047 : 1 | |
2048 -> 4095 : 2 | |
4096 -> 8191 : 5 | |
8192 -> 16383 : 3 | |
16384 -> 32767 : 20 | |
32768 -> 65535 : 870 |************************************ |
65536 -> 131071 : 947 |****************************************|
131072 -> 262143 : 60 |** |
262144 -> 524287 : 5 | |
524288 -> 1048575 : 3 | |
他にも色々な例があるので、眺めてみると面白いと思います。
正直、example だけで十分な場合もかなり多いとは思いますが、BCC のメリットは何と言っても自分でカーネルの内部にハンドラをアタッチして自由に情報を取れることです。 この記事では、BCCで簡単なトレーシングプログラムの書き方を紹介します。
インストール方法
公式の INSTALL.md を参照してください。
Hello World in BCC
BPF で sync コマンドを打つたびに Hello, World! と表示するプログラムを書いてみます。
まず、以下の内容で hello.py を作成します。
from bcc import BPF BPF_PROGRAM = r''' #include <uapi/linux/ptrace.h> int kprobe__sys_sync(struct pt_regs *ctx) { bpf_trace_printk("Hello, World!\n"); return 0; } ''' bpf = BPF(text=BPF_PROGRAM) bpf.trace_print()
次に、hello.py を root ユーザーで実行し、別の端末で sync コマンドを打ちます。
すると sync するたびに Hello, World! が出力されることが確認できると思います。
こんな感じ:
$ sudo python hello.py
<...>-141094 [001] d... 5759646.157609: : Hello, World!
<...>-141099 [000] d... 5759647.607684: : Hello, World!
<...>-141104 [001] d... 5759648.419520: : Hello, World!
kprobe__関数名 という名前の関数を定義すると、その名前のカーネル関数にハンドラを仕掛けることができます。
上の例では kprobe__sys_sync という名前の関数を定義しているため、sys_sync が呼ばれる直前にこの関数が kprobe によって呼び出されます。
また、kretprobe__関数名 という名前の関数を定義すると、その関数から戻るタイミングにハンドラを仕掛けることができます。
次の例で使います。
また、Python 側から bpf.attach_kprobe(), bpf.attach_kretprobe() を読んでハンドラを設定する方法もあります。
詳しくはリファレンスを参照してください。
sync の時間を測る
次にもう少し実用的(?)な例を見てみましょう。次のプログラムは sys_sync の時間を計測し、print するものです。
from bcc import BPF BPF_PROGRAM = r''' #include <uapi/linux/ptrace.h> BPF_HASH(start_at, u32, u64); int kprobe__sys_sync(struct pt_regs *ctx) { u32 pid = (u32)bpf_get_current_pid_tgid(); u64 ts = bpf_ktime_get_ns(); start_at.update(&pid, &ts); return 0; } int kretprobe__sys_sync(struct pt_regs *ctx) { u32 pid = (u32)bpf_get_current_pid_tgid(); u64 *p = start_at.lookup(&pid); if (!p) return 0; u64 ts_start = *p; u64 ts_end = bpf_ktime_get_ns(); u64 delta = ts_end - ts_start; bpf_trace_printk("sync called: delta=%u\n", delta); start_at.delete(&pid); return 0; } ''' bpf = BPF(text=BPF_PROGRAM) bpf.trace_print()
実行するとこんな感じになります。(別の端末で sync を打って下さい)
$ sudo python sync.py
<...>-140474 [000] d... 5757530.462204: : sync called: delta=228816861
<...>-140479 [000] d... 5757531.890676: : sync called: delta=58180443
<...>-140484 [000] d... 5757532.781428: : sync called: delta=50627725
<...>-140489 [000] d... 5757534.292865: : sync called: delta=58540044
- 実行時間を計測するには、関数が呼ばれたタイミングと戻るタイミングでそれぞれタイムスタンプを取得し、その差を計算する必要があります。
そのため、
kprobe__sys_syncとkretprobe__sys_syncを定義して、両方のタイミングでフックが呼ばれるようにしています。 - 関数が呼ばれたタイミングで取得したタイムスタンプを戻るタイミングで呼ばれるハンドラに引き渡すためにハッシュ表を使っています。
- ハッシュ表は
BPF_HASHマクロを使って定義します。第一引数が変数名、第二引数が key の型、第三引数が value の型です。
- ハッシュ表は
bpf_get_current_pid_tgid()は PID と TGID を両方返す関数です。下位32ビットが PID で、上位32ビットが TGID です。- ややこしいんですが、ユーザーランドでよく PID と呼ばれている ID はここで言う TGID で、Thread ID と呼ばれているものがここでいう PID です。
bpf_ktime_get_ns()は現在のタイムスタンプを返します。
read のレイテンシの分布を出力する
以下のプログラムは２秒毎にファイルへの read のレイテンシの分布を出力します。
from bcc import BPF import time BPF_PROGRAM = r''' #include <uapi/linux/ptrace.h> BPF_HASH(start_at, u32, u64); BPF_HISTOGRAM(dist, u32); int kprobe__generic_file_read_iter(struct pt_regs *ctx) { u32 pid = (u32)bpf_get_current_pid_tgid(); u64 ts = bpf_ktime_get_ns(); start_at.update(&pid, &ts); return 0; } int kretprobe__generic_file_read_iter(struct pt_regs *ctx) { u32 pid = (u32)bpf_get_current_pid_tgid(); u64 *p = start_at.lookup(&pid); if (!p) return 0; u64 ts_start = *p; u64 ts_end = bpf_ktime_get_ns(); u64 delta = ts_end - ts_start; u32 key = bpf_log2l(delta); dist.increment(key); start_at.delete(&pid); return 0; } ''' bpf = BPF(text=BPF_PROGRAM) while True: time.sleep(2) table = bpf['dist'] table.print_log2_hist() table.clear()
実行するとこんな感じになります。
$ sudo python read.py
value : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 0 | |
64 -> 127 : 0 | |
128 -> 255 : 0 | |
256 -> 511 : 0 | |
512 -> 1023 : 6 |****************************************|
1024 -> 2047 : 1 |****** |
2048 -> 4095 : 6 |****************************************|
4096 -> 8191 : 1 |****** |
8192 -> 16383 : 2 |************* |
value : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 0 | |
64 -> 127 : 0 | |
128 -> 255 : 0 | |
256 -> 511 : 0 | |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 0 | |
4096 -> 8191 : 0 | |
8192 -> 16383 : 1 |****************************************|
BPF_HISTOGRAM(dist, u32); というのがキモで、分布を保存するためのテーブルを作成し、レイテンシをカウントしています。
Python側からは bpf['テーブル名'] でこのテーブルにアクセスできます。
print_log2_hist() は分布をいい感じに print してくれる便利メソッドです。
テーブルには Python のディクショナリみたいにアクセスすることもできます。 例えば、以下の例はテーブルの内容をタブ区切りで一行で出力しています。
# 分布をタブ区切りで出力する table = bpf['dist'] for k, v in sorted(table.items(), key=lambda x: x[0].value): sys.stdout.write("\t" + str(2 ** k.value) + ":" + str(v.value)) sys.stdout.write("\n")
まとめ
BCC で基本的なトレースを行うプログラムを紹介しました。 もっと知りたい人は公式の example を読んだり、reference guide を読みましょう。
さて、KMC Advent Calendar 2017 の次は aokabit さんです！！どんな記事か楽しみですね！！
