qemuのtrace機能
まとめ
参考リンク
- docs/tracing.txt
- これを読めばtrace機能の使い方はだいたい把握できます
- http://wiki.qemu.org/Features/Tracing/Roadmap
関連ファイル
準備(トレースポイントを追加する)
qemuのtrace機能は何も出力しなくてもオーバヘッドがあるので、ディストリビューションのパッケージでは普通はoffになっていると思います。trace機能を使うためにはコンパイル時にオプションを明示的に指定しなければいけません。
configureの当該オプションは以下の通り。
$ ./configure --help |grep trace --enable-trace-backend=B Set trace backend Available backends: nop simple stderr ust dtrace --with-trace-file=NAME Full PATH,NAME of file to store traces Default:trace-<pid>
バックエンドとしてはsimple, stderr, ust(LTTng), dtraceをサポートしているようです。nopを指定するとソースコードにはトレースポイントは埋めこまれません(つまりオーバヘッドなし)。それ以外を指定するとトレースポイントが埋めこまれます。
トレースポイントはtrace定義ファイル(trace-events)に定義された通り動作します。デフォルトの定義ファイルではすべて無効になっているので、何も出力しません。trace定義ファイルで有効にしてコンパイルするか、qemu動作中にモニタで有効にすると出力するようになります。
ここでは、自分でトレースポイントを追加してみます。qcow2ディスクでbacking storeとCoWされたディスクからデータを読み出す割合を調べることを目的としてblock/qcow2.cを以下のように修正しました。
diff --git a/block/qcow2.c b/block/qcow2.c index 75b8bec..facc921 100644 --- a/block/qcow2.c +++ b/block/qcow2.c @@ -29,6 +29,7 @@ #include "block/qcow2.h" #include "qemu-error.h" #include "qerror.h" +#include "trace.h" /* Differences with QCOW: @@ -486,6 +487,7 @@ static void qcow2_aio_read_cb(void *opaque, int ret) acb->sector_num, acb->cur_nr_sectors); if (n1 > 0) { BLKDBG_EVENT(bs->file, BLKDBG_READ_BACKING_AIO); + trace_read_backing_aio(bs, acb, acb->sector_num, acb->cur_nr_se ctors); acb->hd_aiocb = bdrv_aio_readv(bs->backing_hd, acb->sector_num, &acb->hd_qiov, n1, qcow2_aio_read_cb, acb); if (acb->hd_aiocb == NULL) { @@ -542,6 +544,8 @@ static void qcow2_aio_read_cb(void *opaque, int ret) } BLKDBG_EVENT(bs->file, BLKDBG_READ_AIO); + trace_read_aio(bs, acb, (acb->cluster_offset >> 9) + index_in_cluster, + acb->cur_nr_sectors); acb->hd_aiocb = bdrv_aio_readv(bs->file, (acb->cluster_offset >> 9) + index_in_cluster, &acb->hd_qiov, acb->cur_nr_sectors,
この修正で、backing storeへのI/Oリクエストがあればtrace_read_backing_aioが、それ以外ではtrace_read_aioのトレースポイントが呼び出されるようになります。
これに加え、対応する定義をtrace定義ファイルにも追加します。
read_aio(void *bs, void *acb, int64_t sector_num, int nb_sectors) "bs %p acb %p sector_num %"PRId64" nb_sectors %d" read_backing_aio(void *bs, void *acb, int64_t sector_num, int nb_sectors) "bs %p acb %p sector_num %"PRId64" nb_sectors %d"
今回はsimpleバックエンドを使うので以下のようにコンパイルします。
./configure --target-list=x86_64-softmmu --enable-trace-backend=simple make
makeの途中でtrace.[ch]ファイルが生成されます。このエントリの下の方で軽く解析しています。
実演
trace機能のオプションは出力ファイルを指定するための-traceだけです*1。helpメッセージは以下の通り。
$ ./x86_64-softmmu/qemu-system-x86_64 --help |grep trace -trace Specify a trace file to log traces to
。。。という機能があるのですが、バグなのかうまく動かず、常にconfigureのデフォルトであるtrace-
追記: -trace file=trace.logで動きました。helpが不完全なだけのようです。
qemu.orgにあるlinux-0.2.imgをbacking storeに設定してtest.imgを生成して、2回VMを起動し、ディスクへのアクセスがどう変化するかを調べました。実際にやったことを以下の通り。
$ ./qemu-img create -f qcow2 -b linux-0.2.img test.img Formatting 'test.img', fmt=qcow2 size=20971520 backing_file='linux-0.2.img' encryption=off cluster_size=0 $ ls -s test.img 140 test.img $ ./x86_64-softmmu/qemu-system-x86_64 -hda test.img -curses # シェルのプロンプトが出たあとすぐにVMを終了させる $ ls -s test.img 268 test.img $ ./x86_64-softmmu/qemu-system-x86_64 -hda test.img -curses # 同上 $ ls -1 -srt |tail -3 268 trace-320 268 test.img 268 trace-393
trace-320が一回目のVMの起動によって出力されるトレース内容、trace-393が二回目のものです。ファイルの中身はバイナリですが、simpletrace.pyを使うと人間が読める形式で出力してくれます。
$ python scripts/simpletrace.py trace-events trace-320 |tail read_backing_aio 274.457 bs=0x311dfb0 acb=0x3379610 sector_num=0x58ae nb_sectors=0x32 read_backing_aio 4830.300 bs=0x311dfb0 acb=0x3379610 sector_num=0x5326 nb_sectors=0x2 read_backing_aio 303.194 bs=0x311dfb0 acb=0x3379610 sector_num=0x402e nb_sectors=0x2 read_backing_aio 175.930 bs=0x311dfb0 acb=0x3379610 sector_num=0x8ae0 nb_sectors=0x2 read_backing_aio 344.556 bs=0x311dfb0 acb=0x3379610 sector_num=0x4018 nb_sectors=0x2 read_backing_aio 197.513 bs=0x311dfb0 acb=0x3379610 sector_num=0x4d54 nb_sectors=0x18 read_backing_aio 149.756 bs=0x311dfb0 acb=0x3379610 sector_num=0x4d6c nb_sectors=0x2 read_backing_aio 214.704 bs=0x311dfb0 acb=0x3379610 sector_num=0x4d6e nb_sectors=0x8 read_backing_aio 199.591 bs=0x311dfb0 acb=0x3379610 sector_num=0x4d76 nb_sectors=0x40 read_backing_aio 215.196 bs=0x311dfb0 acb=0x3379610 sector_num=0x4db6 nb_sectors=0x80
こんな感じです。どのセクタに何セクタ分のI/Oリクエストがあるかわかります。
このトレース出力をgrepして何回backing storeへアクセスがあるか調べてみます。
$ python scripts/simpletrace.py trace-events trace-320 |grep read_aio |wc -l 0 $ python scripts/simpletrace.py trace-events trace-320 |grep read_backing_aio |wc -l 4167 $ python scripts/simpletrace.py trace-events trace-393 |grep read_aio |wc -l 12 $ python scripts/simpletrace.py trace-events trace-393 |grep read_backing_aio |wc -l 4156
一回目のVM起動ではすべてbacking storeから、二回目は12回だけCoWされたディスクへのI/Oリクエストが発生していることがわかりました。おそらくファイルシステムのメタデータ に更新があった箇所だけ本体の方にコピーが生成されたのでしょう(推測)。このやり方ではデータ転送量まではわからないですが、とりあえずCoWディスクのI/Oリクエスト数の変化はわかりましたのでよしとします*2。
解析
ここでは、どういう仕組みで動いているのか調べてみます。コンパイル時に生成されるtrace.[ch]の当該部分は以下の通り。
static inline void trace_read_aio(void *bs, void *acb, int64_t sector_num, int nb_sectors) { trace4(169, (uint64_t)(uintptr_t)bs,(uint64_t)(uintptr_t)acb,(uint64_t)(uintptr_t)sector_num,(uint64_t)(uintptr_t)nb_sectors); } static inline void trace_read_backing_aio(void *bs, void *acb, int64_t sector_num, int nb_sectors) { trace4(170, (uint64_t)(uintptr_t)bs,(uint64_t)(uintptr_t)acb,(uint64_t)(uintptr_t)sector_num,(uint64_t)(uintptr_t)nb_sectors); }
trace.hはこんな感じ。今回追加したトレースポイント用関数が定義され、中でtrace4関数を呼び出していることがわかります。第一引数はトレースポイントのIDのようです。
続いてtrace.cは以下の通り。
TraceEvent trace_list[] = {
/* snip */
{.tp_name = "spice_vmc_unregister_interface", .state=0},
{.tp_name = "read_aio", .state=1},
{.tp_name = "read_backing_aio", .state=1},
};
TraceEventはsimpletrace.hに定義されています。
typedef struct { const char *tp_name; bool state; } TraceEvent;
stateは出力するかどうかを表わしていて、1なら出力です。trace定義ファイルでenableにしてあるread_aioとread_backing_aioは1、それ以外は0になっています*3。
trace4関数はsimpletrace.cに定義してあります。
void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4) { trace(event, x1, x2, x3, x4, 0, 0); }
trace関数を呼び出しているだけですね。そのtrace関数もsimpletrace.cに定義してあります。
static void trace(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6) { TraceRecord *rec = &trace_buf[trace_idx]; if (!trace_list[event].state) { return; } rec->event = event; rec->timestamp_ns = get_clock(); rec->x1 = x1; rec->x2 = x2; rec->x3 = x3; rec->x4 = x4; rec->x5 = x5; rec->x6 = x6; if (++trace_idx == TRACE_BUF_LEN) { st_flush_trace_buffer(); } } void st_flush_trace_buffer(void) { if (trace_file_enabled) { flush_trace_file(); } /* Discard written trace records */ trace_idx = 0; } static void flush_trace_file(void) { /* If the trace file is not open yet, open it now */ if (!trace_fp) { trace_fp = fopen(trace_file_name, "w"); if (!trace_fp) { /* Avoid repeatedly trying to open file on failure */ trace_file_enabled = false; return; } write_header(trace_fp); } if (trace_fp) { size_t unused; /* for when fwrite(3) is declared warn_unused_result */ unused = fwrite(trace_buf, trace_idx * sizeof(trace_buf[0]), 1, trace_fp); } } static bool write_header(FILE *fp) { static const TraceRecord header = { .event = HEADER_EVENT_ID, .timestamp_ns = HEADER_MAGIC, .x1 = HEADER_VERSION, }; return fwrite(&header, sizeof header, 1, fp) == 1; }
stateが0なら何もしない。stateが1のときは、バッファが満杯になった時だけ出力するという動作のようです。(trace_file_enabledがfalseのときは出力しないようですが、とりあえず今回は無視します。)出力内容は、ファイルの最初にヘッダ用のレコードを出力して(write_header関数)、あとはバッファの中身を一度に出力しているだけです。
/** Trace buffer entry */ typedef struct { uint64_t event; uint64_t timestamp_ns; uint64_t x1; uint64_t x2; uint64_t x3; uint64_t x4; uint64_t x5; uint64_t x6; } TraceRecord; enum { TRACE_BUF_LEN = 64 * 1024 / sizeof(TraceRecord), }; static TraceRecord trace_buf[TRACE_BUF_LEN];
レコード1つが8*64bit=64バイトで、1024回分バッファリングできるようです。
なおqemu終了時はatexit(3)でバッファの残りを出力しています。
/** * Flush the trace buffer on exit */ static void __attribute__((constructor)) st_init(void) { atexit(st_flush_trace_buffer); }
軽くソースコードを読んでみましたが、simpleという名前の通り簡単なつくりでした。カーネルのdynamic tracingのように無効時にオーバヘッドを減らすトリックもありません。それでも自前でprintfするよりは簡単で軽量なデバッグ出力を追加できそうです。
