ローファイ日記

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

eBPF for Rubyist 現状確認(1) - RbBCC の使い方 in March 2020

気づいたら3月に...

このたび、Rubyアソシエーションの助成対象となった RbBCC の開発について、最終報告書を出したのですが、せっかくなのでブログで何をやったかも書いとこうという気持ちです。

udzura.hatenablog.jp

これの話です。

で、サラッと書くつもりでしたががっつりしています。週末プログラミングのお供にでもどうぞ。

RbBCC の話

以前ブログに書いた気がしていたんですが、 hello world が動いた!みたいなことしか内容がなくて、

udzura.hatenablog.jp

今はもうちょっと現実的なツールが動くんで、とりあえず書いて動かしてみましょう。

動かす環境づくりとインストール

まず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さんがるびまに書いた記事も参考になるでしょう。

magazine.rubyist.net

ただ、本来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についての解説はこちらもどうぞ:

blog.ssrf.in


ということで今日のまとめとして:

  • RbBCC という BCC for Ruby を書いた
  • 割とちゃんと動く

てな感じです! お試しください。

チュートリアルを含むドキュメントを書いていますので、そちらもご参照ください。

github.com

次回は、 RbBCC を使った例をもう少し紹介していきます。多分。