色々な理由 でカーネルのイベントなどをトレースする方法を整理する必要が出て来たので。地道にやっていくシリーズ。最近シリーズものが続いてないのでまた中断される可能性が...。
今回は、カーネルのイベントソースとして tracepoint, kprobe, uprobe というものがあるが、それぞれを使って、違いを確認してみる。理解が間違っていたら教えてください。
環境は基本的に、ご家庭の Ubuntu Bionic でシュッと試しているので、最新のカーネルというわけではない。
$ uname -a Linux ubuntu-bionic 4.15.0-55-generic #60-Ubuntu SMP Tue Jul 2 18:22:20 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
tracepoint
Linuxカーネルには、内部で起こる様々なイベントをトレースするためのフックポイントが組み込まれている。それらを tracepoint と呼ぶ（Ruby の TracePoint クラスなど、同じ名前の機能が他の環境にもあるが、今回はLinuxカーネルのtracepointの話題）。
/sys/kernel/debug/tracing/events を見るとどういうイベントが組み込まれているか一覧できる。
# ls -l /sys/kernel/debug/tracing/events total 0 drwxr-xr-x 6 root root 0 Sep 2 06:31 alarmtimer drwxr-xr-x 20 root root 0 Sep 2 06:31 block drwxr-xr-x 14 root root 0 Sep 2 06:31 bpf drwxr-xr-x 6 root root 0 Sep 2 06:31 bridge drwxr-xr-x 60 root root 0 Sep 2 06:32 btrfs drwxr-xr-x 11 root root 0 Sep 2 06:31 cgroup drwxr-xr-x 16 root root 0 Sep 2 06:31 clk drwxr-xr-x 4 root root 0 Sep 2 06:31 cma drwxr-xr-x 16 root root 0 Sep 2 06:31 compaction ... # ls -l /sys/kernel/debug/tracing/events/random total 0 drwxr-xr-x 2 root root 0 Sep 2 06:31 add_device_randomness drwxr-xr-x 2 root root 0 Sep 2 06:31 add_disk_randomness drwxr-xr-x 2 root root 0 Sep 2 06:31 add_input_randomness drwxr-xr-x 2 root root 0 Sep 2 06:31 credit_entropy_bits drwxr-xr-x 2 root root 0 Sep 2 06:31 debit_entropy -rw-r--r-- 1 root root 0 Sep 2 06:31 enable drwxr-xr-x 2 root root 0 Sep 2 06:31 extract_entropy drwxr-xr-x 2 root root 0 Sep 2 06:31 extract_entropy_user -rw-r--r-- 1 root root 0 Sep 2 06:31 filter drwxr-xr-x 2 root root 0 Sep 2 06:31 get_random_bytes drwxr-xr-x 2 root root 0 Sep 2 06:31 get_random_bytes_arch drwxr-xr-x 2 root root 0 Sep 2 06:31 mix_pool_bytes drwxr-xr-x 2 root root 0 Sep 2 06:31 mix_pool_bytes_nolock drwxr-xr-x 2 root root 0 Sep 2 06:31 push_to_pool drwxr-xr-x 2 root root 0 Sep 2 06:31 random_read drwxr-xr-x 2 root root 0 Sep 2 06:31 urandom_read drwxr-xr-x 2 root root 0 Sep 2 06:31 xfer_secondary_pool
もしくは perf list '*' などのコマンドでも取れる。
試しに random:urandom_read というイベントを有効にする。これは /dev/urandom への読み取りの発生とそのビット数をトレースする。
# echo 1 > /sys/kernel/debug/tracing/events/random/urandom_read/enable
/sys/kernel/debug/tracing/trace を確認するとイベントが記録されている。Rubyの SecureRandom の乱数シード生成メソッドを直接呼び出すと、 /dev/urandom をシードにするので読み取りが発生し、記録される。
# ruby -rsecurerandom -e "SecureRandom.send :gen_random, 8 and p :OK"
:OK
# cat /sys/kernel/debug/tracing/trace | grep ruby
ruby-2692 [003] .... 2168.547642: urandom_read: got_bits 128 nonblocking_pool_entropy_left 0 input_entropy_left 3623
ruby-2692 [003] .... 2168.549446: urandom_read: got_bits 128 nonblocking_pool_entropy_left 0 input_entropy_left 3623
ruby-2692 [003] .... 2168.595669: urandom_read: got_bits 8 nonblocking_pool_entropy_left 0 input_entropy_left 3623
ruby-2692 [003] .... 2168.595674: urandom_read: got_bits 64 nonblocking_pool_entropy_left 0 input_entropy_left 3623
...
kprobe
tracepointは基本的にあらかじめカーネル開発者が用意したフックポイントしかトレースできない。
自分で、特定のカーネル関数の呼び出しをトレースしたい場合 kprobe を使う。
たとえば connect システムコールの内部で呼ばれる sys_connect を追いかける。 sys_connect がちゃんとカーネルのシンボルかどうかは、 /proc/kallsyms というファイルを確認すればわかる。
# cat /proc/kallsyms | grep -i sys_connect ffffffff882342a0 T SyS_connect ffffffff882342a0 T sys_connect
${p|r}:${イベント名} ${カーネルシンボル名} [${オプション}] というフォーマットで /sys/kernel/debug/tracing/kprobe_events というファイルに書き込んで登録する。 p: で始めるとその関数の呼び出し、 r: で始めるとその関数のリターンをトレースできる。
# echo 'p:myprobe1 sys_connect' >> /sys/kernel/debug/tracing/kprobe_events # echo 'r:myretprobe1 sys_connect $retval' >> /sys/kernel/debug/tracing/kprobe_events # cat /sys/kernel/debug/tracing/kprobe_events p:kprobes/myprobe1 sys_connect r:kprobes/myretprobe1 sys_connect arg1=$retval
有効にする方法はtracepointのイベントと同様。
# echo 1 > /sys/kernel/debug/tracing/events/kprobes/myprobe1/enable # echo 1 > /sys/kernel/debug/tracing/events/kprobes/myretprobe1/enable
ping を打ってみるとたしかにその際に実行される connect が記録される。
# ping 8.8.8.8
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
64 bytes from 8.8.8.8: icmp_seq=1 ttl=63 time=58.6 ms
64 bytes from 8.8.8.8: icmp_seq=2 ttl=63 time=72.8 ms
64 bytes from 8.8.8.8: icmp_seq=3 ttl=63 time=116 ms
^C
$ sudo cat /sys/kernel/debug/tracing/trace | grep ping
ping-20063 [003] .... 4200.600447: myprobe1: (SyS_connect+0x0/0x10)
ping-20063 [003] d... 4200.600457: myretprobe1: (do_syscall_64+0x73/0x130 <- SyS_connect) arg1=0x0
なお、登録した kprobe は以下のように削除可能。
# echo '-:myretprobe1' >> /sys/kernel/debug/tracing/kprobe_events
uprobe
ユーザ空間のプログラムの挙動を、カーネル側で追いかけることも可能。これを uprobe と呼ぶ。 uprobe は、バイナリ単位（正確にはその実行ファイルのinode単位とのこと）でイベントを登録する必要がある。
まず、ユーザ空間のプログラムのどこに関数があるか確認する必要がある。 /home/vagrant/.rbenv/versions/2.4.1/bin/ruby というところに、 strip されていないRubyバイナリがある。 objdump -d で関数のバイナリ上のアドレスが確認できる（どういう関数があるかざっと見てみたい、という場合 objdump -T のほうがいいかも）。
# objdump -d /home/vagrant/.rbenv/versions/2.4.1/bin/ruby | grep '<rb_f_sprintf>:' 0000000000124b70 <rb_f_sprintf>:
で、このアドレスを直接 /sys/kernel/debug/tracing/uprobe_events というファイルに書き込む必要がある。 ${pまたはr}:${イベント名} ${バイナリのフルパス}:${16進数(0x...)のアドレス} [${オプション}] というフォーマットで書き込んで登録する。登録後は kprobe のイベントと同じように有効にできる。
# echo 'p:ruby_f_sprintf /home/vagrant/.rbenv/versions/2.4.1/bin/ruby:0x124b70' >> /sys/kernel/debug/tracing/uprobe_events # cat /sys/kernel/debug/tracing/uprobe_events p:uprobes/ruby_f_sprintf /home/vagrant/.rbenv/versions/2.4.1/bin/ruby:0x0000000000124b70 # echo 1 >/sys/kernel/debug/tracing/events/uprobes/ruby_f_sprintf/enable
あとはその Ruby のバイナリを使って、スクリプトで Kernel#sprintf を呼び出すと、その呼び出しがトレースされる。
# /home/vagrant/.rbenv/versions/2.4.1/bin/ruby -e 'p sprintf "Hello, %s", "world"'
"Hello, world"
# sudo cat /sys/kernel/debug/tracing/trace | grep sprintf
ruby-30168 [000] d... 7379.532185: ruby_f_sprintf: (0x56400557ab70)
今回は、 tracepoint, kprobe, uprobe のそれぞれについて、debugファイルシステムを経由した利用方法を確認した。
次回の内容は未定。多分 bpftrace か BCC を素振りしたりする気がする。
参考サイト
より詳細な日本語記事があるので、そっちもぜひ見て欲しい。
uprobe 周りで、 USDT という機能があるが、その話はこちらに。
