最近プロダクション環境での諸々の調査に使いたいというモチベーションで BPF Performance Tools (Book) 読み進めつつ、提供されているbcc-toolsを試したりbpftraceでlibほげほげの関数パラメータを抜いたりしていた、のだがUSDTを使用したトレースはうまく動かせず悶々としていた。

正直USDTはパッケージ入れておけばいきなりproductionでさくっと使える、という感じでもなく当初の目的からはやや外れているのだが、機構があるのに動かせないというのはなんとももどかしいので、諸々試行錯誤してとりあえず動いた、というころまでの記録を残しておく。対象はphpで。

なぜphpなのかというと、プライベート的にもお仕事的にも馴染みがありワンチャン使える可能性もあるのでは・・という期待と、ツールを試す過程で標準パッケージのphpで

$ tplist-bpfcc -l /usr/bin/php
b'/usr/bin/php' b'php':b'request__startup'
b'/usr/bin/php' b'php':b'request__shutdown'
b'/usr/bin/php' b'php':b'compile__file__entry'
b'/usr/bin/php' b'php':b'compile__file__return'
b'/usr/bin/php' b'php':b'function__return'
b'/usr/bin/php' b'php':b'function__entry'
b'/usr/bin/php' b'php':b'execute__entry'
b'/usr/bin/php' b'php':b'execute__return'
b'/usr/bin/php' b'php':b'error'
b'/usr/bin/php' b'php':b'exception__thrown'
b'/usr/bin/php' b'php':b'exception__caught'

を観測したためこれはもしや--enable-dtraceされてるのでは・・となり、試してみたくなったため。

結果的にUbuntuなら先日リリースされた20.04 LTSのイメージで特に独自ビルドなどは頑張らなくてもいくつかのパッケージインストールのみで（一応）動かすこと自体はできることがわかった。

環境

AWS上でUbuntu 20.04 LTS (Focal Fossa) のインスタンスを立てて動かした。

ami

$ echo `curl -s http://instance-data/latest/meta-data/ami-id`
ami-0c1ac8728ef7f87a4 # ubuntu/images/hvm-ssd/ubuntu-focal-20.04-amd64-server-20200423

php

ii  php7.4-cli                       7.4.3-4ubuntu1                    amd64        command-line interpreter for the PHP scripting language

ruby

ii  ruby2.7                          2.7.0-5ubuntu1                    amd64        Interpreter of object-oriented scripting language Ruby

bpf関連

ii  bpfcc-tools                      0.12.0-2                          all          tools for BPF Compiler Collection (BCC)
ii  bpftrace                         0.9.4-1                           amd64        high-level tracing language for Linux eBPF
ii  libbpfcc                         0.12.0-2                          amd64        shared library for BPF Compiler Collection (BCC)
ii  python3-bpfcc                    0.12.0-2                          all          Python 3 wrappers for BPF Compiler Collection (BCC)

サンプルスクリプト

手頃なものがなかったのではるか昔書いた雑スクリプトの先頭に（pidをアタッチする時間を稼ぐために）sleepを追加して試した、今みるとコード的にもなかなかあれだが、まあサイズ的にもコンパクトでいいかな、ということで・・。

https://github.com/egmc/dscheck

実行条件

環境変数 USE_ZEND_DTRACE=1 を設定してDTrace Supportを有効にしたうえでphp スクリプトを実行する
↑で実行したプロセスのpidを対象にトレースを実行する

phpの場合、--enable-dtraceでビルドしただけでは不十分で USE_ZEND_DTRACE=1 で実行しないとDTrace Supportが有効にならない模様。

git.php.net

. Disabled PHP call tracing by default (it makes significant overhead). This may be enabled again using envirionment variable USE_ZEND_DTRACE=1.

上述の通りfocalの標準パッケージは--enable-dtrace自体はされてるようなのでこれでいける

$ /usr/bin/php -i |grep -i dtrace
DTrace Support => available, disabled
$ USE_ZEND_DTRACE=1 /usr/bin/php -i |grep -i dtrace
DTrace Support => enabled

試しに --enable-dtrace なしでビルドしたphpは以下のようになっていた

$ /usr/local/php7.4-no-trace/bin/php -i |grep -i dtrace
DTrace Support => disabled

bpftaceでトレースする

上述のphp スクリプト（$ USE_ZEND_DTRACE=1 php dscheck.php）を実行させつつ、別窓でトレースを実行してテスト

probeのパラメータはここで何が取れるのか確認

autoload処理、関数呼び出しが観測できる、arg1はlineno

# BPFTRACE_STRLEN=200 bpftrace -p `pgrep php` -e 'usdt:/usr/bin/php:execute__entry { printf("%s, %d\n", str(arg0), arg1); }'|head -n10
Attaching 1 probe...
/home/ubuntu/dscheck/vendor/autoload.php, 5
/home/ubuntu/dscheck/vendor/composer/autoload_real.php, 74
/home/ubuntu/dscheck/vendor/composer/autoload_real.php, 21
/home/ubuntu/dscheck/vendor/composer/autoload_real.php, 11
/home/ubuntu/dscheck/vendor/composer/ClassLoader.php, 446
/home/ubuntu/dscheck/vendor/composer/autoload_static.php, 38
/home/ubuntu/dscheck/vendor/composer/autoload_static.php, 30
/home/ubuntu/dscheck/vendor/composer/autoload_static.php, 32
/home/ubuntu/dscheck/vendor/composer/ClassLoader.php, 302

compile__file__entry でスクリプトのコンパイルを覗いてみる（arg0が char *compile_file のはずだがこちらは空になっている・・

# BPFTRACE_STRLEN=200 bpftrace -p `pgrep php` -e 'usdt:/usr/bin/php:compile__file__entry { printf("%s\n", str(arg1)); }'
Attaching 1 probe...
/home/ubuntu/dscheck/vendor/autoload.php
/home/ubuntu/dscheck/vendor/composer/autoload_real.php
/home/ubuntu/dscheck/vendor/composer/ClassLoader.php
/home/ubuntu/dscheck/vendor/composer/autoload_static.php
/home/ubuntu/dscheck/vendor/composer/../swiftmailer/swiftmailer/lib/swift_required.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift.php
/home/ubuntu/dscheck/vendor/composer/../symfony/yaml/Symfony/Component/Yaml/Parser.php
/home/ubuntu/dscheck/vendor/composer/../../src/DsCheck/DsCheck.php
/home/ubuntu/dscheck/vendor/composer/../symfony/yaml/Symfony/Component/Yaml/Inline.php
/home/ubuntu/dscheck/vendor/composer/../symfony/yaml/Symfony/Component/Yaml/Unescaper.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Mailer.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/swift_init.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/dependency_maps/cache_deps.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/DependencyContainer.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/dependency_maps/mime_deps.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/dependency_maps/../mime_types.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/dependency_maps/message_deps.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/dependency_maps/transport_deps.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/preferences.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Preferences.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/MailTransport.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Transport/MailTransport.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Transport.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Transport/SimpleMailInvoker.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Transport/MailInvoker.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Events/SimpleEventDispatcher.php
/home/ubuntu/dscheck/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Events/EventDispatcher.php

なおpidを指定せずにトレースしようとすると以下のように怒られる

# BPFTRACE_STRLEN=200 bpftrace -e 'usdt:/usr/bin/php:compile__file__entry { printf("%s\n", str(arg1)); }'
Attaching 1 probe...
Error finding or enabling probe: usdt:/usr/bin/php:php:compile__file__entry

RbBCCでトレースする

udzuraさんのこちらのエントリでrubyでbccできるぞ、というのを試してみたく

udzura.hatenablog.jp

こちらのサンプルを写経させて頂き、probe対象を変更してfunction名を取得するだけのサンプルを試してみた。（というか実際のところはところこちらを先に動かして、あれ、とれるやんけ・・となりbpftrace側でも同様にトレースできることを確認出来たという流れ）

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 function[128];
};
BPF_PERF_OUTPUT(events);

int do_trace_function_entry(struct pt_regs *ctx) {
    struct data_t data = {};
    data.ts = bpf_ktime_get_ns();
    bpf_usdt_readarg_p(1, ctx, &data.function, sizeof(data.function));
    events.perf_submit(ctx, &data, sizeof(data));
    return 0;
};
BPF

u = USDT.new(pid: pid.to_i)
u.enable_probe(probe: "function__entry", fn_name: "do_trace_function_entry")

b = BCC.new(text: bpf_text, usdt_contexts: [u])
puts("%-18s %s" % ["TIME(s)", "function"])
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 %s" % [time_s, event.function])
end
Signal.trap(:INT) { puts "\nDone."; exit }
loop { b.perf_buffer_poll }

こんな感じでトレースできる

# ruby phpusdt.rb `pgrep php` | head -n20
TIME(s)            function
0.000000000        main
0.000193415        main
0.000223335        getLoader
0.000248361        loadClassLoader
0.000652416        main
0.000740099        main
0.000760310        getInitializer
0.000781820        Composer\Autoload\{closure}
0.000799492        register
0.000818768        composerRequirea069f98d7345659050bcc164f0155069
0.000888641        main
0.000979718        main
0.000999792        registerAutoload
0.001022639        loadClass
0.001038429        findFile
0.001054807        findFileWithExtension
0.001089370        Composer\Autoload\includeFile
0.002951398        main
0.002981065        __construct
Possibly lost 227 samples

python バインディングもそれほどコード書くわけではないのだけど、gemでさくっと自前のbccツールを、みたいなのが出来るのはいいかもしれない・・。

ということで

なんとかphpでUSDTを使用したbcc/bpftraceでのトレースを実行することができた。

少なくともfocalではphpの再ビルドせずに使うことはできるものの、依然条件は厳しく、PHPであればnewrelic等のAPM使うなど、そこまでこれでなにかを観測したいという強いモチベーションもなく、どうかなーというところですが。

（compile__file__xxx でopcodeのキャッシュ状況みるとかワンチャンどうかなーと思いつつ、実際php スクリプトが動いてる環境はmod-phpであったりphp-fpmであったりするので、そのあたりは結局動かせておらず

ついでにメモ

github.com

bccのレポジトリにも各言語のトレースサンプルが存在している、がこちらは

bpf_probe_read_user missing (added in Linux 5.5).

ということでカーネル5.4.0なfocalでは動作しなかった。

ださろぐ@はてな

eBPF+USDTでphpをトレースしてみる、bpftaceとRbBCCでやる

環境

実行条件

bpftaceでトレースする

RbBCCでトレースする

ということで

ついでにメモ