気づいたら3月に...
このたび、Rubyアソシエーションの助成対象となった RbBCC の開発について、最終報告書を出したのですが、せっかくなのでブログで何をやったかも書いとこうという気持ちです。
これの話です。
で、サラッと書くつもりでしたががっつりしています。週末プログラミングのお供にでもどうぞ。
RbBCC の話
以前ブログに書いた気がしていたんですが、 hello world が動いた！みたいなことしか内容がなくて、
今はもうちょっと現実的なツールが動くんで、とりあえず書いて動かしてみましょう。
動かす環境づくりとインストール
まずLinuxを用意します。カーネルのバージョンは新しいほど嬉しいです。今回はもうすぐリリースされるであろう Ubuntu Focal(20.04) を使います。カーネルバージョンは 5.4.0 です。 必要なヘッダファイル、 libbcc （パッケージでは libbpfcc ）を入れておきましょう。
sudo apt install linux-headers-5.4.0-18-generic libbpfcc
なお、ディストロ提供のもので動作するバージョンはFocalのlibbpfcc(0.12)のみで、それ以前のUbuntuなどで libbcc を自分でビルドして入れる場合には こちらが参考になります。 しかし RbBCC は 0.10 ~ 0.12 までしか動作検証(CI)してなく、最新の 0.13 を試す場合動かない可能性があります。
Ruby は rbenv 経由で雑に入れておきましょう。（Focalはディストロ提供のRubyが勢いよく2.7なのですが...）後述する手順でrbenv(ruby-build)自体があった方が助かります。
sudo apt install rbenv # 定義だけ新しくしたい... git clone https://github.com/rbenv/ruby-build.git sudo rsync -av ruby-build/share/ruby-build/ /usr/share/ruby-build/
また、Ruby自体はrootユーザに入れておきます。ここから先の手順は基本的にrootで行います。
sudo su - rbenv install 2.7.0 export PATH="/root/.rbenv/shims:$PATH"
最後に rbbcc をgemとして（今回はgemで大丈夫です。 bundler でプロジェクト単位に固めることもできます。ただのgemなので）インストールします。
gem install rbbcc # 正しくインストールされたか確認 ruby -rrbbcc -e 'p RbBCC::VERSION' #=> "0.4.2" ruby -rrbbcc -e 'p RbBCC::Clib.libbcc_version' #=> #<Gem::Version "0.12.0">
サンプル1（ /dev/urandom へのアクセスをトレース）
早速スクリプトを書いていくことができます。まずは簡単なもの。以下のようなファイルを urandom.rb として保存します。見てわかる通り、一部でC言語の部分があるのですが、今は一旦先に進みます。
require 'rbbcc' include RbBCC b = BCC.new(text: <<BPF) TRACEPOINT_PROBE(random, urandom_read) { bpf_trace_printk("%d\\n", args->got_bits); return 0; } BPF puts("%-18s %-16s %-6s %s" % ["TIME(s)", "COMM", "PID", "GOTBITS"]) b.trace_fields do |task, pid, _, _, ts, msg| puts("%-18.9f %-16s %-6d %s" % [ts, task, pid, msg]) end
2つターミナルを立ち上げ、一方でこのスクリプトを起動。
ruby urandom.rb TIME(s) COMM PID GOTBITS
もう一方で適当なプログラムを動かします。たとえばrubyコマンドを走らせると、
ruby -e 'p :Hello' :Hello
元のターミナルでトレース結果が表示されます。 ruby が起動時に /dev/urandom から128bit（16byte）の情報を2回取り出していることがわかります。他のプログラムを書いたり、あるいは直接catしたりして確認してみましょう。
TIME(s) COMM PID GOTBITS 2375.631369000 ruby 27129 128 2375.632981000 ruby 27129 128 ...
スクリプトのC言語の部分 TRACEPOINT_PROBE(random, urandom_read) は、 random:urandom_read というLinuxカーネルのtracepoint（Rubyの組み込みクラス TracePoint とは基本的に無関係です）です。tracepointとはLinuxが用意してくれているカーネルイベントを取り出すための入り口みたいなものと思ってください。この random:urandom_read は文字通り、urandomへの読み込みに関する情報を取得できます。
こういう感じで、RbBCCを用いるとRuby（と若干の定型的なC）を書くだけで、Linuxの様々なイベントをトレースできます。
サンプル2（libcの malloc(3) のサイズの可視化）
次はユーザランドのライブラリをトレースする例です。以下のファイルを mallochist.rb として保存します。
require 'rbbcc' include RbBCC pid = ARGV[0]&.to_i || -1 b = BCC.new(text: <<BPF) #include <uapi/linux/ptrace.h> BPF_HISTOGRAM(dist); int alloc_enter(struct pt_regs *ctx, size_t size) { dist.increment(bpf_log2l((u32)size / 1024)); return 0; }; BPF b.attach_uprobe(name: "c", sym: "malloc", fn_name: "alloc_enter", pid: pid) puts "Tracing... Hit Ctrl-C to end." trap :INT do puts "\nresult:" b["dist"].print_log2_hist("kbytes") exit end loop { sleep 1 }
これを引数なしで実行すると、Ctrl-Cの入力待ちになります。Ctrl-Cを押すと、その期間中のすべてのプロセスで呼び出された malloc() 関数の要求サイズをヒストグラムで表示してくれます。
ruby mallochist.rb
Tracing... Hit Ctrl-C to end.
^C
result:
kbytes : count distribution
0 -> 1 : 33973 |****************************************|
2 -> 3 : 6 | |
4 -> 7 : 67 | |
8 -> 15 : 1 | |
16 -> 31 : 5 | |
32 -> 63 : 1 | |
64 -> 127 : 0 | |
128 -> 255 : 0 | |
256 -> 511 : 0 | |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 5 | |
例えば、ほとんどの要求は（当然というか）1KB以下ですが、何回か数MBのmalloc要求を走らせているプロセスがいそうだ、などがわかります。そういうプロセスが何者か？であったり、プログラムごとにグラフを分けたり、あるいは失敗した要求を無視したり、といったツールの機能は、先ほどの mallochist.rb に手を加えることで開発できます :)
少しコードの説明をすると、C言語の方で BPF_HISTOGRAM(dist) としてヒストグラムのデータの「入れ物」（BPF mapと言います）を用意します。 alloc_enter() という関数の中でその入れ物の値を、sizeのKB換算のlog2の値をキーに増やしているのは読み取れるでしょう。
このCをコンパイルして、Ruby側で uprobe というものにアタッチしています。uprobeとは、ユーザランドのプログラムの関数呼び出しをトレースする技術で（なお、カーネル関数側のそれをkprobeと呼びます）、今回は libc の中の malloc 関数にアタッチすることを指定しています。libcはほとんどどのプログラムも使うので、結果的にほぼ全てのプログラムの malloc(3) 呼び出しをトレースすることになります。
他に、コードの中で少し面白い点は、Ruby側の BCC#[] を経由して、その入れ物にアクセスできるということです。今回はRubyスクリプトで SIGINT に引っ掛けて中身を取り出し、ヒストグラムを表示（ print_log2_hist ）していますね。
また、（Rubyのコードで予想がつくように）引数指定で特定のプロセスIDのみをトレースすることも可能になっています。みなさんの運用しているRailsプロセスなどにアタッチしてみると面白いかもしれません。
ruby mallochist.rb 29105
Tracing... Hit Ctrl-C to end.
^C
result:
kbytes : count distribution
0 -> 1 : 198963 |****************************************|
2 -> 3 : 19 | |
4 -> 7 : 4 | |
8 -> 15 : 2 | |
16 -> 31 : 2 | |
32 -> 63 : 2 | |
64 -> 127 : 1 | |
128 -> 255 : 1 | |
サンプル3（Rubyのオブジェクト生成をトレース）
最後にもうすこしRubyistにとって面白い例を出します... が、そのまえに、ちょっと変わった「特製」Rubyを用意する必要があります。以下のように、 Ruby 2.7.0 をビルドし直してください。
sudo apt install systemtap-sdt-dev RUBY_CONFIGURE_OPTS='--enable-dtrace' rbenv install 2.7.0
で、以下の rubyusdt.rb というファイルを作成します。ちょっと長いです。
require 'rbbcc' include RbBCC pid = ARGV[0]&.to_i || raise("Usage: #{$0} PID") bpf_text = <<BPF #include <uapi/linux/ptrace.h> struct data_t { u64 ts; char klass[64]; char path[256]; }; BPF_PERF_OUTPUT(events); int do_trace_create_object(struct pt_regs *ctx) { struct data_t data = {}; data.ts = bpf_ktime_get_ns(); bpf_usdt_readarg_p(1, ctx, &data.klass, sizeof(data.klass)); bpf_usdt_readarg_p(2, ctx, &data.path, sizeof(data.path)); events.perf_submit(ctx, &data, sizeof(data)); return 0; }; BPF u = USDT.new(pid: pid.to_i) u.enable_probe(probe: "object__create", fn_name: "do_trace_create_object") b = BCC.new(text: bpf_text, usdt_contexts: [u]) puts("%-18s %-24s %s" % ["TIME(s)", "KLASS", "PATH"]) start = nil b["events"].open_perf_buffer do |cpu, data, size| event = b["events"].event(data) start ||= event.ts time_s = ((event.ts - start).to_f) / 1_000_000_000 puts("%-18.9f %-24s %s" % [time_s, event.klass, event.path]) end Signal.trap(:INT) { puts "\nDone."; exit } loop { b.perf_buffer_poll }
この状態で別のターミナルで、先ほどの「特製」Rubyを用いたプログラムを走らせます。例えば irb などがいいでしょう。このとき、このirbプロセスのPIDを控えておきます。
irb irb(main):001:0> puts $$ 53092 => nil
元のターミナルでこのPIDにアタッチします。
ruby rubyusdt.rb 53092 TIME(s) KLASS PATH
で、irbの方に戻って何かコードを打ち込んでみると、ばばっ！とその際に作られたオブジェクトと、それらが定義されている場所がトレースされます。最新のirbは一行ごとにたくさんのオブジェクトを作りますねえ...。
TIME(s) KLASS PATH 0.000000000 Struct::Key /usr/lib/ruby/2.7.0/reline.rb 0.000053547 Array /usr/lib/ruby/2.7.0/reline/line_editor.rb 0.000082826 Ripper::Lexer /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000116979 Ripper::Lexer::Elem /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000125707 Ripper::Lexer::State /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000203972 Array /usr/lib/ruby/2.7.0/reline/line_editor.rb 0.000216160 Ripper::Lexer /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000232483 Array /usr/lib/ruby/2.7.0/reline/line_editor.rb 0.000241755 Range /usr/lib/ruby/2.7.0/irb/ruby-lex.rb 0.000250589 Ripper::Lexer /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000261074 Ripper::Lexer::Elem /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000267730 Ripper::Lexer::State /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000305811 String /usr/lib/ruby/2.7.0/irb.rb 0.000488908 Array /usr/lib/ruby/2.7.0/reline/line_editor.rb 0.000515790 IRB::Color::SymbolState /usr/lib/ruby/2.7.0/irb/color.rb 0.000526748 Ripper::Lexer /usr/lib/ruby/2.7.0/irb/color.rb 0.000538179 Ripper::Lexer::Elem /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000544523 Ripper::Lexer::State /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000577565 Ripper::Lexer::State /usr/lib/ruby/2.7.0/ripper/lexer.rb 0.000592327 Array /usr/lib/ruby/2.7.0/reline/line_editor.rb 0.000599339 Range /usr/lib/ruby/2.7.0/irb/ruby-lex.rb 0.000607140 Ripper::Lexer /usr/lib/ruby/2.7.0/ripper/lexer.rb ...
先ほどの「特製」Rubyであれば他にも色々な情報をトレースできます。できることは TracePoint にそっくりですが、TracePointクラスと違ってシステムへの影響が極めて小さい形でアタッチ可能です。「本番のRailsアプリケーションがどれくらいオブジェクトを作っているか？」などのトレースも可能でしょう。
ここで、「特製」の解説をします。このRubyは --enable-dtrace オプションをつけてビルドしたRubyなのですが、このオプションは何でしょうか？
これは、DTraceによる細かいトレースを有効にしたRubyを作れというオプションです。Aaron Pattersonさんがるびまに書いた記事も参考になるでしょう。
ただ、本来DTraceはBSD系のUNIXなどでしか使えない機能でもあります。ですが、きょうびのLinuxでは、DTraceのような機能のためにSystemTapやeBPFと呼ばれる技術が導入されており、結果このオプションはLinuxでも使えるようになりました。このようなユーザランドのプログラムに静的に組み込まれたトレースポイントは「USDT（User Statically-Defined Tracing）」と呼ばれます。
どんなUSDTが存在するかは、たとえば bpftrace というツールを使うとわかります。Focalならbpftraceもパッケージで入るので楽ですね...。
sudo apt install bpftrace
ruby -e 'loop { sleep 1 }' &
[1] 54168
sudo bpftrace -p 54168 -l 'usdt:*' | grep 'ruby:'
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:array__create
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:raise
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:gc__sweep__begin
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:gc__sweep__end
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:gc__mark__begin
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:gc__mark__end
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:hash__create
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:load__return
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:load__entry
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:find__require__return
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:require__entry
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:find__require__entry
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:require__return
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:object__create
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:parse__end
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:parse__begin
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:string__create
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:symbol__create
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:method__cache__clear
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:cmethod__entry
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:cmethod__return
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:method__return
usdt:/proc/54168/root/home/vagrant/.rbenv/versions/2.7.0/lib/libruby.so.2.7.0:ruby:method__entry
object__create の他にもGCに関するイベントなど、いくつか興味深いUSDTが見られます。
USDTについての解説はこちらもどうぞ:
ということで今日のまとめとして:
てな感じです！ お試しください。
チュートリアルを含むドキュメントを書いていますので、そちらもご参照ください。
次回は、 RbBCC を使った例をもう少し紹介していきます。多分。
