Qemuのソースコードを読んでいると、trace_ほげほげ()、のような記述が度々出てくる。ここを通ると書かれた変数をどこかに出す、イベントトレース機能に違いない。適当にググると、この機能が追加された直後の何年も前の記事がひっかかるが、現在のUbuntuやRHEL (CentOSなども含む) でどうなっているのか調べた。
Ubuntuの場合
Qemuのトレース機能は、コンパイル時オプションで、configureに与えるオプションによってトレース出力先も異なる。これをtrace backendと呼んでいるようだ。例えば、Ubuntuのqemuパッケージのコンパイルログは公開されている (20.04 "Focal Fossa") が、ここにはconfigureのサマリーとして
Trace backends log
とあり、trace backendはlogというものであることがわかる。
trace_ほげ()は、Cのインライン関数やマクロであり、その定義はソースコードの各ディレクトリにあるtrace.hで定義されるが、trace.hは、tracetoolというプログラムがtrace backendなどに応じてコンパイル時に生成する。Trace backendがlogの場合、こんな感じ だ。これでわかりにくければ、実際にUbuntu上でqemuパッケージをコンパイルしてみれば良い。たとえば、trace_handle_hmp_command(mon, cmdline)ならば、
static inline void _nocheck__trace_handle_hmp_command(void * mon, const char * cmdline)
{
if (trace_event_get_state(TRACE_HANDLE_HMP_COMMAND) && qemu_loglevel_mask(LOG_TRACE)) {
struct timeval _now;
gettimeofday(&_now, NULL);
qemu_log("%d@%zu.%06zu:handle_hmp_command " "mon %p cmdline: %s" "\n",
qemu_get_thread_id(),
(size_t)_now.tv_sec, (size_t)_now.tv_usec
, mon, cmdline);
}
}
static inline void trace_handle_hmp_command(void * mon, const char * cmdline)
{
if (true) {
_nocheck__trace_handle_hmp_command(mon, cmdline);
}
}
のような感じだ (呼び出し側はこんな感じ)。Trace backendがlogの場合、loglevelからLOG_TRACEが抜けることはないようなので、trace_event_get_state(TRACE_HANDLE_HMP_COMMAND)が真のとき、qemu_log()という関数でログが記録される。if (true) の部分も、イベントの種類によっては展開される。
trace_event_get_state()は、イベント毎のstate (1/0) を持っていて、これはQemu monitorのHMPコマンドtrace-eventで設定でき、また同じくinfo trace-eventsコマンドで状態の取得ができる。libvirt配下のVMの場合は、以下のようなコマンドになる。
# virsh qemu-monitor-command --hmp VM info trace-events | grep handle_hmp_command
handle_hmp_command : state 0
# virsh qemu-monitor-command --hmp VM trace-event handle_hmp_command on
# virsh qemu-monitor-command --hmp VM info trace-events | grep handle_hmp_command
handle_hmp_command : state 1
この場合、/var/lib/libvirt/qemu/VM.logに記録が出る。
TID@TIME.STAMP:handle_hmp_command mon 0xXXXXXXXXXXXX cmdline: info trace-events
RHELなどの場合
RHEL互換のCentOSのコンパイルログも、公開されていて (7.9.2009、8系のログは見つからなかった)、これによると、
Trace backend dtrace
とある。DTraceといえば、Solarisのイベントトレース機能で、優れているということで遠い祖先を同じくするFreeBSDやmacOSのほか、Windowsにも移植されているとか。ライセンスがGPLと互換性のないCDDLとあって、Linuxには非公式の移植しかない。代わりにLinuxにはsystemtapがある。
Qemuで使われているのは、DTraceのSDT (Statically Defined Tracing) という機能で、トレースしたい部分にDTRACE_PROBE1()のようなマクロ (1の部分は引数の数) を埋め込む。これと似たような機能はsystemtapにもあり、STAP_PROBEnというマクロを埋め込む、と思いきや、DTrace互換のDTRACE_PROBEn()も用意されていて、DTrace/systemtapどっちでも使えるように書くことができる。RHELではsystemtap-sdtというパッケージを導入することで、好きなプログラムにSDTのプローブを入れるのに用いることができる。
STAP_PROBEnと互換マクロのDTRACE_PROBEnは、最終的にこのような形でインラインアセンブラのコードに展開される。その場にはnop (何もしない命令) が埋め込まれ、別途.note.stapsdtというセクションにアドレスや引数などの情報が記録される。なので、イベントトレース機能を使わない時のオーバーヘッドは最低限に抑えらる。イベントトレース機能を有効にすると、systemtapによりnopがブレークポイント命令 (x86ではint3命令、一般に、nopと同じ命令長) に書き換えられ、カーネルに例外が伝えられる。systemtapのモジュールがこれを処理してイベントをユーザースペースに戻すという仕組みだ。trace_ほげ()の引数や文字列は、自動生成されたtapsetとして/usr/share/systemtap/tapsetにインストールされている。
使い方は、実はRed Hatの文書 に詳述されている (多少誤りがある)。
systemtap-initscriptsパッケージを導入すると、/etc/systemtapというディレクトリができる。qemu-kvmパッケージに含まれる、/usr/share/qemu-kvm/systemtap/conf.d/qemu_kvm.confを/etc/systemtap/conf.dにコピーし、/usr/share/qemu-kvm/systemtap/script.d/qemu_kvm.stpを参考に/etc/systemtap/script.d/qemu_kvm.stpを作成する (qemu_kvm.stpは空っぽに見えるが、これにより、対応するtapsetのプローブが引き込まれる)。
# cp /usr/share/qemu-kvm/systemtap/conf.d/qemu_kvm.conf /etc/systemtap/conf.d
# cat /etc/systemtap/conf.d/qemu_kvm.conf
stap -e 'probe process("/usr/libexec/qemu-kvm").function("main") { printf("") }' -c true
qemu_kvm_OPT="-s4" # per-CPU buffer size, in megabytes
# echo 'probe qemu.kvm.simpletrace.handle_hmp_command {}' > /etc/systemtap/script.d/qemu_kvm.stp
systemctl start systemtapとする (文書にある「qemu_kvm」は不要) と、systemtapモジュール (qemu_kvm) が生成されてカーネルにロードされる (lsmod | headでわかる)。これで、実行中およびこの後実行されるQemuのトレースが記録される。取得するには、staprunの-Aオプションを使う (-Aは、すでにカーネルにロードされたsystemtapモジュールにstaprunを接続し、systemtapのprintfなどの出力を取り出すオプション)。
# systemctl start systemtap
# lsmod | head
Module Size Used by
qemu_kvm 263372 0
vhost_net 22499 1
[略]
# staprun -A qemu_kvm > /tmp/trace.log
トレースしたい処理が終わったら、Ctrl-CではなくCtrl-\を押してSIGQUITを送る。Ctrl-C (SIGINT) を送ると、systemtapのモジュールがアンロードされてしまうので、間違って押してしまった場合はsystemctl restart systemtapなどとする必要がある。
trace.logは、人間に読める形式ではない (tapsetを見ると、printfの%bという書式が使われている。これは、systemtap特有の書式文字で、そのままバイナリで出力する指示) ので、/usr/share/qemu-kvm/simpletrace.pyスクリプトで読める形式に変換する。
# /usr/share/qemu-kvm/simpletrace.py --no-header /usr/share/qemu-kvm/trace-events-all /tmp/trace.log
handle_hmp_command 0.000 pid=3497 mon=0xXXXXXXXXXXXX cmdline=info pci
handle_hmp_command 2934649.189 pid=3497 mon=0xXXXXXXXXXXXX cmdline=info pci
第2項がわかりづらいが、前の行からの時間 (マイクロ秒)を表す。
Ubuntuの時 (log) と違い、qemu monitorのtrace-eventコマンドとは無関係に、/etc/systemtap/script.d/qemu_kvm.stpで記述したプローブポイントのみが記録される。Qemu起動時からの情報が記録できるのが利点であるほか、イベントトレース機能を使わないときには単なるnopで、条件判断すら実行しないのでオーバーヘッドもほとんどない。systemtapのインストールなど、手間がかかるのが弱点と言える。