Qemuのトレース機能

Qemuのソースコードを読んでいると、trace_ほげほげ()、のような記述が度々出てくる。ここを通ると書かれた変数をどこかに出す、イベントトレース機能に違いない。適当にググると、この機能が追加された直後の何年も前の記事がひっかかるが、現在のUbuntuやRHEL (CentOSなども含む) でどうなっているのか調べた。

## Ubuntuの場合

Qemuのトレース機能は、コンパイル時オプションで、configureに与えるオプションによってトレース出力先も異なる。これをtrace backendと呼んでいるようだ。例えば、Ubuntuのqemuパッケージのコンパイルログは[公開されている (20.04 "Focal Fossa")](https://launchpadlibrarian.net/475413959/buildlog_ubuntu-focal-amd64.qemu_1%3A4.2-3ubuntu6_BUILDING.txt.gz) が、ここにはconfigureのサマリーとして

```
Trace backends    log
```

とあり、trace backendはlogというものであることがわかる。

trace_ほげ()は、Cのインライン関数やマクロであり、その定義はソースコードの各ディレクトリにあるtrace.hで定義されるが、trace.hは、[tracetool](https://git.qemu.org/?p=qemu.git;a=blob;f=scripts/tracetool.py;h=ab7653a5ce0db12fca654d56bc1adefde3facb0d;hb=74208cd252c5da9d867270a178799abd802b9338)というプログラムがtrace backendなどに応じてコンパイル時に生成する。Trace backendがlogの場合、[こんな感じ](https://git.qemu.org/?p=qemu.git;a=blob;f=scripts/tracetool/backend/log.py;h=bc43dbb4f4cb2168e7cb66d125554f912887bf3f;hb=74208cd252c5da9d867270a178799abd802b9338) だ。これでわかりにくければ、実際にUbuntu上でqemuパッケージをコンパイルしてみれば良い。たとえば、[trace_handle_hmp_command(mon, cmdline)](https://git.qemu.org/?p=qemu.git;a=blob;f=monitor/hmp.c;h=6c0b33a0b19dff4e31802392ac512914b194e493;hb=74208cd252c5da9d867270a178799abd802b9338#l1085)ならば、

```
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);
    }
}
```

のような感じだ ([呼び出し側はこんな感じ](https://git.qemu.org/?p=qemu.git;a=blob;f=monitor/hmp.c;h=6c0b33a0b19dff4e31802392ac512914b194e493;hb=74208cd252c5da9d867270a178799abd802b9338#l1085))。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系のログは見つからなかった)](https://buildlogs.centos.org/c7.2009.00.x86_64/qemu-kvm/20201001165703/1.5.3-175.el7.x86_64/build.log)、これによると、

```
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](https://sourceware.org/systemtap/langref/4_Probe_points.html#SECTION00055800000000000000)というマクロを埋め込む、と思いきや、DTrace互換のDTRACE_PROBEn()も用意されていて、DTrace/systemtapどっちでも使えるように書くことができる。RHELではsystemtap-sdtというパッケージを導入することで、好きなプログラムにSDTのプローブを入れるのに用いることができる。

STAP_PROBEnと互換マクロのDTRACE_PROBEnは、最終的に[このような](https://sourceware.org/git?p=systemtap.git;a=blob;f=includes/sys/sdt.h;h=c0c5a492cb9cd03f26a03c4ea16aaf31a9dd6e4d;hb=428f84e9e656bce71018e8902e4edb8aacafcc0e#l215)形でインラインアセンブラのコードに展開される。その場にはnop (何もしない命令) が埋め込まれ、別途.note.stapsdtというセクションにアドレスや引数などの情報が記録される。なので、イベントトレース機能を使わない時のオーバーヘッドは最低限に抑えらる。イベントトレース機能を有効にすると、systemtapによりnopがブレークポイント命令 (x86ではint3命令、一般に、nopと同じ命令長) に書き換えられ、カーネルに例外が伝えられる。systemtapのモジュールがこれを処理してイベントをユーザースペースに戻すという仕組みだ。trace_ほげ()の引数や文字列は、自動生成されたtapsetとして/usr/share/systemtap/tapsetにインストールされている。

使い方は、実はRed Hatの[文書](https://access.redhat.com/documentation/ja-jp/red_hat_enterprise_linux/7/html/virtualization_deployment_and_administration_guide/sect-troubleshooting-systemtaptrace) に詳述されている (多少誤りがある)。

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のインストールなど、手間がかかるのが弱点と言える。