序

この記事は、以下の記事

のコメント欄で @angel_p_57 さんが記事主さんに聞かれていた質問

※補足ですが、ext3のファイルシステムではfsyncの使用は不要です。ext3デフォルトではfsync相当の動きになります。

流石にそれはないはずですが、どこからの情報でしょうか。
「デフォルトでfsync相当の動き」は、mountオプションsyncもしくは、個別のファイル属性(chattr(1)manページ参照)の'S'で設定されるものです。

に関して、調査した結果です。

1. 背景

1-1. 記事を書いた理由と想定読者

ext3やLinuxの前提知識が少ない人でもある程度読めるように記事にしてみました。LinuxでC/C++/pythonを使った開発をし始めた/できる程度の人を想定しています。カーネルコードを読める人にはかなり物足りない記事になります。が、件のコメント欄では誰にも伝わってる感じがしなかったので、改めて書いてみた次第です。私もそんな詳しくないので、詳しい方はご指摘等して頂けたらありがたいです。

2. 目的

ext3はfsync(2)が必要なのかどうかを調査し結論を出すこと

3. 調査の方法

10MiBの適当なファイルAを作成し、その中にext3を構築、ループマウントする
マウントしたところにファイルを作成し、色々なタイミング(B)でAのコピーをしてスナップショットを取る
各スナップショットをマウントして中身を確認する
各スナップショットをマウントせずに直接解析するソフト(C)を使用し、中身を確認する

※通常スナップショットはコピーで取るものではないのですが、他に手段もなく、サイズも小さいのでこういう手段にしています

(B)のタイミングは以下の10種類

write(2)で4KiB書き込みを1回行ってプロセス終了した後
write(2)で4KiB書き込みを1回行い6秒sleepし(※1)プロセス終了した後
write(2)で4KiB書き込みを1回行い31秒sleepし(※2)プロセス終了した後
write(2)で4KiB書き込みを1回行いfsync(2)しプロセス終了した後
write(2)で4KiB書き込みを1回行いfsync(2)して6秒sleepし(※1)プロセス終了した後
write(2)で4KiB書き込みを1回行いsyncfs(2)しプロセス終了した後
write(2)で4KiB書き込みを1回行いsync(2)しプロセス終了した後
上記の後umountした後(計7回)

(※1)6秒の理由はext3マウント時のcommitオプションがデフォルトで5だからです
(※2)31秒の理由はカーネルパラメータのvm.dirty_expire_centisecsがデフォルトで3000だからです

(C)のソフトは以下の3種類

dumpe2fs(Ubuntuでは標準装備)
debugfs(Ubuntuでは標準装備)

今回はここまでです。

4. 準備

Ubuntu 24.04前提で準備するものを記述します。

4-1. パッケージインストール

$ sudo apt install build-essential

4KiB書き込み用プログラムのビルドにg++が必要なので。あまり入ってない人もいないと思いますが…

4-2. 4KiB書き込み用プログラム

これは実行用スクリプトに同梱されています。が、内容だけ説明しておきます。

C++でファイルに4KiB書き込むとなると、普通はC/C++の標準ライブラリを使って、Cならfwrite(3)、C++ならstd::ofstreamなどを使用するのですが、今回確認したいのはシステムコールのfsync(2)なので、標準関数より低レベルなシステムコールopen(2)/close(2)/write(2)を使います。

ソースコード(押すと開きます)

tmp/test.cpp

#include <fcntl.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <unistd.h>

#include <cstdio>
#include <string>

const size_t BUFFER_SIZE = 4096;
const size_t FILE_SIZE = 4 * 1024;  // 4KiB

char buffer[BUFFER_SIZE] = {};

int main(int argc, char *argv[]) {
  int fd = open("mnt/dummy", O_CREAT | O_WRONLY | O_TRUNC, 0666);
  if (fd == -1) {
    std::perror(argv[0]);
    return 1;
  }
  for (size_t i = 0; i < static_cast<size_t>(FILE_SIZE / BUFFER_SIZE); ++i) {
    int r = write(fd, buffer, BUFFER_SIZE);
    if (r != BUFFER_SIZE) {
      std::perror(argv[0]);
      return 1;
    }
  }
  if (argc > 1) {
    std::string arg1(argv[1]);
    int r = 0;
    if ((arg1 == "--fsync") || (arg1 == "--fsync6")) {
      r = fsync(fd);
    } else if (arg1 == "--syncfs") {
      r = syncfs(fd);
    }
    if (r == -1) {
      std::perror(argv[0]);
      return 1;
    }
    close(fd);
    if (arg1 == "--sleep") {
      sleep(6);
    } else if (arg1 == "--sleep31") {
      sleep(31);
    } else if (arg1 == "--fsync6") {
      sleep(6);
    } else if (arg1 == "--sync") {
      sync();
    }
  } else {
    close(fd);
  }
  return 0;
}

4KiBの0データをdummyファイルに書き込んで、オプションにより7パターンの動作をして終了するだけのプログラムです。

引数	動作パターン
引数なし	何もしない
--sleep	sleep(6)
--sleep31	sleep(31)
--fsync	fsync(fd)
--fsync6	fsync(fd)とsleep(6)
--syncfs	syncfs(fd)
--sync	sync()

これらの引数により、方法の章で書いたパターンを実施します。

4-3. 実行用スクリプト

上のtest.cppを使って、方法の章で書いたパターンを実施するスクリプトです。

ソースコード(押すと開きます)

test.cppを内包してるのでやや長めです。

test.sh

set -eux
do_umount() {
    sudo sync
    sudo sync
    sudo sync
    while ! sudo umount $*; do
        sleep 1
    done
}
do_test() {
    cp -p loopdisk.img.org loopdisk.img
    sudo mount ./loopdisk.img -o loop ./mnt
    sudo ./test $2
    ls -lai mnt/ | sed '/ \.\.$/d' >$1.ls.0.log
    cp -p loopdisk.img loopdisk.img.$1.snapshot1
    do_umount mnt
    mv loopdisk.img loopdisk.img.$1.snapshot2
    cp -p loopdisk.img.$1.snapshot1 loopdisk.img
    sudo mount ./loopdisk.img -o loop ./mnt
    cp -p loopdisk.img loopdisk.img.$1.snapshot3
    do_umount mnt
    for ss in 1 2 3;do
        cp -p loopdisk.img.$1.snapshot$ss loopdisk.img
        sudo mount ./loopdisk.img -o loop ./mnt
        ls -lai mnt/ | sed '/ \.\.$/d' >$1.ls.$ss.log
        do_umount mnt
    done
}

if [ -e tmp ]; then
    echo "tmp is already exist."
    return 1
fi

sudo true

mkdir tmp
cd tmp
mkdir mnt
dd if=/dev/zero of=loopdisk.img.org bs=1MiB count=10
mkfs.ext3 ./loopdisk.img.org

cat >test.cpp <<EOF
#include <fcntl.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <unistd.h>

#include <cstdio>
#include <string>

const size_t BUFFER_SIZE = 4096;
const size_t FILE_SIZE = 4 * 1024;  // 4KiB

char buffer[BUFFER_SIZE] = {};

int main(int argc, char *argv[]) {
  int fd = open("mnt/dummy", O_CREAT | O_WRONLY | O_TRUNC, 0666);
  if (fd == -1) {
    std::perror(argv[0]);
    return 1;
  }
  for (size_t i = 0; i < static_cast<size_t>(FILE_SIZE / BUFFER_SIZE); ++i) {
    int r = write(fd, buffer, BUFFER_SIZE);
    if (r != BUFFER_SIZE) {
      std::perror(argv[0]);
      return 1;
    }
  }
  if (argc > 1) {
    std::string arg1(argv[1]);
    int r = 0;
    if ((arg1 == "--fsync") || (arg1 == "--fsync6")) {
      r = fsync(fd);
    } else if (arg1 == "--syncfs") {
      r = syncfs(fd);
    }
    if (r == -1) {
      std::perror(argv[0]);
      return 1;
    }
    close(fd);
    if (arg1 == "--sleep") {
      sleep(6);
    } else if (arg1 == "--sleep31") {
      sleep(31);
    } else if (arg1 == "--fsync6") {
      sleep(6);
    } else if (arg1 == "--sync") {
      sync();
    }
  } else {
    close(fd);
  }
  return 0;
}
EOF
g++ -g -Wall -pedantic -std=c++17 test.cpp -o test

do_test case1 "" 2>&1 >case1.log
do_test case2 "--sleep" 2>&1 >case2.log
do_test case2a "--sleep31" 2>&1 >case2a.log
do_test case3 "--fsync" 2>&1 >case3.log
do_test case3a "--fsync6" 2>&1 >case3a.log
do_test case4 "--syncfs" 2>&1 >case4.log
do_test case5 "--sync" 2>&1 >case5.log

for f in loopdisk.img*; do
    dumpe2fs $f 2>&1 > $f.dumpe2fs.log
    sed '/time/d;/^Last mounted on:/d;/^Mount count:/d' $f.dumpe2fs.log > $f.dumpe2fs.notime.log
    debugfs -R 'logdump -a' $f 2>&1 > $f.logdump_not_committed.log;
    debugfs -R 'logdump -Oa' $f 2>&1 > $f.logdump_all.log;
    debugfs -R 'ls -l /' $f 2>&1 > $f.ls.log
done

それほど説明が必要な部分はないと思いますが、少しだけ

dumpe2fsのログを出力した後、sedで結果をフィルタしているのは時間やマウント回数などdiffを取る際に邪魔な部分を消したいからです
debugfsの最初の行はメタデータのディスク反映が終わっていないジャーナルの情報を抽出しています
debugfsの2番目の行はディスク反映済含めて残っている全ジャーナルの情報を抽出しています
debugfsの3番目の行はマウントしたディスクの/をlsした結果を抽出しています
mountにはmount -o loopを使っていますが、こうした場合losetup --direct-io=offと同等になり、マウントしたファイルシステムへの読み書きに1枚、ループ対象のファイルへの読み書きにもう1枚、計2枚のページキャッシュが使用されます。実際スナップショットを取る際のコピーは2枚目のページキャッシュからになるでしょう。

実行すると分かりますが、このスクリプトは結果がバラついてあまり再現性がありません。そのため測定が1度だけでは意味がなく、繰り返し実行して頻度を調べる必要があります。今回は各ケース200回実行させたこともあり、目視確認を嫌って出力自動解析までコードに入れたのでちょっと長くなってしまいました。これらは記事の末尾に全コードまとめて置いてあります。以下はそのトップレベルのスクリプトです。

ソースコード(押すと開きます)

all.sh

set -eux
if [ $# -gt 0 ]; then
    count=$1
else
    count=200
fi
logdir=logs
mkdir -p $logdir
for i in $(seq $count); do
    s=$(date +%+4Y%m%d%H%M%S)
    sh test.sh
    mkdir -p "$logdir/$s"
    mv tmp/*.log "$logdir/$s/"
    rm -rf tmp
    sudo sync
done
lsdir=ls
dumpe2fsdir=dumpe2fs
debugfsdir=debugfs
sh ls_diff.sh $logdir $lsdir
sh dumpe2fs_diff.sh $logdir $dumpe2fsdir
sh debugfs_diff.sh $logdir $debugfsdir
sh report.sh $logdir $lsdir $dumpe2fsdir $debugfsdir

python=python3
cat $logdir/ls_report.txt | $python qiita_ls.py
cat $logdir/dumpe2fs_report.txt | $python qiita_dumpe2fs.py
cat $logdir/debugfs_ls_report.txt | $python qiita_debugfs_ls.py
cat $logdir/debugfs_log_report.txt | $python qiita_debugfs_log.py

5. 調査の実施と結果

5-1. スクリプトを実行

sh all.sh [試行回数]で実行します。

5-2. lsの結果を確認

以下のタイミングで取得したスナップショットイメージをマウントし、test.cppを実行した直後のlsの結果と比較しています。

umount直前に取得したsnapshot1
umount直後に取得したsnapshot2
snapshot1を再マウントして取得したsnapshot3

私の環境で集計した結果は以下のとおりです。

5-2-1. /dummyの差分

スナップショット	引数なし	sleep(6)	sleep(31)	fsync	fsync+sleep(6)	syncfs	sync
snapshot1	差分あり	差分なし(73.0%) 差分あり(27.0%)	差分なし	差分なし	差分なし	差分なし	差分なし
snapshot2	差分なし	差分なし	差分なし	差分なし	差分なし	差分なし	差分なし
snapshot3	差分あり	差分なし(73.0%) 差分あり(27.0%)	差分なし	差分なし	差分なし	差分なし	差分なし

5-2-2. /の差分

スナップショット	引数なし	sleep(6)	sleep(31)	fsync	fsync+sleep(6)	syncfs	sync
snapshot1	差分なし(98.5%) 差分あり(1.5%)	差分なし(97.0%) 差分あり(3.0%)	差分なし	差分なし	差分なし	差分なし	差分なし
snapshot2	差分なし	差分なし	差分なし	差分なし	差分なし	差分なし	差分なし
snapshot3	差分なし(98.5%) 差分あり(1.5%)	差分なし(97.0%) 差分あり(3.0%)	差分なし	差分なし	差分なし	差分なし	差分なし

5-2-3. ポイント

ここで注目すべきは、fsyncなどがなく、sleepもしていないケースでのsnapshotでは/dummyに差分がある、つまりファイル/dummyが存在していないということです。そして、6秒待っているケースでは73%の確率でファイル/dummyが存在していて、31秒待っているケースでは100%の確率でファイル/dummyが存在、fsync/syncfd/syncを呼んでいるケースでも100%存在しているという点です。つまり、ext3では書き込み(open→write→close)後、マウントオプションcommitのデフォルト値5秒以上待っていても、ファイルに書き込まれている保証がないということです。そしてvm.dirty_expire_centisecsのデフォルト値30秒以上待っていると書き込まれています。意味するところは明確ではありませんが、理由はいくつか推測も出来ます。しかし実験の結果からは私の環境ではRHEL7で言及されているような楽観的な仕様

By default, ext3 automatically forces newly created files to disk almost immediately even without fsync()

ではないように見えます。

/側にあまり差分がない理由はよく分かりません。

5-3. dumpe2fsのログを比較

dumpe2fsから取得できるいくつかの属性に違いが検出されます。比較の対象は初期状態(mkfs直後)と各スナップショットになります。あとついでに初期状態のブロック情報が出ているのでそれもリストアップしておきます。

5-3-1. 初期状態のブロック種別

tmp/loopdisk.img.org.dumpe2fs.log から得られる情報になります。

ブロックグループは0のみ

ブロック番号	タイプ
0	Primary superblock
1	Group descriptors
2	Block bitmap
3	Inode bitmap
4	Inode table

5-3-2. umount直前(snapshot1)

属性	引数なし	sleep(6)	sleep(31)	fsync	fsync+sleep(6)	syncfs	sync
Filesystem features(needs_recovery)	+	+	+	+	+	+	+
Journal sequence	-	0x00000002	0x00000002	0x00000002	0x00000002	0x00000002	0x00000002
増加ブロック	-	-	1195(61.0%) -(39.0%)	-	1195(59.0%) -(41.0%)	1195	1195
増加inode	-	-	12(61.0%) -(39.0%)	-	12(59.0%) -(41.0%)	12	12

5-3-3. umount直後(snapshot2)

属性	引数なし	sleep(6)	sleep(31)	fsync	fsync+sleep(6)	syncfs	sync
Filesystem features(needs_recovery)	-	-	-	-	-	-	-
Journal sequence	0x00000004	0x00000004(23.0%) 0x00000005(77.0%)	0x00000004(0.5%) 0x00000005(99.5%)	0x00000005	0x00000005	0x00000005	0x00000005
増加ブロック	1195(99.5%) 1536(0.5%)	1195	1195	1195	1195	1195	1195
増加inode	12	12	12	12	12	12	12

5-3-4. ポイント

umount直前で注目すべき点は、通常/sleep6秒/sleep31秒/fsync/fsync+sleep6秒でinodeが増加していないケースがあること。inodeが増加していないということはdummyファイルが存在しないことを意味しています。

しかしlsの結果(/dummyのsnapshot1)からは、再mount時これらのケースのうちsleep31秒/fsync/fsync+sleep6秒では100%、sleep6秒でも73%でinodeが出来ており、/dummyファイルが復元されていました。これらは、再マウント時にリカバリが機能していることを示唆しています。

umount直前ではfsyncのinode増加は100%になっておらず、syncfs/syncだと100%になっているのは、sync/syncfsがファイルシステム単位のsyncであり、メタデータのsyncも同時に行っているからではないかと推測しています。

umount直後ではJournal sequenceにも4になるものと5になるものが出ていまずが、ここでは気にしないことにします。また増加ブロックにもわずかな差異が発生していますが、これも無視します。増加ブロックの1195,1536は後で調べていて、1195が/dummyの実データ保管ブロックであることが分かっています。1536はレアケースなので調べていませんが、恐らく同じです。

5-4. debugfsのログを比較

debugfsを使うことにより、mount前のsnapshotを解析して状態を取得することが出来ます。ここではdumpe2fsのときと同様に初期状態のイメージと各snapshotを比較した結果を見ていきます。

5-4-1. lsの差分をチェック

debugfsがlsのようなことをエミュレーションしてくれる機能の出力をチェックした結果です。

5-4-1-1. umount直前(snapshot1)

ケース	/dummy	/
引数なし	差分なし	差分なし
sleep(6)	差分なし	差分なし
sleep(31)	差分なし(39.0%) 差分あり(61.0%)	差分なし(78.5%) 差分あり(21.5%)
fsync	差分なし	差分なし
fsync+sleep(6)	差分なし(41.0%) 差分あり(59.0%)	差分なし(41.0%) 差分あり(59.0%)
syncfs	差分あり	差分あり
sync	差分あり	差分あり

5-4-1-2. umount直後(snapshot2)

ケース	/dummy	/
引数なし	差分あり	差分なし(98.5%) 差分あり(1.5%)
sleep(6)	差分あり	差分なし(86.0%) 差分あり(14.0%)
sleep(31)	差分あり	差分なし(64.0%) 差分あり(36.0%)
fsync	差分あり	差分なし(2.5%) 差分あり(97.5%)
fsync+sleep(6)	差分あり	差分あり
syncfs	差分あり	差分あり
sync	差分あり	差分あり

5-4-1-3. snapshot1の再mount直後(snapshot3)

ケース	/dummy	/
引数なし	差分なし	差分なし
sleep(6)	差分なし(27.0%) 差分あり(73.0%)	差分なし(89.0%) 差分あり(11.0%)
sleep(31)	差分あり	差分なし(64.0%) 差分あり(36.0%)
fsync	差分あり	差分なし(2.5%) 差分あり(97.5%)
fsync+sleep(6)	差分あり	差分あり
syncfs	差分あり	差分あり
sync	差分あり	差分あり

5-4-1-4. ポイント

umount直前のスナップショットを直接解析することにより、fsyncを入れるケースで/dummyファイルが作成されていないことがより明確に示されています。対照的にsyncfs/syncは再マウント前に全てが書き込まれていることが分かります。ただし、fsyncを使用した場合でも、再マウントしたときには普通にumountした直後のスナップショットと同じデータに復元しているので、ジャーナルへの書き込みは終わっていることを示しており、sleep6秒/31秒したケースでも73%以上が同じデータに復元出来ている点は興味深いところです。

5-4-2. transaction logの差分をチェック

debugfsがtransaction log、つまりjournalを解析した差分をチェックしたものです。{}がトランザクションを示していて、Cがついているものは直前のトランザクションがコミットされています。{}内の数字はブロックを示しています。Cがついているところまでが復元される対象になります。

5-4-2-1. umount直前(snapshot1)

ケース	all	not_committed
引数なし	-	-
sleep(6)	{3,1,4,164,0,2},C(73.0%) {3,1,4,164,0,2}(27.0%)	{3,1,4,164,0,2},C(73.0%) {3,1,4,164,0,2}(27.0%)
sleep(31)	{4,3,1,164,0,2},C(0.5%) {3,1,4,164,0,2},C(99.5%)	{4,3,1,164,0,2},C(0.5%) {3,1,4,164,0,2},C(99.5%)
fsync	{3,1,4,164,0,2},C	{3,1,4,164,0,2},C
fsync+sleep(6)	{3,1,4,164,0,2},C	{3,1,4,164,0,2},C
syncfs	{3,1,4,164,0,2},C	{3,1,4,164,0,2},C
sync	{3,1,4,164,0,2},C	{3,1,4,164,0,2},C

5-4-2-2. umount直後(snapshot2)

ケース	all	not_committed
引数なし	{3,1,4,164,0,2},C	-
sleep(6)	{3,1,4,164,0,2},C(23.0%) {3,1,4,164,0,2},C,{4},C(77.0%)	-
sleep(31)	{4,3,1,164,0,2},C(0.5%) {3,1,4,164,0,2},C,{4},C(99.5%)	-
fsync	{3,1,4,164,0,2},C,{4},C	-
fsync+sleep(6)	{3,1,4,164,0,2},C,{4},C	-
syncfs	{3,1,4,164,0,2},C,{4},C	-
sync	{3,1,4,164,0,2},C,{4},C	-

5-4-2-3. snapshot1の再マウント直後(snapshot3)

ケース	all	not_committed
sleep(6)	{3,1,4,164,0,2},C(73.0%) {3,1,4,164,0,2}(27.0%)	-
sleep(31)	{4,3,1,164,0,2},C(0.5%) {3,1,4,164,0,2},C(99.5%)	-
fsync	{3,1,4,164,0,2},C	-
fsync+sleep(6)	{3,1,4,164,0,2},C	-
syncfs	{3,1,4,164,0,2},C	-
sync	{3,1,4,164,0,2},C	-

5-4-2-4. ポイント

トランザクション内の対象ブロックは最初にdumpe2fsの結果を見たときに0〜4までは一覧だけしましたが、今回は一応意味も少しだけ記述しておきます。

0はスーパーブロックで最初からあるやつです
1はブロックグループ0のデスクリプタが保管されています

今回は小さいファイルシステムなので、ブロックグループやスーパーブロックは複数出てきません。なので、0,1は無視します。

2,3はグループ0内の、ブロックとinodeの確保/未確保ビットマップです

これらはブロックやinodeを新たに確保したり削除したりしない限り変更されません。今回の操作では/dummyを作成するときにブロックやinodeが必要なので変更が入ります。

4はinodeテーブルです

各ファイル(ディレクトリなども含む)自体の基本属性(inode)を格納している固定長レコードの配列です。各ファイルのinode番号やブロック番号は以下の方法で確認できます。

$ debugfs -R 'blocks /' tmp/loopdisk.img.case3.snapshot3
debugfs 1.47.0 (5-Feb-2023)
164 
$ debugfs -R 'blocks /dummy' tmp/loopdisk.img.case3.snapshot3
debugfs 1.47.0 (5-Feb-2023)
1195 
$ debugfs -R 'icheck 164' tmp/loopdisk.img.case3.snapshot3
debugfs 1.47.0 (5-Feb-2023)
Block	Inode number
164	2
$ debugfs -R 'icheck 1195' tmp/loopdisk.img.case3.snapshot3
debugfs 1.47.0 (5-Feb-2023)
Block	Inode number
1195	12

つまり各トランザクションで記述されているブロックは0〜4の始めからあるブロックと、/のディレクトリエントリを保管しているブロック164だったことが分かります。/dummyの実データが保管されているブロック1195には触れられていません。以上から現設定のext3のジャーナルにはメタデータしか含まれていないことが確認できました。

そして記録されているパターンとしては、3,1,4で始まるトランザクションと4,3,1で始まるトランザクションがあることが分かっています。1は無視するので、違いは3,4と4,3の順番だけになります。3はinodeの確保用bitmapだし、4はinodeテーブルなので、両方書き込まれないと意味がなく、トランザクションでもあり、この順番は重要でないと考えます。

他のパターンとしては、2つ目のトランザクションとして4だけ追加で書き込まれるパターンがありましたが、これは恐らく、/の最終更新時間など属性の更新が必要になったケースではないかと推測しています。しかし裏は取れていません。

これらのトランザクションはブロック1195が書き込まれた後である必要があり、fsyncではトランザクションの書き込みまで行うが、メタデータの書き込みまでは待たず、syncfsやsyncではメタデータの書き込みまで待つことになる、と考えると全ての辻褄が合うのではないかと考えています。

5-5. 結果まとめ

ここまでのポイントから

open→write→closeだけの実施では、データは即時ファイルシステムに書き込まれているわけではない
ext3ではデータの書き込み後5秒(デフォルト)でcommitするように設計されているが、close後6秒待っても書き込まれていないケースがあった
ext3ではデータの書き込み後fsyncすると即時commitされるように見え、commitされる場合は再マウント時リカバリでメタデータが書き込まれる
ページキャッシュの書き込みタイミングは30秒(デフォルト)以内になるが、close後31秒待てばfsyncせずとも書き込まれる

ことが分かっています。以上からext3は書き込み後5秒待っても100%fsync不要とは言えないという結果になりました。

6. 考察

5秒の件が正確に何を指しているのか
本体データ、ジャーナル、メタデータの書き込みタイミング

が、最後まで分かりませんでした。これらはカーネルコードに仕込みを入れて実際にログを追ってみないと分かりません。ただその前に5秒や30秒だけでなく、それらの情報の書き込み時間の正確な分布が現象ベースで欲しいと思います。

また、今回は10MiBのファイルシステムに4KiBのファイルを作ってるだけですが、作成するファイルの大きさに対してどういう分布の変化をするのかも知りたいところです。

7. まとめ

今回の調査結果からは、

ext3は書き込み後5秒待っても100%fsync不要とは言えない

という結論になった。

付録

用語集

ext3

Linuxで使われていたファイルシステムの1つです。この系譜で現在使われているのはext4で、ext4は2025年1月現在恐らくLinuxで一番標準的なファイルシステムです。ext2というジャーナルのないシンプルなファイルシステムにジャーナルを追加して耐久性を上げたのがext3というのが私の理解です。

ファイルシステム

Linuxでは/で始まる階層構造に割り振られたファイルを管理するためのシステムです。何をファイルとして扱うかはOSに依りますが、多くはデータファイルであることが多く、フラットなデータ領域をいかにして階層を持ったファイル(データ)集合として扱うか、つまりフォーマットをどうするかの仕様とも言えます。連続データであればメモリ上でも1ファイルの中にもファイルシステムは構築可能です。一般的にOSが直に使うものなので、ドライバで実装されるのが普通です。LinuxではVFS APIを実装したドライバを書けば、新しいファイルシステムを実装できます。

ジャーナル

ファイルシステムの文脈で出てくるジャーナルとは、トランザクションログのことです。データベースに詳しい人はこの言葉だけでもうピンと来てると思います。

ファイルを書いたり編集したりする操作をジャーナルに記録していき、コミットした時点でその操作を確定するために使用します。コミット前までの操作は確定していないので、内容が保証されません。例えばファイルを書き込み中にUPS未使用のLinuxで急にコンセントを抜いたとき、再起動後にコミット後の書き込みは復旧できないという意味です(雷による停電だとそもそもディスクが壊れてたりして保証できませんが…)。

本記事で扱うのはext3ですが、今は実装がext4ドライバに含まれており、資料もext4のものになりますが、私が知る限り一番詳しい資料は以下になります。

ext2

先に書いたとおりシンプルなファイルシステムです。ext2はまず全体をブロックという単位に分け、それをいくつかの種類に分類して管理しています。詳細は面倒なので英語版のext2 wikipediaに任せます。一番詳しい資料は以下になります。

ページキャッシュ

Linuxカーネル2.4未満にあったバッファキャッシュが現在どうなってるのか(メタデータをどう扱っているのか)よく知らないですが、バッファキャッシュはページキャッシュと同じであるとして書いています。この不明点は今現在も私が結論を明確に出せない理由の一つになっています。

ファイルからデータを読み取ったり、ファイルにデータを書き込んだりするとき、Linuxカーネルでは一旦カーネル内のメモリ領域に書き込んでからユーザーのプログラムに渡したり、ディスクに書き込んだりしています。このメモリ領域をページキャッシュと言います。ディスクへの書き込みはpdflush(Dirty Page FLUSH)というカーネルスレッドが担当していて、カーネルパラメータにより若干動作を変えます。pdflushによるディスクへの書き込みは小さなファイルなら一般的にユーザープログラムがclose(2)した後行われる動作になります。書き込んだファイルをユーザープログラムが読むとページキャッシュから読まれるのでディスクまで書き込まれてるように見えるのですが、実際にはユーザープログラムが終了した後でもpdflushによるディスクへの書き込みが行われていなければディスクには書き込まれていません。

正直ユーザープログラムから見た内容まで解説してるカーネル側の資料は見当たらず、カーネル側から見た、ちょっと古いけどそこそこ読みやすい資料は以下になります。

fsync

ファイル単位でページキャッシュのフラッシュをしてくれるシステムコールです。詳細はman 2 fsyncで見てください。

sync

sync(2)/syncfs(2)はファイルシステム単位でページキャッシュのフラッシュをしてくれるシステムコールです。sync(2)は対象を選べず全てになります。詳細はman 1 sync、man 2 syncfs、man 2 syncで見てください。

ループマウント

通常mountコマンドはブロックデバイスを指定してそれを指定のマウントポイントにマウントするのですが、ブロックデバイスの代わりに普通のファイルを指定してmountすると、ループマウントと呼ばれます。このマウントにはループデバイスが必要となります。Linuxではmountオプションにloop指定を入れるだけでループマウントでき、ループデバイスが自動で割り当てられます。ループマウントをすると、そのファイルシステムの内容は全て指定された普通のファイルに記録されます。

詳細(?)は以下を見てください。

ext3のマウントオプションcommit

ジャーナルのコミット間隔を秒数で指定します。デフォルトは5秒です。詳細はman 5 ext3で見てください。

カーネルパラメータ dirty_expire_centisecs

sysctlコマンドで設定したり出来るカーネルパラメータのvm.dirty_expire_centisecsです。ページキャッシュに書き込んでからの経過時間がこれを過ぎるとディスクへ書き込むべき状態になります(条件の1つで、他の条件でも同じ状態になります)。デフォルトは30秒です。

詳細は各カーネルバージョンのドキュメントを見てください。私が使っている6.8.0-51のドキュメントは以下です。

dumpe2fs

ext2～4ファイルシステム用のdumpツールです。といってもrestoreできるようなものではありません。ただの診断ツールで大雑把な情報を教えてくれます。今回は各スナップショットから情報を取り出して、主にブロック情報とiノードを比較するために使っています。

詳細はman dumpe2fsで見てください。

debugfs

dumpe2fsと似たようなext2～4ファイルシステム用のdebugツールです。dumpe2fsよりは細かい情報を出力でき、書き込んだりも出来るようになっているinteractiveな使い方のツールです。今回は各スナップショットから情報を取り出して、主にジャーナルの情報とディレクトリ走査情報を比較するために使っています。

詳細はman debugfsで見てください。

全スクリプト

Ubuntu 22.04/24.04用環境構築スクリプトです(測定はしません)。tarアーカイブの代わりです。

ファイル	説明
all.sh	測定実行スクリプト。引数で測定回数指定(デフォルト200回)
test.sh	実際の測定用スクリプト1回分
classify.sh	ケース分類用ライブラリ
ls_diff.sh	test.shの出力のうち、lsの結果から差分抽出するスクリプト
dumpe2fs_diff.sh	test.shの出力のうち、dumpe2fsの結果から差分抽出するスクリプト
debugfs_diff.sh	test.shの出力のうち、debugfsの結果から差分抽出するスクリプト
report.sh	各抽出された差分を目視確認しやすい結果に整形するスクリプト
qiita_base_ls.py	複数のスクリプトから抽出された共通部分
qiita_ls.py	report.shが出力した結果のうちls分を解析しQiitaの表形式にするスクリプト
qiita_dumpe2fs.py	report.shが出力した結果のうちdumpe2fs分を解析しQiitaの表形式にするスクリプト
qiita_debugfs_ls.py	report.shが出力した結果のうちdebugfsのls分を解析しQiitaの表形式にするスクリプト
qiita_debugfs_log.py	report.shが出力した結果のうちdebugfsのログ分を解析しQiitaの表形式にするスクリプト

ソースコード(押すと開きます)

create_env.sh

cat >all.sh <<CREATE_ENV_EOF
set -eux
if [ \$# -gt 0 ]; then
    count=\$1
else
    count=200
fi
logdir=logs
mkdir -p \$logdir
for i in \$(seq \$count); do
    s=\$(date +%+4Y%m%d%H%M%S)
    sh test.sh
    mkdir -p "\$logdir/\$s"
    mv tmp/*.log "\$logdir/\$s/"
    rm -rf tmp
    sudo sync
done
lsdir=ls
dumpe2fsdir=dumpe2fs
debugfsdir=debugfs
sh ls_diff.sh \$logdir \$lsdir
sh dumpe2fs_diff.sh \$logdir \$dumpe2fsdir
sh debugfs_diff.sh \$logdir \$debugfsdir
sh report.sh \$logdir \$lsdir \$dumpe2fsdir \$debugfsdir

python=python3
cat \$logdir/ls_report.txt | \$python qiita_ls.py
cat \$logdir/dumpe2fs_report.txt | \$python qiita_dumpe2fs.py
cat \$logdir/debugfs_ls_report.txt | \$python qiita_debugfs_ls.py
cat \$logdir/debugfs_log_report.txt | \$python qiita_debugfs_log.py
CREATE_ENV_EOF
cat >classify.sh <<CREATE_ENV_EOF
classify() {
    classify_files=\$*
    classify_caseno=0
    for classify_f in \$classify_files;do
        if [ -e \$classify_f ];then
            classify_caseno=\$(expr \$classify_caseno + 1)
            mkdir "case\$classify_caseno"
            mv \$classify_f "case\$classify_caseno/"
            classify_h="case\$classify_caseno/\$(basename \$classify_f)"
            if [ ! -e \$classify_h ]; then
                exit 1
            fi
            for classify_g in \$classify_files;do
                if [ -e \$classify_g ];then
                    if cmp \$classify_h \$classify_g; then
                        mv \$classify_g "case\$classify_caseno/"
                    fi
                fi
            done
        fi
    done
}
CREATE_ENV_EOF
cat >debugfs_diff.sh <<CREATE_ENV_EOF
. ./classify.sh

logdir=\$1
tooldir=\$2

for d in \$logdir/20*;do
    echo \$d
    cd \$d
    d=\$(basename \$d)
    for ss in 1 2 3;do
        for c in 1 2 2a 3 3a 4 5;do
            for logtype in logdump_all logdump_not_committed ls;do
                diff loopdisk.img.org.\$logtype.log loopdisk.img.case\$c.snapshot\$ss.\$logtype.log | sed 's/[0-9]*-[A-Za-z]*-\\([0-9]*\\) [0-9]*:[0-9]*/\\1/' >../debugfs.\$d.case\$c.snapshot\$ss.\$logtype.diff
            done
        done
    done
    cd ../..
done

mkdir -p \$logdir/\$tooldir/log
cd \$logdir/\$tooldir/log
for ss in 1 2 3;do
    mkdir snapshot\$ss
    cd snapshot\$ss
    for c in 1 2 2a 3 3a 4 5;do
        mkdir case\$c
        cd case\$c
        for logtype in logdump_all logdump_not_committed;do
            mkdir \$logtype
            cd \$logtype
            classify ../../../../../debugfs.*.case\$c.snapshot\$ss.\$logtype.diff
            cd ..
        done
        cd ..
    done
    cd ..
done
cd ../../..
mkdir -p \$logdir/\$tooldir/ls
cd \$logdir/\$tooldir/ls
for ss in 1 2 3;do
    mkdir snapshot\$ss
    cd snapshot\$ss
    for c in 1 2 2a 3 3a 4 5;do
        mkdir case\$c
        cd case\$c
        classify ../../../../debugfs.*.case\$c.snapshot\$ss.ls.diff
        cd ..
    done
    cd ..
done
cd ../../..
CREATE_ENV_EOF
cat >dumpe2fs_diff.sh <<CREATE_ENV_EOF
. ./classify.sh

logdir=\$1
tooldir=\$2

for d in \$logdir/20*;do
    echo \$d
    cd \$d
    d=\$(basename \$d)
    for c in 1 2 2a 3 3a 4 5;do
        for ss in 1 2;do
            diff loopdisk.img.org.dumpe2fs.notime.log loopdisk.img.case\$c.snapshot\$ss.dumpe2fs.notime.log >../dumpe2fs.\$d.case\$c.snapshot\$ss.diff
        done
    done
    cd ../..
done

for ss in 1 2;do
    mkdir -p \$logdir/snapshot\$ss
    cd \$logdir/snapshot\$ss
    for c in 1 2 2a 3 3a 4 5;do
        mkdir case\$c
        cd case\$c
        classify ../../dumpe2fs.*.case\$c.snapshot\$ss.diff
        cd ..
    done
    cd ../..
done

mkdir -p \$logdir/\$tooldir
mv \$logdir/snapshot* \$logdir/\$tooldir
CREATE_ENV_EOF
cat >ls_diff.sh <<CREATE_ENV_EOF
. ./classify.sh

logdir=\$1
tooldir=\$2

for d in \$logdir/20*;do
    echo \$d
    cd \$d
    d=\$(basename \$d)
    for c in 1 2 2a 3 3a 4 5;do
        for ss in 1 2 3;do
            diff case\$c.ls.0.log case\$c.ls.\$ss.log | sed 's/[0-9]*月 [0-9]* [0-9]*:[0-9]*//' >../ls.\$d.case\$c.snapshot\$ss.diff
        done
    done
    cd ../..
done

for ss in 1 2 3;do
    mkdir -p \$logdir/snapshot\$ss
    cd \$logdir/snapshot\$ss
    for c in 1 2 2a 3 3a 4 5;do
        mkdir case\$c
        cd case\$c
        classify ../../ls.*.case\$c.snapshot\$ss.diff
        cd ..
    done
    cd ../..
done

mkdir -p \$logdir/\$tooldir
mv \$logdir/snapshot* \$logdir/\$tooldir
CREATE_ENV_EOF
cat >report.sh <<CREATE_ENV_EOF
logdir=\$1
lsdir=\$2
dumpe2fsdir=\$3
debugfsdir=\$4

total=\$(ls -1 \$logdir/\$lsdir/snapshot1/case1/*/*|wc -l)
for i in \$logdir/\$lsdir/snapshot*/case*/*;do
    echo "============================================================================"
    echo "[\$i]"
    count=\$(ls -1 \$i/*|wc -l)
    percent=\$(echo "scale=2;\$count*100/\$total"|bc)
    echo "Count: \$count/\$total(\$percent%)"
    cat \$(ls -1 \$i/*|head -1)
done | tee \$logdir/ls_report.txt

total=\$(ls -1 \$logdir/\$dumpe2fsdir/snapshot1/case1/*/*|wc -l)
for i in \$logdir/\$dumpe2fsdir/snapshot*/case*/*;do
    echo "============================================================================"
    echo "[\$i]"
    count=\$(ls -1 \$i/*|wc -l)
    percent=\$(echo "scale=2;\$count*100/\$total"|bc)
    echo "Count: \$count/\$total(\$percent%)"
    cat \$(ls -1 \$i/*|head -1)
done | tee \$logdir/dumpe2fs_report.txt

total=\$(ls -1 \$logdir/\$debugfsdir/ls/snapshot1/case1/*/*|wc -l)
for i in \$logdir/\$debugfsdir/ls/snapshot*/case*/*;do
    echo "============================================================================"
    echo "[\$i]"
    count=\$(ls -1 \$i/*|wc -l)
    percent=\$(echo "scale=2;\$count*100/\$total"|bc)
    echo "Count: \$count/\$total(\$percent%)"
    cat \$(ls -1 \$i/*|head -1)
done | tee \$logdir/debugfs_ls_report.txt

total=\$(ls -1 \$logdir/\$debugfsdir/log/snapshot1/case1/logdump_all/*/*|wc -l)
for i in \$logdir/\$debugfsdir/log/snapshot*/case*/*/*;do
    echo "============================================================================"
    echo "[\$i]"
    count=\$(ls -1 \$i/*|wc -l)
    percent=\$(echo "scale=2;\$count*100/\$total"|bc)
    echo "Count: \$count/\$total(\$percent%)"
    cat \$(ls -1 \$i/*|head -1)
done | tee \$logdir/debugfs_log_report.txt
CREATE_ENV_EOF
cat >test.sh <<CREATE_ENV_EOF
set -eux
do_umount() {
    sudo sync
    sudo sync
    sudo sync
    while ! sudo umount \$*; do
        sleep 1
    done
}
do_test() {
    cp -p loopdisk.img.org loopdisk.img
    sudo mount ./loopdisk.img -o loop ./mnt
    sudo ./test \$2
    ls -lai mnt/ | sed '/ \\.\\.\$/d' >\$1.ls.0.log
    cp -p loopdisk.img loopdisk.img.\$1.snapshot1
    do_umount mnt
    mv loopdisk.img loopdisk.img.\$1.snapshot2
    cp -p loopdisk.img.\$1.snapshot1 loopdisk.img
    sudo mount ./loopdisk.img -o loop ./mnt
    cp -p loopdisk.img loopdisk.img.\$1.snapshot3
    do_umount mnt
    for ss in 1 2 3;do
        cp -p loopdisk.img.\$1.snapshot\$ss loopdisk.img
        sudo mount ./loopdisk.img -o loop ./mnt
        ls -lai mnt/ | sed '/ \\.\\.\$/d' >\$1.ls.\$ss.log
        do_umount mnt
    done
}

if [ -e tmp ]; then
    echo "tmp is already exist."
    return 1
fi

sudo true

mkdir tmp
cd tmp
mkdir mnt
dd if=/dev/zero of=loopdisk.img.org bs=1MiB count=10
mkfs.ext3 ./loopdisk.img.org

cat >test.cpp <<EOF
#include <fcntl.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <unistd.h>

#include <cstdio>
#include <string>

const size_t BUFFER_SIZE = 4096;
const size_t FILE_SIZE = 4 * 1024;  // 4KiB

char buffer[BUFFER_SIZE] = {};

int main(int argc, char *argv[]) {
  int fd = open("mnt/dummy", O_CREAT | O_WRONLY | O_TRUNC, 0666);
  if (fd == -1) {
    std::perror(argv[0]);
    return 1;
  }
  for (size_t i = 0; i < static_cast<size_t>(FILE_SIZE / BUFFER_SIZE); ++i) {
    int r = write(fd, buffer, BUFFER_SIZE);
    if (r != BUFFER_SIZE) {
      std::perror(argv[0]);
      return 1;
    }
  }
  if (argc > 1) {
    std::string arg1(argv[1]);
    int r = 0;
    if ((arg1 == "--fsync") || (arg1 == "--fsync6")) {
      r = fsync(fd);
    } else if (arg1 == "--syncfs") {
      r = syncfs(fd);
    }
    if (r == -1) {
      std::perror(argv[0]);
      return 1;
    }
    close(fd);
    if (arg1 == "--sleep") {
      sleep(6);
    } else if (arg1 == "--sleep31") {
      sleep(31);
    } else if (arg1 == "--fsync6") {
      sleep(6);
    } else if (arg1 == "--sync") {
      sync();
    }
  } else {
    close(fd);
  }
  return 0;
}
EOF
g++ -g -Wall -pedantic -std=c++17 test.cpp -o test

do_test case1 "" 2>&1 >case1.log
do_test case2 "--sleep" 2>&1 >case2.log
do_test case2a "--sleep31" 2>&1 >case2a.log
do_test case3 "--fsync" 2>&1 >case3.log
do_test case3a "--fsync6" 2>&1 >case3a.log
do_test case4 "--syncfs" 2>&1 >case4.log
do_test case5 "--sync" 2>&1 >case5.log

for f in loopdisk.img*; do
    dumpe2fs \$f 2>&1 > \$f.dumpe2fs.log
    sed '/time/d;/^Last mounted on:/d;/^Mount count:/d' \$f.dumpe2fs.log > \$f.dumpe2fs.notime.log
    debugfs -R 'logdump -a' \$f 2>&1 > \$f.logdump_not_committed.log;
    debugfs -R 'logdump -Oa' \$f 2>&1 > \$f.logdump_all.log;
    debugfs -R 'ls -l /' \$f 2>&1 > \$f.ls.log
done
CREATE_ENV_EOF
cat >qiita_base_ls.py <<CREATE_ENV_EOF
import re

count_regex = re.compile(r'^Count: (\\d+)/(\\d+)\\((\\d*.\\d+)%\\)\$')

def parse_head(line, head_regex):
    m = head_regex.match(line)
    if m:
        return (m.group(1), m.group(2))
    else:
        raise RuntimeError('Error!!!')

def parse_count(line):
    m = count_regex.match(line)
    if m:
        return (int(m.group(1)), int(m.group(2)), float(m.group(3)))
    else:
        raise RuntimeError('Error!!!')

def parse_case(lines, head_regex, file_regex):
    it = iter(lines)
    head = next(it)
    snapshot, cs = parse_head(head, head_regex)
    countline = next(it)
    count, total, percent = parse_count(countline)

    dummy_diff = False
    root_diff = False
    file = None
    for line in it:
        m = file_regex.match(line)
        if m:
            file = m.group(1)
            if file == 'dummy':
                dummy_diff = True
            elif file == '.':
                root_diff = True
            else:
                raise RuntimeError('Error!!!')
    return (snapshot, cs, count, total, percent, dummy_diff, root_diff)

case2idx = {
    'case1': 0,
    'case2': 1,
    'case2a': 2,
    'case3': 3,
    'case3a': 4,
    'case4': 5,
    'case5': 6,
}

def record(result, snapshot, cs, count, total, percent, dummy_diff, root_diff):
    if not snapshot in result.keys():
        result[snapshot] = {'dummy': [0, 0, 0, 0, 0, 0, 0], 'root': [0, 0, 0, 0, 0, 0, 0]}
    dict_file = result[snapshot]
    idx = case2idx[cs]
    if dummy_diff:
        dict_file['dummy'][idx] += percent
    if root_diff:
        dict_file['root'][idx] += percent

def table_out(fin, fout, head_regex, file_regex, print_result):
    result = {}
    it = iter(fin)
    next(it)
    lines = []
    for line in it:
        line = line.rstrip()
        if line == '============================================================================':
            snapshot, cs, count, total, percent, dummy_diff, root_diff = parse_case(lines, head_regex, file_regex)
            record(result, snapshot, cs, count, total, percent, dummy_diff, root_diff)
            lines = []
        else:
            lines.append(line)
    snapshot, cs, count, total, percent, dummy_diff, root_diff = parse_case(lines, head_regex, file_regex)
    record(result, snapshot, cs, count, total, percent, dummy_diff, root_diff)

    print_result(fout, result)
CREATE_ENV_EOF
cat >qiita_debugfs_log.py <<CREATE_ENV_EOF
import re

count_regex = re.compile(r'^Count: (\\d+)/(\\d+)\\((\\d*.\\d+)%\\)\$')

def parse_head(line, head_regex):
    m = head_regex.match(line)
    if m:
        return (m.group(1), m.group(2), m.group(3))
    else:
        raise RuntimeError('Error!!!')

def parse_count(line):
    m = count_regex.match(line)
    if m:
        return (int(m.group(1)), int(m.group(2)), float(m.group(3)))
    else:
        raise RuntimeError(f'Error!!!: {line}')



skip_switch_regex = re.compile(r'^-.*\$')
skip_diff_line_regex = re.compile(r'^\\d.*\$')
skip_journal_starts_regex = re.compile(r'^[<>] Journal starts at block.*\$')
end_of_journal_regex = re.compile(r'^[<>] (Found sequence \\d+ \\(not \\d+\\)|No magic number) at block \\d+|: end of journal.\$')
commit_regex = re.compile(r'^> Found expected sequence \\d+, type \\d+ \\(commit block\\) at block \\d+\$')
skip_found_descriptor_regex = re.compile(r'^> Found expected sequence \\d+, type \\d+ \\(descriptor block\\) at block \\d+\$')
start_transaction_regex = re.compile(r'^> Dumping descriptor block, sequence \\d+, at block \\d+:\$')
transaction_fs_block_regex = re.compile(r'^>   FS block (\\d+) logged at journal block \\d+ \\(flags 0x[0-9a-f]+\\)\$')

def parse_case(lines, head_regex, file_regex):
    it = iter(lines)
    head = next(it)
    snapshot, cs, logtype = parse_head(head, head_regex)
    countline = next(it)
    count, total, percent = parse_count(countline)

    transactions = []
    transaction = None
    for line in it:
        m = skip_switch_regex.match(line)
        if m:
            continue
        m = skip_diff_line_regex.match(line)
        if m:
            continue
        m = skip_journal_starts_regex.match(line)
        if m:
            continue
        m = skip_found_descriptor_regex.match(line)
        if m:
            continue
        m = end_of_journal_regex.match(line)
        if m:
            if transaction is not None and len(transaction) > 0:
                transactions.append(transaction)
                transaction = None
            continue
        m = commit_regex.match(line)
        if m:
            if transaction is not None and len(transaction) > 0:
                transactions.append(transaction)
                transaction = None
            transactions.append('C')
            continue
        m = start_transaction_regex.match(line)
        if m:
            if transaction is None:
                transaction = []
            else:
                raise RuntimeError('Error')
            continue
        m = transaction_fs_block_regex.match(line)
        if m:
            transaction.append(m.group(1))
            continue
        raise RuntimeError(f'unknown line: {line}')

    return (snapshot, cs, logtype, count, total, percent, transactions)

def record(result, snapshot, cs, logtype, count, total, percent, transactions):
    if snapshot not in result.keys():
        result[snapshot] = {}
    dict_snapshot = result[snapshot]
    if cs not in dict_snapshot.keys():
        dict_snapshot[cs] = {}
    dict_case = dict_snapshot[cs]
    if logtype not in dict_case.keys():
        dict_case[logtype] = []
    dict_case[logtype].append((percent, transactions))

case2name = {
    'case1': '引数なし',
    'case2': 'sleep(6)',
    'case2a': 'sleep(31)',
    'case3': 'fsync',
    'case3a': 'fsync+sleep(6)',
    'case4': 'syncfs',
    'case5': 'sync',
}

def table_out(fin, fout, head_regex, file_regex):
    result = {}
    it = iter(fin)
    next(it)
    lines = []
    for line in it:
        line = line.rstrip()
        if line == '============================================================================':
            snapshot, cs, logtype, count, total, percent, transactions = parse_case(lines, head_regex, file_regex)
            record(result, snapshot, cs, logtype, count, total, percent, transactions)
            lines = []
        else:
            lines.append(line)
    snapshot, cs, logtype, count, total, percent, transactions = parse_case(lines, head_regex, file_regex)
    record(result, snapshot, cs, logtype, count, total, percent, transactions)
    
    for snapshot, cases in result.items():
        print(f'[{snapshot}]')
        for case, cols in cases.items():
            print(f'|{case2name[case]}|', end='', file=fout)
            for logtype, pat_ary in cols.items():
                newpat = {}
                for percent, transactions in pat_ary:
                    if len(transactions) > 0:
                        transactions = ','.join(x if not isinstance(x, list) else '{'+','.join(x)+'}' for x in transactions)
                    else:
                        transactions = '-'
                    if transactions not in newpat:
                        newpat[transactions] = percent
                    else:
                        newpat[transactions] += percent
                text = '<br>'.join(f'{transactions}({percent}%)' if percent < 100 else transactions for transactions, percent in newpat.items())
                print(f'{text}|', end='', file=fout)
            print(file=fout)

import re

head_regex = re.compile(r'^\\[[^/]*/[^/]*/[^/]*/([^/]*)/([^/]*)/([^/]*)/[^/]*\\]\$')
file_regex = re.compile(r'^>\\s*\\d+\\s+\\d+\\s+\\(\\d+\\)\\s+\\d+\\s+\\d+\\s+\\d+\\s+\\d+\\s+(dummy|\\.)\$')

import sys
table_out(sys.stdin, sys.stdout, head_regex, file_regex)
CREATE_ENV_EOF
cat >qiita_debugfs_ls.py <<CREATE_ENV_EOF
from qiita_base_ls import table_out
import re

head_regex = re.compile(r'^\\[[^/]*/[^/]*/[^/]*/([^/]*)/([^/]*)/[^/]*\\]\$')
file_regex = re.compile(r'^>\\s*\\d+\\s+\\d+\\s+\\(\\d+\\)\\s+\\d+\\s+\\d+\\s+\\d+\\s+\\d+\\s+(dummy|\\.)\$')

casenames = [
    '引数なし',
    'sleep(6)',
    'sleep(31)',
    'fsync',
    'fsync+sleep(6)',
    'syncfs',
    'sync',
]

def print_result(fout, result):
    for snapshot, dict_cases in result.items():
        print(f'[{snapshot}]', file=fout)
        for case_number in range(len(casenames)):
            print(f'|{casenames[case_number]}|', end='', file=fout)
            for file in ['dummy', 'root']:
                col = dict_cases[file][case_number]
                if col == 0.:
                    print('差分なし|', end='', file=fout);
                elif col == 100.:
                    print('差分あり|', end='', file=fout);
                else:
                    print(f'差分なし({100. - col}%)<br>', end='')
                    print(f'差分あり({col}%)|', end='')
            print(file=fout)
    fout.flush()

import sys
table_out(sys.stdin, sys.stdout, head_regex, file_regex, print_result)
CREATE_ENV_EOF
cat >qiita_dumpe2fs.py <<CREATE_ENV_EOF
import re

head_regex = re.compile(r'^\\[[^/]*/[^/]*/([^/]*)/([^/]*)/[^/]*\\]\$')
count_regex = re.compile(r'^Count: (\\d+)/(\\d+)\\((\\d*.\\d+)%\\)\$')
param_regex = re.compile(r'^([<>])\\s([^:]+):\\s+(.*)\$')

def parse_head(line):
    m = head_regex.match(line)
    if m:
        return (m.group(1), m.group(2))
    else:
        raise RuntimeError('Error!!!')

def parse_count(line):
    m = count_regex.match(line)
    if m:
        return (int(m.group(1)), int(m.group(2)), float(m.group(3)))
    else:
        raise RuntimeError(f'Error!!!: {line}')

def diff_ranges(left_ranges, right_ranges):
    li = 0
    ri = 0
    left_range = left_ranges[li]
    right_range = right_ranges[ri]
    left0 = left_range[0]
    right0 = right_range[0]
    left_only = []
    right_only = []
    while True:
        if left0 < right0:
            if left_range[1] < right0:
                left_only.extend(range(left0, left_range[1]+1))
                li += 1
                if li >= len(left_ranges):
                    break
                else:
                    left_range = left_ranges[li]
                    left0 = left_range[0]
            else:
                left_only.extend(range(left0, right0))
                left0 = right0
                if left_range[1] < right_range[1]:
                    right0 = left_range[1]+1
                    li += 1
                    if li >= len(left_ranges):
                        right_only.extend(range(left_range[1]+1, right_range[1]+1))
                        ri += 1
                        break
                    else:
                        left_range = left_ranges[li]
                        left0 = left_range[0]
                else:
                    left0 = right_range[1]+1
                    ri += 1
                    if ri >= len(right_ranges):
                        left_only.extend(range(right_range[1]+1, left_range[1]+1))
                        li += 1
                        break
                    else:
                        right_range = right_ranges[ri]
                        right0 = right_range[0]
        else:
            if right_range[1] < left0:
                right_only.extend(range(right0, right_range[1]+1))
                ri += 1
                if ri >= len(right_ranges):
                    break
                else:
                    right_range = right_ranges[ri]
                    right0 = right_range[0]
            else:
                right_only.extend(range(right0, left0))
                right0 = left0
                if right_range[1] < left_range[1]:
                    left0 = right_range[1]+1
                    ri += 1
                    if ri >= len(right_ranges):
                        left_only.extend(range(right_range[1]+1, left_range[1]+1))
                        li += 1
                        break
                    else:
                        right_range = right_ranges[ri]
                        right0 = right_range[0]
                else:
                    right0 = left_range[1]+1
                    li += 1
                    if li >= len(left_ranges):
                        right_only.extend(range(left_range[1]+1, right_range[1]+1))
                        ri += 1
                        break
                    else:
                        left_range = left_ranges[li]
                        left0 = left_range[0]
    while li < len(left_ranges):
        left_range = left_ranges[li]
        left_only.extend(left_range[0], left_range[1]+1)
        li += 1
    while ri < len(right_ranges):
        right_range = right_ranges[ri]
        right_only.extend(right_range[0], right_range[1]+1)
        ri += 1
    return (tuple(left_only), tuple(right_only))

def diff_ary(left, right):
    li = 0
    ri = 0
    l_only = []
    r_only = []
    while ri < len(right):
        lelm = left[li]
        found = False
        for ristart in range(ri, len(right)):
            if right[ristart] == lelm:
                found = True
                break
        if found:
            r_only.extend(right[ri:ristart])
            ri = ristart
            li += 1
            ri += 1
            if li >= len(left):
                break
        else:
            l_only.add(lelm)
            li += 1
            if li >= len(left):
                break
    if ri < len(right):
        r_only.extend(right[ri:])
    return (tuple(l_only), tuple(r_only))

def parse_case(lines):
    it = iter(lines)
    head = next(it)
    snapshot, cs = parse_head(head)
    countline = next(it)
    count, total, percent = parse_count(countline)

    left_params = {}
    params = {}
    for line in it:
        m = param_regex.match(line)
        if m:
            left_right = m.group(1)
            name = m.group(2)
            values = re.split(r',? +', m.group(3))
            if left_right == '<':
                left_params[name] = values
            elif left_right == '>':
                if name == 'Free blocks':
                    pass
                elif name == 'Free inodes':
                    pass
                elif name == '  Free blocks':
                    left_ranges = [[int(x) for x in e.split('-')] for e in left_params[name]]
                    right_ranges = [[int(x) for x in e.split('-')] for e in values]
                    params['増加ブロック'], dummy = diff_ranges(left_ranges, right_ranges);
                    if len(dummy) != 0:
                        raise RuntimeError('Error!!!')
                elif name == '  Free inodes':
                    left_ranges = [[int(x) for x in e.split('-')] for e in left_params[name]]
                    right_ranges = [[int(x) for x in e.split('-')] for e in values]
                    params['増加inode'], dummy = diff_ranges(left_ranges, right_ranges);
                    if len(dummy) != 0:
                        raise RuntimeError('Error!!!')
                elif name == 'Journal start':
                    pass
                elif name == 'Journal sequence':
                    params[name] = values[0]
                elif name == 'Filesystem features':
                    minus, plus = diff_ary(left_params[name], values)
                    for e in plus:
                        params[f'{name}({e})'] = '+'
                    for e in minus:
                        params[f'{name}({e})'] = '-'
                else:
                    raise RuntimeError(f'Unexpected parameter "{name}"')
            else:
                raise RuntimeError('Error!!!')
    return (snapshot, cs, count, total, percent, params)

def record(result, snapshot, cs, count, total, percent, params):
    if not snapshot in result.keys():
        result[snapshot] = {}
    dict_cases = result[snapshot]
    if not cs in dict_cases.keys():
        dict_cases[cs] = []
    ary_params = dict_cases[cs]
    ary_params.append({'percent': percent, 'params': params})

import sys
f = sys.stdin
result = {}
it = iter(f)
next(it)
lines = []
for line in it:
    line = line.rstrip()
    if line == '============================================================================':
        snapshot, cs, count, total, percent, params = parse_case(lines)
        record(result, snapshot, cs, count, total, percent, params)
        lines = []
    else:
        lines.append(line)
snapshot, cs, count, total, percent, params = parse_case(lines)
record(result, snapshot, cs, count, total, percent, params)

rowids=[]
for snapshot, value in result.items():
    for cs, ary in value.items():
        for obj in ary:
            params = obj['params']
            percent = obj['percent']
            for name in params.keys():
                if name not in rowids:
                    rowids.append(name)

for snapshot, value in result.items():
    print(f'[{snapshot}]')
    for name in rowids:
        print(f'|{name}|', end='')
        for cs, ary in value.items():
            ary2 = ((obj["params"], obj["percent"]) for obj in ary)
            ary3 = ((params[name] if name in params.keys() else '-', percent) for params, percent in ary2)
            ary4 = {}
            for pv, percent in ary3:
                if isinstance(pv, (list, tuple)):
                    pv = ','.join(str(x) for x in pv)
                if pv not in ary4.keys():
                    pv = str(pv)
                    ary4[pv] = percent
                else:
                    ary4[pv] += percent
            if len(ary4) > 1:
                col = '<br>'.join(f'{pv}({percent}%)' for pv, percent in ary4.items())
            else:
                col = next(iter(ary4.keys()));
            print(f'{col}|', end='')
        print()
CREATE_ENV_EOF
cat >qiita_ls.py <<CREATE_ENV_EOF
from qiita_base_ls import table_out
import re

head_regex = re.compile(r'^\\[[^/]*/[^/]*/([^/]*)/([^/]*)/[^/]*\\]\$')
file_regex = re.compile(r'^<\\s*\\d+\\s+[-rwxdst]+\\s+\\d+\\s+\\w+\\s+\\w+\\s+\\d+\\s+(dummy|\\.)\$')

def print_result(fout, result):
    for file in ['dummy', 'root']:
        print(f'[{file}]', file=fout)
        for key, value in result.items():
            print(f'|{key}|', end='', file=fout)
            for col in value[file]:
                if col == 0.:
                    print('差分なし|', end='', file=fout);
                elif col == 100.:
                    print('差分あり|', end='', file=fout);
                else:
                    print(f'差分なし({100. - col}%)<br>', end='')
                    print(f'差分あり({col}%)|', end='')
            print(file=fout)
    fout.flush()

import sys
table_out(sys.stdin, sys.stdout, head_regex, file_regex, print_result)
CREATE_ENV_EOF