docs/tutorial_one_liners_japanese.md
12個の簡単なレッスンで Linux の bpftrace を学びましょう．各レッスンはワンライナーです．すぐに試すことができ，一連のワンライナーで bpftrace の要点が分かります．bpftrace の詳細はインストラクションマニュアルを参照して下さい．
bpftrace -l 'tracepoint:syscalls:sys_enter_*'
"bpftrace -l" は全てのプローブを表示します．後ろに検索語を付けることができます．
*及び?）が使用できます．# bpftrace -e 'BEGIN { printf("hello world\n"); }'
Attached 1 probe
hello world
^C
"hello world" を表示します．Ctrl-Cで実行を終了します．
BEGINは特別なプローブで，プログラムの開始時にイベントが発生します（awk の BEGIN と同様です）．変数の初期化やヘッダの出力に利用できます．# bpftrace -e 'tracepoint:syscalls:sys_enter_openat { printf("%s %s\n", comm, str(args.filename)); }'
Attached 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 プローブ（カーネルの静的トレーシング）です．これにより openat() システムコール呼び出し時にイベントが発生します．Tracepoint の API は安定性が保証されているため，kprobe（カーネルの動的トレーシング，レッスン6で紹介）よりも利用が推奨されます．なお，最近の Linux（カーネル2.26以上）では open 関数は常に openat システムコールを呼びます．comm はビルトイン変数の一つで，現在のプロセス名を保持します．同様のビルトイン変数に pid や tid があります．args は対象の tracepoint の全ての引数を含む構造体へのポインタです．この構造体は tracepoint の情報に基づいて bpftrace が自動で生成します．構造体のメンバの情報は bpftrace -vl tracepoint:syscalls:sys_enter_openat で調べることができます．args.filename は args 構造体を参照してメンバ変数 filename の値を取得します．str() はポインタを文字列に変換します．（訳注：bpftrace はポインタと文字列を別々のものとして扱います．printf("%s") の引数には文字列を与える必要があります． ）bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }'
Attached 1 probe
^C
@[bpftrace]: 6
@[systemd]: 24
@[snmp-pass]: 96
@[sshd]: 125
プロセスごとにシステムコール呼び出しの回数を計数します．集計結果は Ctrl-C でプログラムを終了した際に表示されます．
マップに格納された値は bpftrace が終了したとき（Ctrl-Cを押したときなど）に自動で表示されます．
# bpftrace -e 'tracepoint:syscalls:sys_exit_read /pid == 18644/ { @bytes = hist(args.ret); }'
Attached 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 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[128, 256) 1 |@
PID 18644 のプロセスによるカーネル関数 sys_read() の戻り値をヒストグラムにまとめます．
[128, 256) は値が128以上256未満であることを意味します．その横は発生回数及び，ASCII文字による発生回数のヒストグラムです．ヒストグラムはの分布の多峰性の調査に活用できます．# bpftrace -e 'kretprobe:vfs_read { @bytes = lhist(retval, 0, 2000, 200); }'
Attached 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() のバイト数を線形スケールのヒストグラムとして集計します．トレースにはカーネルの動的トレーシングを利用します．
kretprobe:vfs_read は kretprobe プローブ（関数の戻りに対するカーネル動的トレーシング）を vfs_read() カーネル関数に設定します．関数の実行開始時にイベントを発生させる kprobe プローブ（次のレッスンで紹介）もあります．これらは強力なプローブタイプで，数万の異なるカーネル関数をトレースすることができます．しかしこれらは「不安定」なプローブです．なぜなら，カーネル関数の名称，引数，戻り値，そして役割はカーネルバージョンごとに変わる可能性があるためです．kprobe/kretprobe が異なるカーネルで動作する保証はありません．また，生のカーネル関数をトレースすることになるため，プローブや引数，戻り値の意味を理解するためにはカーネルのソースコードを参照する必要があるでしょう．retval）は vfs_read() の戻り値で，これは読み出したバイト数です．# bpftrace -e 'kprobe:vfs_read { @start[tid] = nsecs; } kretprobe:vfs_read /@start[tid]/ { @ns[comm] = hist(nsecs - @start[tid]); delete(@start, tid); }'
Attached 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を利用しています．read は同時に複数実行される可能性があります．それぞれの開始時刻をどう保存すれば良いでしょうか？それぞれの read に対して一意の識別子が生成できれば，それをキーとして利用できます．あるカーネルスレッドは一度に一つのシステムコールしか実行できないため，スレッドIDを一意の識別子として利用できます．
nsecs: マシン起動からのナノ秒を意味します．これは高精度のタイムスタンプカウンターの値で，イベント時刻の測定に利用できます．
/@start[tid]/: このフィルタは開始時間が記録されているかをチェックします．このフィルタが無い場合，このプログラムはある read の開始後に実行され，その read の終了のイベントのみを捕捉する可能性があります．この場合，結果として 現在時刻 - 開始時間ではなく，現在時刻 - 0 を計算することになります．（訳注：存在しないキーに対するマップアクセスは0を返します）
delete(@start, tid): 変数を解放します．（訳注：delete をしたマップの値は，プログラム終了時に表示されません．）
# bpftrace -e 'tracepoint:sched:sched* { @[probe] = count(); } interval:s:5 { exit(); }'
Attached 25 probes
@[tracepoint:sched:sched_wakeup_new]: 1
@[tracepoint:sched:sched_process_fork]: 1
@[tracepoint:sched:sched_process_exec]: 1
@[tracepoint:sched:sched_process_exit]: 1
@[tracepoint:sched:sched_process_free]: 2
@[tracepoint:sched:sched_process_wait]: 7
@[tracepoint:sched:sched_wake_idle_without_ipi]: 53
@[tracepoint:sched:sched_stat_runtime]: 212
@[tracepoint:sched:sched_wakeup]: 253
@[tracepoint:sched:sched_waking]: 253
@[tracepoint:sched:sched_switch]: 510
5秒間プロセスレベルのイベントを計数し，サマリを出力します．
sched プローブカテゴリには，fork や exec，コンテキストスイッチなどの高位のスケジューラとプロセスに関するイベントがあります．tracepoint:sched:sched* はマッチした全てのプローブにアクションを紐付けます．probe を利用して，実際のプローブの名称をプログラム内から参照できます．）# bpftrace -e 'profile:hz:99 { @[kstack] = count(); }'
Attached 1 probe
^C
[...]
@[
filemap_map_pages+181
__handle_mm_fault+2905
handle_mm_fault+250
__do_page_fault+599
async_page_fault+69
]: 12
[...]
@[
cpuidle_enter_state+164
do_idle+390
cpu_startup_entry+111
start_secondary+423
secondary_startup_64+165
]: 22122
99ヘルツでカーネルスタックのプロファイリングをおこない，その出現頻度を出力します．
ustack があります．# bpftrace -e 'tracepoint:sched:sched_switch { @[kstack] = count(); }'
^C
[...]
@[
__schedule+697
__schedule+697
schedule+50
schedule_timeout+365
xfsaild+274
kthread+248
ret_from_fork+53
]: 73
@[
__schedule+697
__schedule+697
schedule_idle+40
do_idle+356
cpu_startup_entry+111
start_secondary+423
secondary_startup_64+165
]: 305
コンテキストスイッチ（off-CPU）イベントに繋がるスタックトレースを計数します．上記は出力の最後の二つのみを表示しています．
# bpftrace -e 'tracepoint:block:block_rq_issue { @ = hist(args.bytes); }'
Attached 1 probe
^C
@:
[0, 1] 1 |@@ |
[2, 4) 0 | |
[4, 8) 0 | |
[8, 16) 0 | |
[16, 32) 0 | |
[32, 64) 0 | |
[64, 128) 0 | |
[128, 256) 0 | |
[256, 512) 0 | |
[512, 1K) 0 | |
[1K, 2K) 0 | |
[2K, 4K) 0 | |
[4K, 8K) 24 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8K, 16K) 2 |@@@@ |
[16K, 32K) 6 |@@@@@@@@@@@@@ |
[32K, 64K) 5 |@@@@@@@@@@ |
[64K, 128K) 0 | |
[128K, 256K) 1 |@@ |
ブロックI/O要求をバイト単位でヒストグラムとして表示します．
このプローブのコンテキストは重要です．このイベントはデバイスに対して I/O が発行されたときに発生します．これはよくプロセスコンテキストで発生し，その場合ビルトイン変数，例えば comm はそのときのプロセス名を意味しますが，このイベントはカーネルコンテキスト（例えば readahead）でも発生します．この場合 pid や comm は予期しないものになるでしょう．
# cat path.bt
#ifndef BPFTRACE_HAVE_BTF
#include <linux/path.h>
#include <linux/dcache.h>
#endif
kprobe:vfs_open
{
printf("open path: %s\n", str(((struct path *)arg0)->dentry->d_name.name));
}
# bpftrace path.bt
Attached 1 probe
open path: dev
open path: if_inet6
open path: retrans_time_ms
[...]
カーネルの動的トレーシングで vfs_open() をトレーシングします．この関数は (struct path *) を第一引数に取ります．
arg0 はビルトイン変数で，プローブの最初の引数を意味します．これはプローブタイプごとに意味が異なり，kprobe の場合は関数の最初の引数を意味します．他の引数には arg1, ..., argN でアクセスできます．((struct path *)arg0)->dentry->d_name.name: arg0 を struct path * にキャストしてから dentry や後続のメンバ変数を参照します．カーネル構造体のサポートは bcc と同様にカーネルヘッダを利用します．したがって多くの構造体が利用可能ですが，全てではありません．場合によっては手動で構造体を定義する必要があります．例えば dcsnoop tool では nameidata 構造体の一部を手動で定義しています．これはこの構造体がヘッダ内で定義されていないためです．LinuxカーネルのBTFデータがある場合，全ての構造体が利用可能です．
ここまでで bpftrace の多くを理解し，強力なワンライナーを作成・利用することができます．bpftrace のその他の機能については インストラクションマニュアル を参照して下さい．