大きなコピーが途中で急に遅くなるのはなぜか — txg.cと書き込みスロットルを読む
子どもの発表会の4K素材を、編集機からhomenasにコピーしたときのことです。10GbE越しのコピーは、最初の数秒だけ回線の上限近くまで出て、そこから一段落ちたところで落ち着きました。当時は「Windows側のキャッシュが効いているうちだけ速いんだろう」くらいに思って、深くは考えませんでした。
arc.c、vdev_queue.c、zil.cと読んできて、どの回にも「txg」が出てきました。今回はその本体です。txgを回すmodule/zfs/txg.c、dirtyデータ(メモリ上にあって、まだディスクに書かれていない変更)を数えるdsl_pool.c、書き込みを遅らせるdmu_tx.cの3つを読みました。対象はOpenZFS masterの9d59e8e(2026年10月12日)です。
3つで4,408行、モジュールパラメータは12個です。書き込みを遅らせる本体のdmu_tx.cには1個もなく、つまみはすべてdsl_pool.cとtxg.cの側にあります。
zfs-2.4.4とも比べました。仕組みと既定値は同じです。masterでは、dedupの表(DDT)やブロッククローンの管理表(BRT)の更新でsync中に増える分を先に見積もって数える処理が足され、dirtyデータの集計からロックを外す変更なども入っていますが、この記事の話は2.4.4でもそのまま当てはまります。いつも通りhomenasで測った数字は出てきません。グラフと表の値も、式から計算したものです。
txgは「受付中」と「書き出し中」が並んで進む
txg の流れ: ふだんは「受付中」と「書き出し中」の2つが並ぶ
図は横にスクロールできます横軸は時間の流れを表すだけで、長さは実測ではない。灰色の細い区間が quiescing(締め切って、途中の変更が終わるのを待つ)。締め切った txg が前の sync の終わりを待つ状態もあり、そのときは txg が3つ同時に動いている。
txg(トランザクショングループ)は、変更をまとめてディスクに書くための単位です。txg.cの冒頭コメントによると、txgには3つの状態があります。
- open: 新しい変更を受け付ける
- quiescing: 受付を締め切り、途中まで進んでいる変更が終わるのを待つ
- syncing: たまった変更をディスクに書き出す
コメントには「最大3つのtxgが同時に動きうる」とあります。ただ、txg_sync_thread()を読むと、syncスレッドが次のtxgの締め切りを促すのは、前のtxgを書き終えてからでした。ふだんは、1つを書き出しながら次の1つが変更を受け付けている2つ並びが基本で、締め切り(quiescing)は短い受け渡しの時間です。締め切ったtxgが前のsyncの終わりを待って3つ並ぶのは、ほかの処理が締め切りを急かした場合です(txg_wait_open())。
「txgは5秒ごと」でおなじみのzfs_txg_timeout(既定5)も、数え方を見ると「前のsyncの開始から5秒」でした。書き出しが5秒以内に終われば、残りの時間は待ちます。5秒を超えれば、終わったところですぐ次のtxgを締め切ります。
締め切りのきっかけは、5秒だけではない
次の txg を締め切って sync するきっかけ
図は横にスクロールできますどれか1つでも当てはまると、sync スレッドは今の open txg を締め切って書き出す。ただし前の txg を書き出している最中なら、それが終わってから。
syncスレッドが待つのをやめるきっかけは5つありました。
書き込みが多いときに効くのは2つ目です。dsl_pool_dirty_space()は、書き込みでdirtyデータが増えるたびに、そのtxgの分が上限の20%(zfs_dirty_data_sync_percent)を超えていないかを見て、超えていればtxg_kick()でsyncスレッドを起こします。大きなコピーの最中は、5秒を待つまでもなく、量でtxgが区切られていくことになります。
3つ目は、zil.cの回で見たZILのログデータ(WR_COPIEDとWR_NEED_COPYの記録)です。こちらも同じ形で数えられていて、1つのtxgの分がzfs_wrlog_data_maxの15%を超えるとsyncを急かします。zfs_wrlog_data_maxの既定値は、dirtyデータの上限の2倍です。
5つ目は意外でした。scrubやresilverの実行中は、タイマーを待たずにsyncを続けます。scrubの仕事はsyncの中(spa_sync()から呼ばれるdsl_scan_sync())で進むので、そうしないと進まないのだと思います。
締め切るとき、何を待っているのか
締め切り(quiesce)は、途中の書き込みが全部抜けるのを待つ
図は横にスクロールできます数字はその CPU で、その txg に入ったまま、まだ終わっていない書き込み(トランザクション)の数。CPU ごとに分けて数えるのは、ロックの取り合いを避けるため。
書き込みはtxgに入るときtxg_hold_open()で「保持数」を1つ増やし、終わるとtxg_rele_to_sync()で1つ減らします。この保持数は1つのカウンタではなく、CPUごとに分けて数えています。全員が1つのカウンタを取り合うと、そこでロックの奪い合いになるからでしょう。
締め切りのtxg_quiesce()は、まず全CPUの受付ロックを取ってopenのtxg番号を1つ進め、すぐにロックを外します。これ以降に来た書き込みは次のtxgに入ります。そのあと、締め切ったtxgの保持数が全CPUで0になるのを待ちます。待つのは、すでに入っていた書き込みがARC上での書き換えを終えるまでの時間だけです。コメントにも、quiescingは「I/Oではなくソフトウェアの処理時間で決まるので、ふつうはごく短い」とあります。
dirtyデータの目盛り
dirty データの目盛り(zfs_dirty_data_max を 100% として)
図は横にスクロールできます上限 zfs_dirty_data_max の既定値は、物理メモリの 10% と「4GiB か物理メモリの 25% の小さいほう」の、さらに小さいほう。RAM 128GB の homenas では 4GiB になる。
書き込みの流量の絞り(スロットル)は、どれもdirtyデータの量を、上限zfs_dirty_data_maxに対する割合で見ています。vdev_queue.cの回で出てきた値も含めて、1本の目盛りに並べるとこうなります。
上限の既定値は、物理メモリの10%と、「4GiBか物理メモリの25%の小さいほう」の、さらに小さいほうです。RAM 128GBのhomenasでは、12.8GBではなく4GiBになります。
1つ注意したいのは、20%だけは「そのtxgの分」で判定していて、ほかは「全txgの合計」で判定していることです。書き出し中のtxgの分も合計に入るので、ディスクへの書き出しが遅いと、次のtxgが受け付けた分と合わせて合計が増えていきます。その合計が60%を超えたところで、書き込み側にブレーキがかかります。
60%を超えると、1件ずつ眠らされる
書き込み1件あたりの最小時間(dmu_tx_delay の式、既定値)
図は横にスクロールできます式の値を描いたもので、実測ではない。60% までは 0。縦軸は 4ms で切っているが、100% に近づくと 1 件 100ms(上限)まで伸びる。横軸の下段は上限 4GiB の homenas での量。点にカーソルを当てると値が出る。
60%(zfs_delay_min_dirty_percent)を超えると、dmu_tx_delay()が書き込み1件(トランザクション)ごとに「最低これだけはかける」という時間を課します。式はコメントにそのまま書かれています。
1件あたりの最小時間 = zfs_delay_scale × (dirty − 60%の量) ÷ (上限 − dirty)
zfs_delay_scaleの既定値は500µsで、60%と100%のちょうど中間の80%で、1件あたり500µsになります。分母が「上限までの残り」なので、100%に近づくほど急に伸び、最大100ms(zfs_delay_max_ns)で頭打ちになります。この最大値には「10 IOPSも出せないなら何かがおかしい」というコメントが付いていました。
| dirtyの量 | homenasでの量 | 1件あたりの最小時間 | 1秒あたりの件数の上限 |
|---|---|---|---|
| 60%以下 | 2.4GiB以下 | 0 | 制限なし |
| 70% | 2.8GiB | 約167µs | 約6,000件 |
| 80% | 3.2GiB | 500µs | 2,000件 |
| 90% | 3.6GiB | 1.5ms | 約667件 |
| 95% | 3.8GiB | 3.5ms | 約286件 |
| 99% | 約3.96GiB | 19.5ms | 約51件 |
どれも式から計算した値です。コメントでは、zfs_delay_scaleは「1秒あたりに処理できる最大の件数で10億を割った値」くらいにするとよい、とされています。既定の500µsは、2,000件/秒に当たります。
何本で書いても、間隔は同じ
遅延は前の人の起床時刻に積まれる
図は横にスクロールできますt は前の図の「1件あたりの最小時間」。スレッドが何本あっても、起きる間隔は t 以上空くので、1秒あたりに通る書き込みの件数は最大で 1/t。待っているのが自分だけなら、自分が来た時刻から数える(それまでにかかった時間は差し引かれる)。
この遅延が「1件あたり」として効くのは、起きる時刻の決め方のおかげです。dmu_tx_delay()は、「自分が来た時刻 + t」と「直前に誰かが起きた時刻 + t」のうち、遅いほうまで眠ります。先に待っている人がいれば、その後ろにtずつ並ぶことになります。
コメントには、こうすれば遅延がスレッドの数に左右されない、と書かれています。100本のスレッドで書いても1本で書いても、1秒あたりに通る件数の上限は1/tです。遅延の曲線が「IOPSの逆数」と説明されているのは、このためでした。
ただし、1件がどれだけのデータを運ぶかは書き方で変わります。ファイルの末尾にブロック単位で追記していくような書き込みなら、だいたい1件で1ブロック分です。なので、この上限がそのまま何MB/sという意味にはなりません。
書き込み1件が通る関所
書き込み1件が txg に入るまでの関所(dmu_tx_assign)
図は横にスクロールできます「遅延済み」の印が付いたトランザクションは、やり直したときに 60% の判定を素通りする。1件が眠らされるのは1回だけで、同じ書き込みが何度も遅らされることはない。
最後に、書き込みがtxgに入るまでのdmu_tx_assign()をまとめておきます。
60%の判定は、dirtyデータだけでなくZILのログデータについても行われます。zil.cの回で、fsyncされなかった記録は捨てられると書きましたが、txgが書き終わって捨てられるまでの間は、ここで数えられています(WR_INDIRECTの分は数えません)。fsyncの多いワークロードでは、dirtyデータに余裕があっても、ログデータの側でブレーキがかかることがあり得ます。
一度眠らされたトランザクションには「遅延済み」の印(tx_dirty_delayed)が付き、やり直しのときは60%の判定を素通りします。同じ書き込みが何度も眠らされて、いつまでも進めない、ということは起きません。
その先の「空き容量とメモリを予約」の中では、ARCの側でもdirtyなバッファが多すぎないかを見ています(arc_tempreserve_space())。こちらに引っかかった場合も待たされます。
あのコピーで起きていたこと
ここまでを冒頭のコピーに当てはめてみます。検証はしていないので、仮説です。
10GbEで流れ込んだ書き込みは、最初はdirtyデータとしてメモリにたまるだけなので、ディスクの速さとは関係なく受け付けられます。txgは量(上限の20%、約0.8GiB)で次々に区切られて書き出しも始まりますが、RAIDZ2のHDDへの書き出しが受け付けの速さに追いつかなければ、合計はじわじわ増えていきます。合計が60%(約2.4GiB)を超えたところで1件ごとの遅延が始まり、そこからは、受け付けの速さが書き出しの速さと釣り合う所まで遅延が伸びて落ち着きます。最初の数秒だけ速かったのは、この2.4GiBぶんの「貯金」を使っていた時間だった、というのが今の理解です。
もしそうなら、zfs_dirty_data_maxを大きくしても、最初の速い時間が延びるだけで、落ち着いた後の速さは変わらないはずです。落ち着いた後の速さを決めているのは、プールが書き出せる速さのほうだからです。逆に、1つのtxgが大きくなれば1回のsyncも長くなるので、書き終わりを待つ操作(zpool syncやスナップショットの作成など)は待たされやすくなりそうです。
もちろん、Windows側のキャッシュも効いていたかもしれません。次に大きなコピーをするときは、下の値を並べて見ておくつもりです。
見ておく値
# txg ごとの記録(直近100件)。ndirty はその txg の dirty 量、
# otime / qtime / wtime / stime は open・quiescing・待機・sync にかかった時間(ナノ秒)
cat /proc/spl/kstat/zfs/homenas/txgs
# 遅延や停止が何回起きたか
grep -e dirty -e wrlog -e delay /proc/spl/kstat/zfs/dmu_tx
# 今の上限(バイト)
cat /sys/module/zfs/parameters/zfs_dirty_data_max
| 値 | 読み方 |
|---|---|
txgsのndirty | そのtxgがsyncを始めたときのdirtyデータの量 |
txgsのstime | syncにかかった時間。5秒を超えていれば、次のtxgは待たずに始まっている |
dmu_tx_dirty_delay | dirtyデータが60%を超えて、遅延の手続きに入った件数 |
dmu_tx_dirty_over_max | dirtyデータが100%に達して、下がるのを待った件数 |
dmu_tx_wrlog_delay | ZILのログデータが60%を超えて、遅延の手続きに入った件数 |
dmu_tx_dirty_throttle | ARCの側で待たされた件数 |
読み終えて
「txgは5秒ごと」「書き込みはメモリの10%までためる」という覚え方は、間違いではありませんが、だいぶ足りていませんでした。5秒は前のsyncの開始から数える上限で、書き込みが多ければ量でもっと早く区切られます。ためておける量の上限に近づく手前から、書き込みは1件ずつ、前の人の後ろに並ぶ形で眠らされていきます。
ZFSの書き込みは「メモリに書けたら終わり」に見えて、実際にはディスクの速さに合わせて少しずつ待たされていました。しかも、ある所で急に止めるのではなく、なめらかな曲線で待たせる作りです。dmu_tx.cのコメントにアスキーアートで描かれた2枚のグラフ(普通の目盛りと対数の目盛り)が、今回いちばん印象に残りました。
行番号と既定値は9d59e8e時点のものです。図は自分で読んで起こしたもので、細部はGitHubの該当行で確かめてください。行番号はGitHubの該当行へのリンクです。
| 関数 | ファイル | 行 | この記事での役割 |
|---|---|---|---|
txg_sync_thread() | txg.c | 510 | syncのきっかけを待ち、txgを書き出す |
txg_quiesce() | txg.c | 378 | 締め切って、保持数が0になるのを待つ |
txg_hold_open() | txg.c | 309 | open txgに入り、CPUごとの保持数を増やす |
txg_kick() | txg.c | 811 | syncスレッドを急かす |
dsl_pool_need_dirty_delay() | dsl_pool.c | 992 | 合計が60%を超えたかを見る |
dsl_pool_need_dirty_sync() | dsl_pool.c | 1008 | そのtxgの分が20%を超えたかを見る |
dsl_pool_dirty_space() | dsl_pool.c | 1019 | dirtyデータを数え、必要ならsyncを急かす |
dsl_pool_wrlog_count() | dsl_pool.c | 638 | ZILのログデータを数える |
dmu_tx_delay() | dmu_tx.c | 964 | 1件あたりの最小時間を計算して眠る |
dmu_tx_try_assign() | dmu_tx.c | 1055 | 60%の判定と、txgへの割り当て |
dmu_tx_assign() | dmu_tx.c | 1239 | 割り当てを、通るまでやり直す |
dmu_tx_wait() | dmu_tx.c | 1342 | 100%なら下がるまで待ち、遅延を課す |
投稿者: 宮田 | カテゴリー: パフォーマンス | 難易度: 上級