Hatena::ブログ(Diary)

KVM日記 RSSフィード

Linux KVM(Kernel-based Virtual Machine)好きの独り言

2011-06-11

qemuのtrace機能

はじめに

qemuには内部の処理をtraceするための機能があります。この機能を使うとprintfのように簡単でprintfより軽量なデバッグ出力を追加することができます。

まとめ

  • 用途はデバッグ(printfの代わり)
  • コンパイル時に機能をon/off指定する必要がある
    • 普通はoffになっている
  • 個々のトレースポイントは動的にon/off可能
    • ただしoff時にもオーバヘッドあり
  • 出力フォーマットにLTTngやDTraceがある
  • 実装はシンプル(面白味に欠けるともいう)

環境

参考リンク

関連ファイル

  • trace-events: trace定義ファイル(仮称)
  • scripts/tracetool: 指定バックエンド用のtrace.[ch]をコンパイル時に生成するスクリプト
  • simpletrace.[ch]: simpletraceバックエンドのソースコード
  • scripts/simpletrace.py: simpletraceバックエンドのデータを解析・整形出力するスクリプト

準備(トレースポイントを追加する)

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-<pid>が使われてしまいました。今回は特に困らないなので気にしないことにします。

追記: -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するよりは簡単で軽量なデバッグ出力を追加できそうです。

おわりに

実装的には面白味はあんまりなかったですが、qemuを改良する人にとっては便利な機能なのではないでしょうか。

バグらしきものも残っていますし、最適化の余地も残っているので、興味がある人はコントリビュートするのに良いかもしれません*4

*1qemuコンソールにも機能がありますが、今回は触れません。

*2:まぁ適当なスクリプトを書けばすぐにわかりますが。

*3:このstateはqemuコンソールで変えることができます。tp_nameはコンソールで名前を指定してstateを変更するためのものです。

*4ロードマップには一応ありますね。

スパム対策のためのダミーです。もし見えても何も入力しないでください
ゲスト


画像認証

トラックバック - http://d.hatena.ne.jp/kvm/20110611/1307807337