最近プロダクション環境での諸々の調査に使いたいというモチベーションで 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では動作しなかった。
