ローファイ日記

出てくるコード片、ぼくが書いたものは断りがない場合 MIT License としています http://udzura.mit-license.org/

自分のためのカーネルトレーシング、その1

色々な理由カーネルのイベントなどをトレースする方法を整理する必要が出て来たので。地道にやっていくシリーズ。最近シリーズものが続いてないのでまた中断される可能性が...。

今回は、カーネルのイベントソースとして 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 を確認するとイベントが記録されている。RubySecureRandom の乱数シード生成メソッドを直接呼び出すと、 /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

www.kernel.org

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

www.kernel.org

ユーザ空間のプログラムの挙動を、カーネル側で追いかけることも可能。これを 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 を素振りしたりする気がする。

参考サイト

より詳細な日本語記事があるので、そっちもぜひ見て欲しい。

mmi.hatenablog.com

uprobe 周りで、 USDT という機能があるが、その話はこちらに。

blog.ssrf.in

BCCの hello_world.py 相当がCRubyでも動いた

udzura.hatenablog.jp

mrubyでやってる話は前したけど、CRubyでも動いた。

github.com

BCC が動作し、インストール済みのLinuxシステムで以下のコマンドでもうインストールできます。

$ gem install rbbcc --pre

デモのようにシステム全体の clone(2) をトレースして何かを出力する( Python版の hello_world.py 相当)例。こういうコードが動く。

require 'rbbcc' 

code = <<CLANG
int kprobe__sys_clone(void *ctx)
{
  bpf_trace_printk("Hello, World!\\n");
  return 0;
}
CLANG
RbBCC::BCC.new(text: code).trace_print
続きを読む

libbccをmrubyにポートしている話

たまには「〜話」メソッドでブログを書く。あと6月は二回ブログを書けたのでめでたい。

さて、タイトルのようなことをしています。

前提としてeBPFという、カーネル内で動く特定の目的のプログラムを比較的高速・安全に書くための技術があるのですが、そのプログラムはバイトコードベースなので、eBPFを扱うプログラムをもう少し人間的な形式で書きたくなります。せめてC言語とか。そのためのコンパイラがlibbccです。

github.com

大きくはkprobe、uprobe、kernel tracepointといったカーネルイベントのトレースをしたり、XDPというネットワーク周りのトレースをしたり挙動を変更する処理を書くことができたりします。

以下の記事が詳しいと思います。

mmi.hatenablog.com

qiita.com

知人の id:mrtc0 さんという人がeBPF関係の中でもUSDTという、プログラムの任意の箇所に任意のプローブ(もともと探針、みたいな意味ですね)を埋め込む(それも元のプログラムへ影響を最小限にして埋め込める)機能があるのですが、その検証をしていたりします。

blog.ssrf.in

今回、mrubyでその範囲の機能だけでもポートできた気がするので紹介します。

続きを読む

完全なワンバイナリーmruby

タイトルは 575 です。相変わらず気ぜわしいので小ネタを投げます。

mruby は「ワンバイナリ」を作れるRubyとして知られています。ですが、実際にはlibcなどをダイナミックリンクします。それはそうでしょうという感じですが、例えばLinuxでmruby-bin-mrubyでmrubyバイナリを作ると、こんな感じで確認できます。

$ ldd ./bin/mruby
        linux-vdso.so.1 (0x00007ffca74f3000)
        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f9bd477e000)
        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f9bd438d000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f9bd4de4000)

なので、これらのダイナミックリンクを、スタティックリンクに変えれば「真の」ワンバイナリと言えるわけです。ぼくも「not a dynamic executable」と言われたい(?)。

続きを読む

See you, RubyKaigi

Hey Rubyists, did you enjoy RubyKaigi 2019 in Fukuoka? I am @udzura.

RubyKaigiがまずは終わった(残件はある)といいつつ本業も慌ただしく、すぐに 次のプロジェクト に入ってしまった感じでなかなかふりかえりモードになれない(なんならまだふりかえっていないのであった)。いったん今の感想、エモなどをダンプしておこうという記事。

はじめに

どうしてもしなければならない宣伝(©️ id:uzulla さん)があるんですが、Fukuoka.rb で久しぶりにLT大会をするので、RubyKaigiで高まった人、そうでもない人、どなたでも是非 ご登壇ください 。RubyKaigi Teamより、 参加賞 もご提供いただいております。

fukuokarb.connpass.com

もちろん普通のご参加も歓迎です!飛び入りも!

Speaker として

さて。

今回、様々な立場としてRubyKaigiに参加した。もらったパーカもオーガナイザーの青とスピーカーの白の2色を制覇した(一般参加者のオレンジは辞退した)。

まずスピーカーとしては、3回目となるおしゃべりをした。今回はRailsを早く起動する話と見せかけた、実はコンテナの話...。

speakerdeck.com

去年は正直反省点の多いおしゃべりだったけど、今回は書いたコードとやったことの話をベースにできたのは個人的には、良かった。

トークの作り方も新手法を導入していた:

  • 最初に英語でスクリプトを書く
  • それを邦訳する
  • 日本語にしたら明らかに言葉が足りないところがわかるので英語を足す
  • 一通り喋る
  • 時間などもみて言葉を足す
  • 繰り返し
  • 最後にスクリプトをスライドに起こす

この手順を実施したらそれなりに文章も整理され、かつ英語を作るコストを最小限に抑えられたので、今後も(全部日本語の場合含め)採用していきたいやり方であるところ。ただ、今年は結局ネイティブチェックができなかったなあ...。

Grenadine、手すき(いつ?)にドキュメント整理してパッケージ作っときますので試してみてください。今まであまりしたことがないような体験ができます。

github.com

昔日本語で書いた記事です。

udzura.hatenablog.jp

Local Organizer として

今年は実は発表しながらオーガナイザー業もしていた。と言っても、RubyKaigiはトークが一番大事ということで id:jinroq さんをはじめFukuoka.rbメンバーにどんどん投げて行く形にはなった(むしろ、もっと自分から剥がせないといけなかったね...)。

いろいろなことがあり様々で、裏方話でもあるので、詳細はオーガナイザー志望者などにどん蔵、檳榔の夜などのいい感じの店で話す形を取ろうと思う :)

ただ、良かったこととしてはなにより、説明するまでもないFukuoka.rbを代表するRubyist、CRubyのコミットを毎日読んでいることでおなじみ id:nagachika さんをキーノートに迎えることができたことだと思う。世界のRubyistに、nagachikaさんの凄さを伝えられたので、Local Organizerとして一番重要なことはきっとできたのではないか。と。

www.youtube.com

そのほか一つだけ挙げるなら、やはりあのカオス、川端商店街での公式懇親会の話をさせてほしい。

「商店街で懇親会ってどうやるの?」という内容をすでに10名ぐらいに聞かれていてFAQなので、手順をここに残しておくが、商店街のような普通の道路で懇親会をするにはまず、その地域が「国家戦略特別区域」というものに指定されていないといけない。いわゆる川端商店街こと上川端322号線・326号線・327号線もその区域の一つ。

申請を出し、MICE(いわゆる国際会議)を盛り上げるという目的に合致していると当局が判断したら許可が下り、懇親会ができる。MICEなので、規模(700人程度以上とか)、海外のお客様の比率などが判断の材料になるとのこと。RubyKaigiはただの国際会議なのでぴったりではあった。

実際の様子は会場デザイナーさんのFacebookの記事や当日のツイートなどをご覧いただきたい。

www.facebook.com

参加された皆様からも「真っ当な人間には思いつけない」「マジでカオス。クレイジーという言葉がぴったり」などの大好評をいただいていた。

個人的にも、このカオスは福岡でコミュニティをやっていてたまに生じるカオスにとても性質が近く、参加者の皆さんに「えも言われぬ、あの感じin福岡」を少しでも体験していただけたと思うので、良かった。

Attendee として

正直当日は色々気を回すことがあるのと、つい人間の皆さんと会話するのを優先してしまい、なかなか身を入れてトークを聞くことができなかった気もしている。逆に空いた時間に細かくハックスペースに行ってもぞもぞ何かを書いていた記憶もあるけど... 何書いてたっけ... (お茶、最高でしたね。豊橋出身ですが静岡茶より八女茶が好きです)

Pattern matchingOvto の話とか、資料を後から眺めるとちゃんとリアルタイムで聞ければよかったのかな、などと思うけど...。録画を楽しみにするのもまた一興なのかも。

LTはうまいことゆっくり聞けたので楽しめた。VTEPの話がよかった。

github.com

関連イベントのほうは前夜祭からAfter Hackまで色々と参加できた。これは地元開催の便利なところ。地方巡業になってからはAfter Partyは飛行機の関係で行ったことがなかったため、最終日無理を言って参加してしまったが、これも出られてよかった。

そしてAfter Hackは、Fukuoka.rbな感じとRubyKaigiがなんとも言えずに混ざった雰囲気になり、感慨深かった。ちなみにとても豪華メンツによる成果発表は動画に撮っています。

fukuokarb.connpass.com

全体に

今年は今まででぼくが一番RubyKaigiに近づいた年だったのかもしれない。

Rubyistは、それぞれに自分の中のRubyKaigiを持っているような気がしているんだけれど、今年はぼくはローカルなオーガナイザーでもあって、それで結構ワガママというか「udzuraの中でのRubyKaigi」が出て、若干振り回してしまった場面もあったと思うが(すいません...)、それ含め松田さんを始めコアオーガナイザーでうまくまとめていただけたような気がしている。

ローカルなオーガナイザーとしては、RubyKaigi 2019はFukuoka.rbのメンバーのみなさん(論理メンバー含む)がオーガナイザー、ヘルパー、そしてキーノートとトークとLTという感じで色々とコミットメントをしてくださって、とてもエモかった。

何度か言っているけどぼくが2013年に福岡に来た当時は「Rubyって福岡では誰が書いてるんだろう?」と本気で思っていたんだけど、そういうところから、なんやかんやベストフォートでいろいろやって、 福岡Ruby会議02 もやって、RubyKaigi 2019もやれることになった。その間にRubyistの友達がたくさん増えた。

この記事も、今Fukuoka.rbでワイワイした中書いていて、 コミュニティでコードを書いていくって楽しい ということを改めて、強く思うことができた。ぼくは、2011年に初めてRubyコミュニティに行き、 東京Ruby会議05 で「ぼくはRubyを一人で書いてるんじゃない!」 と思ったんだけど、そのことも思い出した。

RubyKaigiに行くと、なんだかたくさん人間がいて、みんなRubyを書いていたり、何かしらRubyのことを考えている。そのことは僕にとってはとても嬉しいことだ。Rubyの話を聞けたし(と言いつつ若干だけど)、Rubyのコードの話をたくさんの人とできた。

とにかく、楽しめたので、よかった(...これは一旦は終わったから言えるのかも)。


来年の松本では、どういう形で参加しているのかはまだわからないけど、きっとRubyistの皆様とお会いできることでしょう... それまでは、 See you!