ローファイ日記

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

超入門USDT

Linuxアドベントカレンダー2020 8日目の記事です。前日はmomomo_rimotoさんの多段sshとchroot環境。そしていろいろなコマンドを使いたいでした。

qiita.com

今日はみんな大好きなeBPFにも関係して、特にUSDTという機能に関するお話をします。

USDT、それは

USDT(User Statically-Defined Tracing) とは、要するに、ユーザランドにあるプログラムに対して、静的にトレースのための窓口（プローブ）を埋め込む仕組みです。トレースが無効の際はパフォーマンスが落ちないような工夫がされています。

詳細な説明は id:mrtc0 の記事の方がわかりやすいので、簡単な説明に留めますが...

blog.ssrf.in

カーネル側をトレースする際に、動的な関数などのプローブをkprobe、静的にカーネルに組み込まれたプローブをtracepointと呼びますが、ユーザランドでは動的な関数などのプローブをuprobe、静的なものをUSDTと呼ぶ、という風に対応しています。

試しにlibcのUSDTに関する情報を見てみます。libc.soのELFバイナリには .note.stapsdt とうNOTEセグメントがあり、どのようなUSDTがどの位置にあるかという情報が記されています。

$ readelf -n /usr/lib/x86_64-linux-gnu/libc-2.31.so | head -40

Displaying notes found in: .note.gnu.property
  Owner                Data size        Description
  GNU                  0x00000010       NT_GNU_PROPERTY_TYPE_0
      Properties: x86 feature: IBT, SHSTK
...

Displaying notes found in: .note.stapsdt
  Owner                Data size        Description
  stapsdt              0x0000003a       NT_STAPSDT (SystemTap probe descriptors)
    Provider: libc
    Name: setjmp
    Location: 0x0000000000045d75, Base: 0x00000000001c1698, Semaphore: 0x0000000000000000
    Arguments: 8@%rdi -4@%esi 8@%rax
  stapsdt              0x0000003b       NT_STAPSDT (SystemTap probe descriptors)
    Provider: libc
    Name: longjmp
    Location: 0x0000000000045f21, Base: 0x00000000001c1698, Semaphore: 0x0000000000000000
    Arguments: 8@%rdi -4@%esi 8@%rdx
  stapsdt              0x00000042       NT_STAPSDT (SystemTap probe descriptors)
    Provider: libc
    Name: longjmp_target
    Location: 0x0000000000045f3d, Base: 0x00000000001c1698, Semaphore: 0x0000000000000000
    Arguments: 8@%rdi -4@%eax 8@%rdx
  stapsdt              0x0000003b       NT_STAPSDT (SystemTap probe descriptors)
    Provider: libc
    Name: longjmp
    Location: 0x0000000000045fb7, Base: 0x00000000001c1698, Semaphore: 0x0000000000000000
    Arguments: 8@%rdi -4@%esi 8@%rdx
  stapsdt              0x00000042       NT_STAPSDT (SystemTap probe descriptors)
    Provider: libc
...

USDTを有効にしたバイナリを作る

USDTを有効にしたプログラムを作成する場合、以下のような DTRACE_PROBE[N] マクロをソースコードに宣言する必要があります。

// 2引数のプローブの例
DTRACE_PROBE2(progname, usdtname, longval, strval);

このマクロはBSD系のプログラムで利用できるマクロと共通のフォーマットになっているため、多くのプログラムでは、configureの際に --enable-dtrace などdtraceを有効にするフラグを設定すると、LinuxではUSDTが有効のバイナリが作成されます。

以下はRubyの例です。

$ sudo apt install systemtap-sdt-dev # 事前に入れる
$ RUBY_CONFIGURE_OPTS='--enable-dtrace' rbenv install 2.7.2
Downloading ruby-2.7.2.tar.bz2...
-> https://cache.ruby-lang.org/pub/ruby/2.7/ruby-2.7.2.tar.bz2
Installing ruby-2.7.2...
Installed ruby-2.7.2 to /home/vagrant/.rbenv/versions/2.7.2
$ rbenv global 2.7.2

readelfで確認すると確かに .note.stapsdt が定義されていました*1。

$ ldd `rbenv which ruby`
        linux-vdso.so.1 (0x00007ffefaddc000)
        libruby.so.2.7 => /home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7 (0x00007f12abe01000)

$ readelf -n /home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7
...
Displaying notes found in: .note.stapsdt
  Owner                Data size        Description
  stapsdt              0x00000043       NT_STAPSDT (SystemTap probe descriptors)
    Provider: ruby
    Name: array__create
    Location: 0x0000000000037a08, Base: 0x000000000035ce42, Semaphore: 0x00000000003b7cd8
    Arguments: -4@$0 8@%rax -4@4(%rsp)
  stapsdt              0x00000045       NT_STAPSDT (SystemTap probe descriptors)
    Provider: ruby
    Name: array__create
    Location: 0x0000000000039c58, Base: 0x000000000035ce42, Semaphore: 0x00000000003b7cd8
    Arguments: -8@%rbx 8@%rax -4@4(%rsp)
  stapsdt              0x00000045       NT_STAPSDT (SystemTap probe descriptors)
    Provider: ruby
    Name: array__create
    Location: 0x000000000003b558, Base: 0x000000000035ce42, Semaphore: 0x00000000003b7cd8
    Arguments: -8@%rbp 8@%rax -4@4(%rsp)
  stapsdt              0x00000045       NT_STAPSDT (SystemTap probe descriptors)
    Provider: ruby
    Name: array__create
    Location: 0x000000000003c618, Base: 0x000000000035ce42, Semaphore: 0x00000000003b7cd8
    Arguments: -8@%rbx 8@%rax -4@4(%rsp)
...

USDTにアタッチする

簡単にアタッチしてみましょう。bpftraceをインストールします*2。今回はUbuntu Focalの標準で提供されている、aptで入れられるもので十分でしょう。

$ sudo apt install bpftrace

動作確認のため bpftrace -l を動かします。

$ sudo bpftrace -l 'usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7'
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:array__create
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:raise
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:gc__sweep__begin
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:gc__sweep__end
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:gc__mark__begin
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:gc__mark__end
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:hash__create
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:load__return
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:load__entry
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:find__require__return
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:require__entry
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:find__require__entry
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:require__return
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:object__create
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:parse__end
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:parse__begin
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:string__create
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:symbol__create
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:method__cache__clear
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:cmethod__entry
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:cmethod__return
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:method__return
usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7:ruby:method__entry

さて、トレースを試します。今回、Rubyが起動直後からSinatraのアプリをセットアップするまでに、どれだけのファイルをrequireするか可視化します。

下準備として、以下のような __block.rb という名前のファイルを作っておきます。

puts $$
gets

Sinatraのアプリのコードはこれくらいで（事前に gem install sinatra でgemを入れておきましょう）。

require 'sinatra'

get '/' do
  "Hola!\n"
end

__block.rb を -r オプションで事前に読み込ませて、起動時にPIDを出力しつつ一旦止まるようにします。

$ ruby -r./__block.rb test.rb 
53958

別のターミナルでbpftraceを起動し、このPIDにアタッチします。なお、 BPFTRACE_STRLEN をいう環境変数を渡さないとrequireしたファイル名が64バイトで切り詰められてしまいます。

$ sudo env BPFTRACE_STRLEN=128 \
> bpftrace \
> -p 53958 \
> -e 'usdt:/home/vagrant/.rbenv/versions/2.7.2/lib/libruby.so.2.7.2:ruby:require__entry {
>   printf("[%d]%s - %s required\n", pid, comm, str(arg0));
> }'
Attaching 1 probe...

アタッチしたら、Sinatra側のプロセスでリターンキーを押し起動を再開します。

$ ruby -r./__block.rb test.rb 
53958

[2020-12-07 01:53:09] INFO  WEBrick 1.6.0
[2020-12-07 01:53:09] INFO  ruby 2.7.2 (2020-10-01) [x86_64-linux]
== Sinatra (v2.1.0) has taken the stage on 4567 for development with backup from WEBrick
[2020-12-07 01:53:09] INFO  WEBrick::HTTPServer#start: pid=53958 port=4567

すると、bpftraceでは以下のようにrequireしたファイルの一覧が表示されます。

[53958]ruby - sinatra required                                                                                                       
[53958]ruby - sinatra required                                                                                                       
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/sinatra-2.1.0/lib/sinatra/main.rb required                
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/sinatra-2.1.0/lib/sinatra/base.rb required                
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-2.2.3/lib/rack.rb required                           
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-2.2.3/lib/rack/version required                      
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/tilt-2.0.10/lib/tilt.rb required                          [53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/tilt-2.0.10/lib/tilt/mapping.rb required                  
[53958]ruby - monitor required                                                                                                       
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/tilt-2.0.10/lib/tilt/dummy.rb required                    [53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/tilt-2.0.10/lib/tilt/template.rb required                 
[53958]ruby - thread required                                                                                                        
...
[53958]ruby - logger required
[53958]ruby - uri required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection/http_origin.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection/ip_spoofing.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection/json_csrf.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection/path_traversal.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection/xss_header.rb required
[53958]ruby - /home/vagrant/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/rack-protection-2.1.0/lib/rack/protection.rb required

USDTを用いたトレースツールを作る

今度は、作られたオブジェクトの統計情報を表示するためのツールを作成します。せっかくなのでRubyを用いた rbbcc を使いましょう*3。

github.com

インストールはomnibusで固めたall-in-oneなパッケージを用いることができます。

$ wget https://github.com/udzura/omnibus-rbbcc/releases/download/0.6.4/rbbcc_0.6.4_focal-1_amd64.deb
$ sudo apt install ./rbbcc_0.6.4_focal-1_amd64.deb
$ rbbcc --version
RbBCC: version 0.6.4
Using ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]

さて、以下のようなRubyのスクリプトを書き、 objcount.rb として保存します（長いです）。

require 'rbbcc'
include RbBCC

pid = ARGV[0]&.to_i || raise("Usage: #{$0} PID")

prog = <<BPF
#include <uapi/linux/ptrace.h>
struct key_t {
  char klass[64];
};
struct leaf_t{
  u64 count;
};
BPF_HASH(store, struct key_t, struct leaf_t);

int countup_create_object(struct pt_regs *ctx) {
  struct key_t key = {0};
  struct leaf_t initial = {0}, *data_;

  bpf_usdt_readarg_p(1, ctx, &key.klass, sizeof(key.klass));

  data_ = store.lookup_or_try_init(&key, &initial);
  if(data_) {
    struct leaf_t data = *data_;
    data.count++;
    store.update(&key, &data);
  }

  return 0;
};
BPF

u = USDT.new(pid: pid.to_i)
u.enable_probe(probe: "object__create", fn_name: "countup_create_object")

b = BCC.new(text: prog, usdt_contexts: [u])

block = true
Signal.trap(:INT) { puts "\nCollected."; block = false}
puts "Collecting events... Hit Ctrl-C to finish"
while block
end

puts "%-32s %5s" % %W(KLASS_NAME COUNT)
res = {}
b["store"].items.sort_by{|k, v| -v.count }.each do |k, v|
  # integrate some dups
  res[k.klass] ||= 0
  res[k.klass] += v.count
end

res.sort_by{|k, v| -v }.each do |klass, count|
  puts "%-32s %5d" % [klass, count]
end

動かします、先ほど同様 __block.rb で一度停止させる形でsinatraを起動しました。

$ ruby -r./__block.rb test.rb 
120811

別のターミナルで objcount.rb を起動します。

$ sudo rbbcc ./objcount.rb 120811
Collecting events... Hit Ctrl-C to finish

Sinatraのターミナルでリターンを押し、起動し切ってからrbbccのターミナルでCtrl-Cを押すと、起動までに作成されたRubyレベルのオブジェクトが集計され、表示されます。

Collecting events... Hit Ctrl-C to finish
^C 
Collected.
KLASS_NAME                       COUNT
String                            3755                           
Range                              768
Gem::StubSpecification             173
File                               173
Gem::StubSpecification::StubLine   173
Class                              145
Gem::Version                        92
Gem::Requirement                    80
Regexp                              76
Array                               46  
Gem::Dependency                     31
Object                              26
#<Class:0x0000564a75ebefb8>         21
#<Class:0x0000564a760a4be8>         20
#<Class:0x0000564a75ea2c28>         19            
#<Class:0x0000564a75ebe158>         19
#<Class:0x0000564a75ea2e58>         19
#<Class:0x0000564a760a4f08>         18             
Mustermann::AST::Node::Char         15
#<Class:0x0000564a76089e10>         15
Hash                                11
Mustermann::AST::Transformer::ExpressionTransform::Operator     8
Thread::Mutex                        8
...

例えば、意図せず特定のクラスのインスタンスが大量に作られていないか、などの事象が確認できるかもしれません。

また、USDT + eBPFの組み合わせであれば本番環境のアプリケーションに、パフォーマンスの劣化をほぼ気にせずにアタッチができます*4。RubyのTracePointクラスのような他の方法よりもその点は有利と言えます。

まとめ

このように、USDTを経由すれば、eBPFなどを用いてアプリケーションレベルのトレースやデバッグが可能になります。

なお、USDT自体はeBPF固有のプローブではありません。systemtap、ftraceやperfなどでも使えます。例えばブレンダン氏の下記の記事などを参照してください。

www.brendangregg.com

明日は Dolphin_0809 さんの記事です！

今回の環境のバージョンなど

Ubuntu

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.1 LTS
Release:        20.04
Codename:       focal

kernel

$ uname -a
Linux ubuntu2004.localdomain 5.8.0-29-generic #31~20.04.1-Ubuntu SMP Fri Nov 6 16:10:42 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

glibc

$ sudo apt show libc6
Package: libc6
Version: 2.31-0ubuntu9.1

Ruby（tracee）

$ ruby -v
ruby 2.7.2p137 (2020-10-01 revision 5445e04352) [x86_64-linux]

rbbcc

$ rbbcc --version
RbBCC: version 0.6.4
Using ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]

*1:どういうプローブがあるかはRDocがあります。 https://docs.ruby-lang.org/en/2.4.0/dtrace_probes_rdoc.html これはRuby のバージョンが微妙に古いですが、内容は同じです。

*2:bpftraceに関しては2日目の記事もぜひ

*3:TODO: Python版BCCでの実装例も置いておく。あまり変わりませんが。

*4:単純にアタッチ有効/無効で 10000 回のアクセスを比較したベンチでは、有効時に平均レスポンスタイムが1.013 [ms]、無効時は0.862 [ms]でした。本番アプリケーションではI/OなどCPUレベルでの劣化と無関係なボトルネックが増えるため、より微小な差異になるでしょう。