Mobile Factory Tech Blog

技術好きな方へ!モバイルファクトリーのエンジニアたちが楽しい技術話をお届けします!

OverlayFS でデータ入りのテスト用 DB を素早く起動する

駅メモ!開発基盤チームの id:xztaityozx です。
今回はテスト実行のボトルネックを OverlayFS を利用することで解消した話と、OverlayFS の動作を調べるためにbpftraceを使った話をします。

かんたん概要

  1. Test::mysqldを使って挿入済みのデータを持ったmysqldをテストごとに起動していた
  2. データが増えてきたことでコピーがめちゃくちゃ遅くなり、開発体験が最悪になった
  3. コピーを OverlayFS でのマウントに置き換えてすごく速くした
  4. 動作について気になる点があったのでbpftrace を使ってトレースを行い、カーネル関数の呼び出しも観察した

前提

この記事で登場する主なツールのバージョンを示します

  • Ubuntu 22.04.4(WSL2)
    • カーネル: 5.15.146.1-microsoft-standard-WSL2
  • hyperfine 1.18.0
  • Docker 26.0.0, build 2ae903e
  • sysbench 1.0.20
  • bpftrace 0.12.0

背景

単体テストで用いる DB をどのように起動していますか?Test::mysqldなどを用いてmysqldを起動したり、MySQL コンテナを起動したりなど様々かと思います。駅メモ!でも先にも登場した Test::mysqld とApp::Prove::Plugin::MySQLPoolを用いて、テスト開始前に専用のmysqldを起動していました。

Test::mysqld はcopy_data_fromにディレクトリへのパスを渡すことで、そのディレクトリのコピーを MySQL のデータディレクトリとすることができます。つまり、データを複製して起動することができるということですね。
駅メモ!ではこの仕組みを用いることで、テストで必ず使うことになるデータ(例えばマスターデータ)が事前に挿入された MySQL を起動しています。こうすることでテストの開始にかかる時間の短縮と複雑なデータセットの挿入の簡略化を狙っています。元々どんな目的で運用されていたかはわかりませんが、少なくとも現在はこの目的で運用しています。

課題点

この運用は課題点がありました。それは事前挿入しておきたいデータが増えたことにより、コピーに時間がかかりすぎるようになったことです。具体的にかかる時間として、コピー元のデータが壊れていないこと前提で、平均 40 秒ほどかかる状況でした。

1 回当たりのテスト実行のたびに 40 秒+テスト実行時間が掛かっていれば開発体験は最悪です。エンジニアは少し変更しては待機、少し変更しては待機を繰り返す必要があるわけですが、何か別のことをするには短すぎ、計算資源だけではなく人件費の無駄にもなっていました。

もちろんチームではなにも対策をしていなかったわけではないのですが、次の手が見つかっていない状況でした。

課題に対するアプローチ

先にも述べた通り課題点はコピーすべきデータが増えてしまったことです。そこでまずは挿入しておきたいデータを無くす、もしくは最小限に減らすことです。そのテストで必要なデータはbefore allなどでテストごとに挿入します。データセットの柔軟性もよくなるのでこの方法を採用したいですが、複雑なデータセットの挿入を再現するのにかかるコストが高いこと、直すべきテストが多すぎることから取りたくない方法でした。

次に考えたのはデータ入りのコンテナイメージを作っておく方法です。なんでも試そうということでやってみましたが、これは少しだけ効果がありました。

$ docker run --rm -d -p 3306:3306 \
    -e MYSQL_ALLOW_EMPTY_PASSWORD=1 \
    -v $PWD/data:/var/lib/mysql mysql:8.0.34

# だいたい3GBのデータを挿入...


$ docker stop ....

$ cat <<EOF > Dockerfile
FROM mysql:8.0.34
COPY ./data /var/lib/mysql
EOF

$ docker build -t hoge .

$ hyperfine --warmup=3 \
    --prepare='docker stop db||true' -- \
    'docker run --rm -d -e MYSQL_ALLOW_EMPTY_PASSWORD=1 --name db -P hoge'
Benchmark 1: docker run --rm -d -e MYSQL_ALLOW_EMPTY_PASSWORD=1 --name db -P hoge
  Time (mean ± σ):      8.716 s ±  2.697 s    [User: 0.008 s, System: 0.014 s]
  Range (min … max):    6.480 s … 14.670 s    10 runs

大体 8 秒程度で起動できるようになりました。40 秒からかなり高速化できています。しかしながら、イメージサイズが大きくなるにつれて起動時間が増加することを確認できたため、いずれ同じ課題に直面してしまうことが考えられました。

とはいえ、データディレクトリをコピーするよりかなり速いことには変わりなく、このあたりにヒントがありそうでした。

OverlayFS

ヒントというか答えは OverlayFS でした。OverlayFS は Linux カーネル 3.18 で追加された複数のファイルシステムを 1 つにマージする仕組みで、Docker にも用いられています。OverlayFS では書き込み時に元のファイルをコピーしてくる(Copy on Write)ので、OverlayFS 作成時にはコピーのコストが乗って来ません。Docker コンテナは(ストレージドライバにもよりますが)OverlayFS による重ね合わせで実現されるため、単純にコピーするより速く起動できたということでした。さらに詳しい解説はDocker のドキュメントやその他の解説記事をご参照ください。

さて、この OverlayFS は通常mountコマンドで作成しますが、docker run時に--mountオプションを以下のように書けば OverlayFS の作成とマウントが同時に行えます。ちょっと複雑ですが…

$ docker run --rm -it --mount type=volume,dst=/tmp/hoge,volume-driver=local,volume-opt=type=overlay,\"volume-opt=o=lowerdir=${PWD}/lower,upperdir=${PWD}/upper,workdir=${PWD}/work\",volume-opt=device=overlay ubuntu

作成した Ubuntu コンテナ内でdfコマンドを実行し、マウントされた OverlayFS を確認してみます

$ df -h /tmp/hoge
Filesystem      Size  Used Avail Use% Mounted on
overlay        1007G   29G  928G   3% /tmp/hoge

OverlayFS をコンテナにマウントできることがわかったので、これを今回の課題に応用していきます。つまりホストマシンに用意したデータディレクトリを OverlayFS としてコンテナにマウントすればよいということです。データ入りコンテナと同じようにhyperfineでのベンチマークを取ってみます。

$ hyperfine --warmup=3 \
    --prepare 'docker stop db||true; sudo rm -rf ./upper ./work;mkdir ./upper ./work' -- \
    'docker run --rm -d -P --name db -e MYSQL_ALLOW_EMPTY_PASSWORD=1 --mount type=volume,dst=/var/lib/mysql,volume-driver=local,volume-opt=type=overlay,\"volume-opt=o=lowerdir=${PWD}/data,upperdir=${PWD}/upper,workdir=${PWD}/work\",volume-opt=device=overlay mysql:8.0.34'
Benchmark 1: docker run --rm -d -P --name db -e MYSQL_ALLOW_EMPTY_PASSWORD=1 --mount type=volume,dst=/var/lib/mysql,volume-driver=local,volume-opt=type=overlay,\"volume-opt=o=lowerdir=${PWD}/data,upperdir=${PWD}/upper,workdir=${PWD}/work\",volume-opt=device=overlay mysql:8.0.34
  Time (mean ± σ):     316.6 ms ±  38.3 ms    [User: 5.0 ms, System: 10.2 ms]
  Range (min … max):   271.5 ms … 392.3 ms    10 runs

300 ミリ秒程度でコンテナの起動が完了しています。40 秒から比べると 100 倍以上高速です。

mysqld が使えるまでの時間を調べる

Copy on Write(CoW)の影響が起動シーケンスにどれぐらい出るのかも調べてみます。今回は以下のようなシェルスクリプトとhyperfineで簡単なベンチマークを取ることで検証とします。

#!/usr/bin/env zsh

CONTAINER_NAME=db

function prepare-container-with-overlayfs() {
  docker stop "$CONTAINER_NAME" || true
  sudo rm -rf ./work ./upper
  mkdir ./work ./upper

  docker run --rm -d -p 3306:3306 \
    --name "$CONTAINER_NAME" \
    --mount type=volume,dst=/var/lib/mysql,volume-driver=local,volume-opt=type=overlay,\"volume-opt=o=lowerdir=${PWD}/data,upperdir=${PWD}/upper,workdir=${PWD}/work\",volume-opt=device=overlay \
    -e MYSQL_ALLOW_EMPTY_PASSWORD=1 \
    mysql:8.0.34
}

function prepare-container() {
  docker stop "$CONTAINER_NAME" || true
  docker run --rm -d -p 3306:3306 \
    --name "$CONTAINER_NAME" \
    -e MYSQL_ALLOW_EMPTY_PASSWORD=1 \
    hoge
}

function launch() {
  while ! docker exec "$CONTAINER_NAME" mysqladmin ping --silent; do; done
  while ! docker exec "$CONTAINER_NAME" mysql -e "SELECT 1" &> /dev/null; do; done
}

if [[ "$1" == "prepare-container-with-overlayfs" ]]; then
  prepare-container-with-overlayfs
elif [[ "$1" == "prepare-container" ]]; then
  prepare-container
elif [[ "$1" == "launch" ]]; then
  launch
else
  exit 1
fi

hogeイメージと./dataは以下の手順で作成しています

$ docker run -d --rm \
    -e MYSQL_ALLOW_EMPTY_PASSWORD=1 \
    -e MYSQL_DATABASE=test \
    -- name hoge \
    -v $PWD/data:/var/lib/mysql mysql:8.0.34

$ docker exec hoge mysql -e 'create database test'

$ sysbench /usr/share/sysbench/oltp_read_write.lua \
    --db-driver=mysql \
    --mysql-db=test \
    --mysql-user=root \
    --mysql-password="" \
    --mysql-host=127.0.0.1 \
    --mysql-port=3306 \
    --tables=7 \
    --table-size=1000000 prepare

$ docker stop hoge

$ cat <<EOF > Dockerfile
FROM mysql:8.0.34
COPY ./data /var/lib/mysql
EOF

$ docker build -t hoge .

実行結果は以下の通りです。

# データ入りのコンテナの場合
$ hyperfine --warmup=3 --prepare='./benchmark.zsh prepare-container' -- './benchmark.zsh launch'
  Time (mean ± σ):     918.3 ms ±  64.5 ms    [User: 158.4 ms, System: 142.4 ms]
  Range (min … max):   855.9 ms … 1049.1 ms    10 runs


# OverlayFSなデータディレクトリの場合
$ hyperfine --warmup=3 --prepare='./benchmark.zsh prepare-container-with-overlayfs' -- './benchmark.zsh launch'
  Time (mean ± σ):     935.5 ms ±  92.6 ms    [User: 165.7 ms, System: 174.3 ms]
  Range (min … max):   831.3 ms … 1149.7 ms    10 runs

20 ミリ秒程度の差があるようでした。OverlayFS なデータディレクトリの場合はmysqldの起動シーケンス中にほとんどのファイルで CoW が発生し、そのぶん時間がかかってしまうと思っていたのですが、20 ミリ秒ということであればそういうわけではなさそうです。

クエリを実行してみる

テスト用の DB を高速にするという課題は、OverlayFS なデータボリュームを使うことで解決できそうなことがわかりました。準備を自動で行うスクリプトを実装・配布、実際に利用してもらい、改善されたことが確認できました。

しかしながら、起動時の処理では CoW がほとんど発生していないことが個人的には気になっていました。 そこで、ここをもう少し追うことにしました。具体的には、起動直後のコンテナに対してsysbenchを流すことでコピーのコストが発生するかを確認してみます。CoW の動作を見たいので、oltp_write_only を使うこととします。ここからは趣味です。

まずはデータ入りのコンテナに対して実行したものを示します

$ sysbench /usr/share/sysbench/oltp_write_only.lua \
    --db-driver=mysql \
    --mysql-db=test \
    --mysql-user=root \
    --mysql-password="" \
    --mysql-host=127.0.0.1 \
    --mysql-port=3306 \
    --tables=7 \
    --table-size=1000000 run
sysbench 1.0.20 (using system LuaJIT 2.1.0-beta3)

Running the test with following options:
Number of threads: 1
Initializing random number generator from current time


Initializing worker threads...

Threads started!

SQL statistics:
    queries performed:
        read:                            0
        write:                           7164
        other:                           3582
        total:                           10746
    transactions:                        1791   (179.04 per sec.)
    queries:                             10746  (1074.25 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          10.0029s
    total number of events:              1791

Latency (ms):
         min:                                    2.58
         avg:                                    5.58
         max:                                   15.51
         95th percentile:                        9.91
         sum:                                 9999.11

Threads fairness:
    events (avg/stddev):           1791.0000/0.00
    execution time (avg/stddev):   9.9991/0.00

次に OverlayFS なデータディレクトリの場合です。

$ sysbench /usr/share/sysbench/oltp_write_only.lua \
    --db-driver=mysql \
    --mysql-db=test \
    --mysql-user=root \
    --mysql-password="" \
    --mysql-host=127.0.0.1 \
    --mysql-port=3306 \
    --tables=7 \
    --table-size=1000000 run
sysbench 1.0.20 (using system LuaJIT 2.1.0-beta3)

Running the test with following options:
Number of threads: 1
Initializing random number generator from current time


Initializing worker threads...

Threads started!

SQL statistics:
    queries performed:
        read:                            0
        write:                           5348
        other:                           2674
        total:                           8022
    transactions:                        1337   (133.68 per sec.)
    queries:                             8022   (802.11 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          10.0008s
    total number of events:              1337

Latency (ms):
         min:                                    2.86
         avg:                                    7.48
         max:                                 1651.00
         95th percentile:                        9.91
         sum:                                 9997.96

Threads fairness:
    events (avg/stddev):           1337.0000/0.00
    execution time (avg/stddev):   9.9980/0.00

注目したいのは Latency (ms)maxです。データ入りコンテナの場合は 15.51 ミリ秒 なのに対して、OverlayFS なデータディレクトリの場合は 1651.00 ミリ秒 となっています。そのほかの Latency の統計については特に差はありません。Write のどのタイミングで発生しているかは明確ではないですが、CoW のコストが Write に掛かっているように見えます。

CoW のコストがいつ乗ってくるのかを確認してみる

CoW の影響があるのは、書き込みクエリ実行時であることはなんとなく予想できたので、次はそのコストがいつ発生するのかを見ていきます。CoW の性質を考えると初回の書き込みが Commit されたときであるのは自明なのですが、気になったので調べます。

調べ方としては、以下のようなシェルスクリプトを OverlayFS なデータディレクトリを持つコンテナに対して実行するというものです。

for i ($(seq 10)); do
    s=$(date +%s%3N)
    docker exec db mysql -e "insert into test.sbtest1(k, c, pad) values(99999999, 'char', 'pad')"
    echo $i : $(($(date +%s%3N)-$s)) ms
done

sysbenchが作ったテーブルに対して 1 件のレコードを挿入することを 10 回繰り返しています。実行後は挿入にかかった時間をミリ秒で出力しています。 これを実行してみると以下のような結果が得られました。

1 : 384 ms
2 : 43 ms
3 : 45 ms
4 : 38 ms
5 : 38 ms
6 : 39 ms
7 : 39 ms
8 : 37 ms
9 : 38 ms
10 : 36 ms

1 回目だけ 10 倍程度遅いですね。ここに CoW のコストが乗っていると考えてよさそうです。

bpftrace で本当に 1 回目だけコピーが発生しているかを見てみる

はじめて書き込みを行ったときにコピーのコストが乗ってきているのはほぼそうだと言えそうなのですが、ここまで来たらカーネルのトレースをしてコピー系の関数が最初だけ呼ばれていることを確認したいと思ったのでやってみます。 今回これを確認するために使ったのは bpftrace/bpftraceという、awkと似た文法で書けるトレーシングツールです。詳しい解説は README やその他の解説記事などをご覧ください。

github.com

OverlayFS のヘッダファイルを見てみると、OverlayFS に関する関数は ovl_ で始まることが分かるので

$ bpftrace 'kprobe:ovl_* { printf("%s\n", func) }'

などとして OverlayFS で CoW が発生するとき、しないときの関数呼び出しを記録、両者を比較すると以下のような呼び出し順の違いがありました。因みにめちゃくちゃざっくりで、めちゃくちゃ端折っています

CoW なとき CoW じゃないとき
sys_enter_openat sys_enter_openat
ovl_open ovl_open
ovl_already_copied_up ovl_already_copied_up
ovl_already_copied_up
ovl_copy_up_start
ovl_copy_up_end
ovl_already_copied_up

これらの関数の呼び出しをトレースしてみます。トレースするのは以下のようなシェルスクリプトを実行する間です。内容としてはコンテナの起動とsbtest2テーブルへの書き込みを繰り返すものです。1 回目だけ CoW が発生するはずなので、その様子を確認します。

sudo rm -rf ./upper ./work
mkdir ./upper ./work

for i ($(seq 3)); do
    docker stop db
    sleep 10
    docker run --rm -d -p 3306:3306 \
        --name "$CONTAINER_NAME" \
        --mount type=volume,dst=/var/lib/mysql,volume-driver=local,volume-opt=type=overlay,\"volume-opt=o=lowerdir=${PWD}/data,upperdir=${PWD}/upper,workdir=${PWD}/work\",volume-opt=device=overlay \
        -e MYSQL_ALLOW_EMPTY_PASSWORD=1 \
        mysql:8.0.34
    sleep 10;
    s=$(date +%s%3N)
    docker exec db mysql -e "insert into test.sbtest2(k, c, pad) values($RANDOM, 'char', 'pad')"
    echo $i : $(($(date +%s%3N)-$s)) ms
done

docker stop db

bpftraceのコードは以下の通りです。

tracepoint:syscalls:sys_enter_openat /str(args->filename) == "./test/sbtest1.ibd" / {
    printf("elapsed: %ldms\tcomm: %s\tprobe: %s\tname: %s\tflags: %d\n", elapsed / 1_000_000, comm, probe, str(args->filename), args->flags)
}

kfunc:ovl_open {
  printf("elapsed: %ldms\tcomm: %s\tprobe: %s\tname: %s\n", elapsed / 1_000_000, comm, probe, str(args->file->f_path.dentry->d_name.name))
}

kfunc:ovl_copy_up_start, kfunc:ovl_copy_up_end {
  printf("elapsed: %ldms\tcomm: %s\tprobe: %s\tname: %s\n", elapsed / 1_000_000, comm, probe, str(args->dentry->d_name.name))
}

kretfunc:ovl_already_copied_up {
  printf("elapsed: %ldms\tcomm: %s\tprobe: %s\tname: %s\tretval: %d\n", elapsed / 1_000_000, comm, probe, str(args->dentry->d_name.name), retval)
}

シェルスクリプトの実行ログは以下の通りです。

Error response from daemon: No such container: db
8eefa5dec9b920fa2b483a32f86e4b90ac1089fd750fd2f3e6fd28efcc1a73d5
1 : 359 ms
db
0ba1c5ed2784922a515ff0ae1fd5d75dfcc2db0892b2c54f6ef5fbbc8c849992
2 : 44 ms
db
4da332ad30eb565dcb0ec91e67b4a705ec52c1592298180e66c23995ccb7c853
3 : 41 ms
db

トレースログは以下の通りです。

# sbtest2のイベントだけに注目する
# elapsed: 経過時間(ms)
# comm: タスク名。/proc/<pid>/comm の内容
# prove: プローブの名前。今回は呼び出された関数の名前ととらえてOK
# name: 関数の引数から取り出した操作対象のファイル名
# flags: ファイルのオープンモード
# retval: 関数の戻り値。今回は ovl_already_copied_up だけ出力させていて、この関数の戻り値はbool型
$ cat trace.log | grep sbtest2 | column -t
elapsed:  20757ms  comm:  boot         probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  20757ms  comm:  boot         probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  20757ms  comm:  boot         probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  0
elapsed:  20972ms  comm:  boot         probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  20972ms  comm:  boot         probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  20972ms  comm:  boot         probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  0
elapsed:  30413ms  comm:  connection   probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  30413ms  comm:  connection   probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  30413ms  comm:  connection   probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  0
elapsed:  30414ms  comm:  connection   probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   2
elapsed:  30414ms  comm:  connection   probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  30414ms  comm:  connection   probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  0
elapsed:  30414ms  comm:  connection   probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  0
elapsed:  30414ms  comm:  connection   probe:  kfunc:ovl_copy_up_start               name:  sbtest2.ibd
elapsed:  30729ms  comm:  connection   probe:  kfunc:ovl_copy_up_end                 name:  sbtest2.ibd
elapsed:  30729ms  comm:  connection   probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  42805ms  comm:  boot         probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  42805ms  comm:  boot         probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  42805ms  comm:  boot         probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  42925ms  comm:  boot         probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  42925ms  comm:  boot         probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  42925ms  comm:  boot         probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  42953ms  comm:  ib_buf_dump  probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  42953ms  comm:  ib_buf_dump  probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  42953ms  comm:  ib_buf_dump  probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  42953ms  comm:  ib_buf_dump  probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   2
elapsed:  42953ms  comm:  ib_buf_dump  probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  42953ms  comm:  ib_buf_dump  probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  64644ms  comm:  boot         probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  64644ms  comm:  boot         probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  64644ms  comm:  boot         probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  64764ms  comm:  boot         probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  64764ms  comm:  boot         probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  64764ms  comm:  boot         probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  65764ms  comm:  ib_src_main  probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   0
elapsed:  65764ms  comm:  ib_src_main  probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  65764ms  comm:  ib_src_main  probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1
elapsed:  65765ms  comm:  ib_src_main  probe:  tracepoint:syscalls:sys_enter_openat  name:  ./test/sbtest2.ibd  flags:   2
elapsed:  65765ms  comm:  ib_src_main  probe:  kfunc:ovl_open                        name:  sbtest2.ibd
elapsed:  65765ms  comm:  ib_src_main  probe:  kretfunc:ovl_already_copied_up        name:  sbtest2.ibd         retval:  1

1 回目だけcopy_up_startcopy_up_endが呼ばれており、その処理に 315 ミリ秒かかっていることがわかります。シェルスクリプトの 1 回目の実行時間は 359 ミリ秒なので、辻褄があっていそうです。 さらに 2 回目以降はcopy_up_startcopy_up_endの前のovl_already_copied_upが 1 を返しており、コピーアップ系の処理がスキップされているのがわかります。以上で無事 CoW の様子を観察することができました。 (ところでクエリ実行中の commconnectionib_buf_dumpib_src_mainだったりするのはなぜなんでしょう?)

まとめ

この記事では単体テストで利用する DB を高速に起動する方法として、OverlayFS を使った例を示しました。さらにbpftraceを使ったトレースを行い、OverlayFS の挙動の一部を観察、理解することができました。

単体テスト用 DB 高速起動の仕組みは、すでにチームには実験段階の機能として公開しており、使い心地などをフィードバックしてもらっている段階です。また何か進展があったら記事を書きたいと思います。

以上です。


モバファクでは中途採用・新卒採用ともに絶賛募集中です。
会社の情報については、モバファクブログでも発信しています。
技術好きな方、モバファクにご興味をお持ちの方は、ぜひご応募ください!
・モバファクブログ:https://corpcomn.mobilefactory.jp/
・採用サイト:https://recruit.mobilefactory.jp/