このチュートリアルは12の短いレッスンで bpftrace を学びます。それぞれのレッスンはワンライナーです。
英語版はこちら: https://github.com/iovisor/bpftrace/blob/master/docs/tutorial_one_liners.md
現時点ではラフな翻訳となります。
bpftrace -l 'tracepoint:syscalls:sys_enter_*'
"bpftrace -l" はprobeを全部リストします。
- probeとは、イベントデータをキャプチャするために設定されたポイントです。
- ワイルドカードやグロブが使えます (
*and?) grep(1)などでフィルターしてもいいですね
# bpftrace -e 'BEGIN { printf("hello world\n"); }'
Attaching 1 probe...
hello world
^C
hello world をプリントします。
BEGINは awk のBEGINのようなスペシャルなprobeです- action は
{}で probe と結びつきます
# bpftrace -e 'tracepoint:syscalls:sys_enter_openat { printf("%s %s\n", comm, str(args->filename)); }'
Attaching 1 probe...
snmp-pass /proc/cpuinfo
snmp-pass /proc/stat
snmpd /proc/net/dev
snmpd /proc/net/if_inet6
^C
tracepoint:syscalls:sys_enter_openatという tracepoint 型のprobeを使います。 ｀openat()システムコールの開始をトレースします。Tracepointはバージョンにより変わりにくいstableなAPIがあるので、kprobe(lesson 6でやります)よりも適切な場合が多いです。ちなみに、モダンなLinux(glibc >= 2.26)はopen()関数は必ずopenat` システムコールを呼びます。commはビルトインの変数で、カレントプロセス名を格納しますargsはtracepointの引数を格納する構造体のポインタですbpftrace -vl tracepoint:syscalls:sys_enter_openatでメンバーがわかりますargs->filenameでfilenameがわかりますstr()で char* の引数を可読な文字列にします
bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }'
Attaching 1 probe...
^C
@[bpftrace]: 6
@[systemd]: 24
@[snmp-pass]: 96
@[sshd]: 125
プロセスごとのsyscall呼び出しを集計します。
@は map と呼ばれる特別な変数型です。そこにデータを格納、集計できます。@numのように名前もつけられます[]は連想配列のようにキーを指定できますcount()は map function です。count()は、呼び出された延回数をmapに格納します。commごとに保存しているので、プロセスごとの集計結果となります。
Mapはコマンド終了時に自動でプリントされます（Ctrl-Cなどで止められます）
# bpftrace -e 'tracepoint:syscalls:sys_exit_read /pid == 18644/ { @bytes = hist(args->ret); }'
Attaching 1 probe...
^C
@bytes:
[0, 1] 12 |@@@@@@@@@@@@@@@@@@@@ |
[2, 4) 18 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[4, 8) 0 | |
[8, 16) 0 | |
[16, 32) 0 | |
[32, 64) 30 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[64, 128) 19 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
sys_read() の返り値を PID=18644 のプロセスについてサマライズしてくれます。
/.../: これはフィルター（predicateとも）です。これがついているとき、アクションは、フィルターの中の表現がtrueの時だけ実行されます。このケースではprocess IDが18644の時だけ実行されます。"&&", "||" のようなオペレータもサポートします。ret: これは関数の返り値です。sys_read()の場合 -1 はエラー、その他はreadに成功したバイト数です。@: これは先ほどのmapですが、[]なしで使います。bytesという名前はアウトプットでも使われますhist(): これは引数に渡した値を2のべき乗でヒストグラムに集計してくれます。表記の[128, 256)は例えば値が128 <= value < 256に収まった数という意味です。このヒストグラムから、2つ山がある分布であることが読み取れます。- その他に、
lhist() (linear hist), count(), sum(), avg(), min(), and max()などの集計関数があります。
# bpftrace -e 'kretprobe:vfs_read { @bytes = lhist(retval, 0, 2000, 200); }'
Attaching 1 probe...
^C
@bytes:
(...,0] 0 | |
[0, 200) 66 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[200, 400) 2 |@ |
[400, 600) 3 |@@ |
[600, 800) 0 | |
[800, 1000) 5 |@@@ |
[1000, 1200) 0 | |
[1200, 1400) 0 | |
[1400, 1600) 0 | |
[1600, 1800) 0 | |
[1800, 2000) 0 | |
[2000,...) 39 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
read() のバイト数を線形ヒストグラムで集計します。これはkernel dynamic tracingを使っています。
kretprobe:vfs_readというprobeを使っています。これはkretprobeというprobe typeで、カーネルのfunctionvfs_read()のreturnをトレースします。同様にkprobeというprobe typeもあります（次のレッスンで）。functionの開始（enter）をトレースします。これらは強力なprobe typeで、何万ものkernel functionsをトレース可能にします。しかし、これらは "unstable" なprobe typeです。これらkprobe/kretprobeはカーネル関数をトレースするので、異なるバージョンのカーネルで同じようにトレースできることは保証されません。例えば関数名、引数、返り値、役割などが変わり得ます。加えて、カーネル関数のトレースなので、真の理解にはカーネルのソースコードを読む必要があるでしょう。lhist(): これは線形ヒストグラムで、value, min, max, stepが引数です。vfs_read()のretvalは読み込んだバイト数です。
# bpftrace -e 'kprobe:vfs_read { @start[tid] = nsecs; } kretprobe:vfs_read /@start[tid]/ { @ns[comm] = hist(nsecs - @start[tid]); delete(@start[tid]); }'
Attaching 2 probes...
[...]
@ns[snmp-pass]:
[0, 1] 0 | |
[2, 4) 0 | |
[4, 8) 0 | |
[8, 16) 0 | |
[16, 32) 0 | |
[32, 64) 0 | |
[64, 128) 0 | |
[128, 256) 0 | |
[256, 512) 27 |@@@@@@@@@ |
[512, 1k) 125 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[1k, 2k) 22 |@@@@@@@ |
[2k, 4k) 1 | |
[4k, 8k) 10 |@@@ |
[8k, 16k) 1 | |
[16k, 32k) 3 |@ |
[32k, 64k) 144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[64k, 128k) 7 |@@ |
[128k, 256k) 28 |@@@@@@@@@@ |
[256k, 512k) 2 | |
[512k, 1M) 3 |@ |
[1M, 2M) 1 | |
read() にかかった時間を計測します。単位はナノ秒です。プロセス名ごとのヒストグラムです。
@start[tid]: ここで、スレッドIDをキーとして使います。OSでは各所でreadが呼ばれると思いますが、それぞれのスタート時のタイムスタンプを保存したいです。どうやって？ それぞれのreadの開始でユニークなキーを生成してそれをキーに保存すればいいでしょう。しかし、実はカーネルスレッドは一回に一つのシステムコールしか呼べないので、我々は スレッドIDを そのユニークなキーに使うことができます。一つのスレッドが同時に二回以上readを呼べないですからね。nsecs: これは起動時点からの経過時間をナノ秒で取得します。非常に解像度の高い時間カウンタなので時間計測などに使えます。/@start[tid]/: このフィルターで、start timeがレコードされているか確認しています。このフィルターがないと開始のタイミングが取得できなくて終わりだけが取得できるreadの呼び出しが発生してしまいます（bpftraceを呼ぶ直線に開始したreadなど）。そういうものはnow - startではなくnow - zeroが計測されて異常値になります。delete(@start[tid]): でstartの値をリリースします。同じtidでreadは何度も呼ばれるからです。
@udzura
ちょっと前に自分も訳して放置してたので，ご参考まで... （公開しておけばよかったですね，すみません）
https://github.com/mmisono/bpftrace/blob/japanese_oneliner/docs/tutorial_one_liners_japanese.md