1. はじめに
本記事では、PostgreSQLのパフォーマンスが出ない際、チェックポイントや書き出しプロセスがどう影響しているかを可視化し、最適な設定パラメータを導き出す方法を解説します。
PostgreSQLは更新内容をまず WAL(Write-Ahead Log) に書き、後でまとめてデータファイルに書き出します。この「まとめて書き出す」タイミングが チェックポイント です。
チェックポイントには2つの関連プロセスがあります。
| プロセス | 役割 |
|---|---|
| チェックポインタ(checkpointer) | チェックポイント本体を実行する |
| バックグラウンドライタ(bgwriter) | 平時にダーティバッファを少しずつ書き出し、チェックポイント時のI/Oスパイクを事前に緩和する |
ダーティバッファとは、メモリ上だけで更新され、まだディスクに書き込まれていないデータの事です。バックグラウンドライタ(bgwriter)が十分に機能しているほど、チェックポイント時の一括書き出し量が減り、I/Oスパイクが小さくなります。
この記事では あえて問題のある設定で動かし、pg_stat_bgwriter とログで何が起きているかを観察したうえで、チューニングによって改善するまでを実施しています。
1.1 検証環境と初期化
| 項目 | 内容 |
|---|---|
| OS | AmazonLinux2023 |
| PostgreSQL | 16 |
| インスタンスタイプ | t3.micro (2 vCPU、 1GiB) |
| データ | pgbench scale factor 100(約1,500万行) |
pgbenchの初期化をスケール100で実行します。
pgbench -i -s 100 -U postgres pgbench_test
2. 問題のある状態を作る
まず意図的に悪化させた設定で動かし、何が起きるかを観察します。
2.1 問題が発生する設定内容
| 項目 | 設定値 | 意図 |
|---|---|---|
| shared_buffers | 8MB | 共有メモリを極小にしてバッファが足りない状態を作る |
| checkpoint_timeout | 30s | 30秒ごとに強制的にチェックポイントを発生させる |
| checkpoint_completion_target | 0.001 | チェックポイントの書き出しをほぼ分散させない |
| bgwriter_delay | 10s | バックグラウンドライタ(bgwriter)の動作周期を極端に長くする |
| bgwriter_lru_maxpages | 0 | バックグラウンドライタ(bgwriter)による先行書き出しを無効化する |
| bgwriter_lru_multiplier | 2 | (今回は影響なし) |
| max_wal_size | 126MB | 悪化させるために少ない値 |
2.2 問題が起きている実行結果
# バックグラウンドライタ(bgwriter)の統計情報を初期化
$ psql -U postgres -d pgbench_test -c "SELECT pg_stat_reset_shared('bgwriter');"
# PostgreSQL 停止・OSキャッシュクリア・起動
$ sudo systemctl stop postgresql
$ sync && echo 3 | sudo tee /proc/sys/vm/drop_caches
$ sudo systemctl start postgresql
# pgbenchの実行
$ pgbench -c 15 -j 2 -T 60 -P 5 -U postgres pgbench_test
pgbench (16.12)
starting vacuum...end.
progress: 5.0 s, 1098.4 tps, lat 12.976 ms stddev 10.414, 0 failed
progress: 10.0 s, 1461.6 tps, lat 10.262 ms stddev 5.256, 0 failed
progress: 15.0 s, 803.8 tps, lat 18.655 ms stddev 13.825, 0 failed
progress: 20.0 s, 1636.8 tps, lat 9.160 ms stddev 4.840, 0 failed
progress: 25.0 s, 940.0 tps, lat 15.962 ms stddev 12.782, 0 failed
progress: 30.0 s, 1495.2 tps, lat 9.992 ms stddev 7.806, 0 failed
progress: 35.0 s, 1367.4 tps, lat 11.015 ms stddev 9.409, 0 failed
progress: 40.0 s, 1184.8 tps, lat 12.652 ms stddev 10.432, 0 failed
progress: 45.0 s, 1826.2 tps, lat 8.217 ms stddev 3.100, 0 failed
progress: 50.0 s, 1109.2 tps, lat 13.520 ms stddev 12.407, 0 failed
progress: 55.0 s, 780.2 tps, lat 19.225 ms stddev 18.356, 0 failed 【注目】極端に低くなる
progress: 60.0 s, 1019.2 tps, lat 14.716 ms stddev 12.188, 0 failed
(省略)
tps = 1231.732909 (without initial connection time)
50秒付近でTPSが780まで落ちています。チェックポイントが原因と予想できますが、次のセクションで実際に確認します。
2.3 pg_stat_bgwriterで観察する
pg_stat_bgwriterとは、バックグラウンドプロセス(バックグラウンドライタやチェックポインタ)の活動統計を表示するためのシステムビューです。主に確認できる項目は下記の内容です。
| 項目名称 | コメント |
|---|---|
| checkpoints_timed | スケジュール通りのチェックポイント数 |
| checkpoints_req | 強制チェックポイント数(WAL上限超え)← 要注意 |
| checkpoint_write_time | チェックポイントでの書き込み時間合計(ms) |
| checkpoint_sync_time | チェックポイントでのfsync時間合計(ms) |
| buffers_checkpoint | チェックポイントで書き出したバッファ数 |
| buffers_clean | バックグラウンドライタ(bgwriter)が書き出したバッファ数 |
| buffers_backend | バックエンド自身が書き出したバッファ数 ← 要注意 |
| maxwritten_clean | バックグラウンドライタ(bgwriter)がレート制限で止まった回数 |
| buffers_alloc | 新規割り当てバッファ数 |
確認用のSQLです。
SELECT
checkpoints_timed,
checkpoints_req,
ROUND(checkpoint_write_time) AS write_ms,
ROUND(checkpoint_sync_time) AS sync_ms,
buffers_checkpoint,
buffers_clean,
buffers_backend,
maxwritten_clean,
buffers_alloc
FROM pg_stat_bgwriter;
2.4 警戒シグナル(3つ)
(1) checkpoints_req が多い
WALが max_wal_size を超えて強制チェックポイントが走っています。スケジュール通りに分散されず、突発的なI/Oスパイクが発生します。
(2) buffers_backend が多い
バックグラウンドライタ(bgwriter)が追いつかず、クエリを実行しているバックエンドプロセス自身がディスク書き出しを行っています。クエリの遅延に 直接 影響するため、最も避けたい状態です。
(3) maxwritten_clean が多い場合(今回は0です)
バックグラウンドライタ(bgwriter)がレート制限(bgwriter_lru_maxpages)に引っかかって途中で止まっています。bgwriter_lru_maxpages を増やすことで解消できます。
2.5 実測値を読む
今回の実行後に確認した内容がこちらです。
$ psql -U postgres -d pgbench_test -f ./pgsql/check_bgwriter.sql
checkpoints_timed | checkpoints_req | write_ms | sync_ms | buffers_checkpoint | buffers_clean | buffers_backend | maxwritten_clean | buffers_alloc
--------------------------------------------------------------------------------------------------------------------------------------------
5 | 6 | 1389 | 16468 | 3325 | 0 | 77914 | 0 | 149414
(1 row)
-
checkpoints_req=6:60秒間で6回、WAL上限超えによる強制チェックポイントが発生 -
buffers_backend=77914:バックエンド自身の書き出しが多発。
$$77,914 \times 8\text{ KB} = 623,312\text{ KB} \approx 608\text{ MB}$$ -
maxwritten_clean=0:バックグラウンドライタ(bgwriter)がレート制限で止まった回数は無い
通常は バックグラウンドライタ(bgwriter)やチェックポインタ(checkpointer)が裏側で書き出すべきところを、メモリ(shared_buffers)に空きがないため、ユーザーのクエリをさばいている backend process が「自分で掃除(書き出し)をしないと新しいデータが読み込めない」状態に陥っています。これがTPS低下の正体です。このように、先ほどのTPS低下の原因が、クエリのプロセスが直接ディスクに書き出している事が確認できました。
2.6 log_checkpointsで時系列を追う
pg_stat_bgwriter では累積値しか見えません。TPS低下とチェックポイントの発生タイミングを照合するには log_checkpoints が有効です。
# postgresql.conf
log_checkpoints = on
設定すると以下のようなログが出力されます。
別ウィンドウで下記コマンドを実行するとPostgreSQLのログでも、問題が発生している事が確認できます。
「checkpoint starting」に続いて、walなら強制実行で、timeならスケジュール実行です。
$ sudo tail -f /var/lib/pgsql/data/log/postgresql-Sat.log
(省略)
LOG: checkpoint starting: wal ← WAL上限超えによる強制実行
LOG: checkpoint complete: wrote 363 buffers (35.4%); 0 WAL file(s) added, 6 removed, 0 recycled; write=0.479 s, sync=3.721 s, total=4.252 s; sync files=9, longest=1.823 s, average=0.414 s; distance=98285 kB, estimate=98344 kB; lsn=16/563F5228, redo lsn=16/54005B68
LOG: checkpoints are occurring too frequently (7 seconds apart)
HINT: Consider increasing the configuration parameter "max_wal_size".
LOG: checkpoint starting: time ← スケジュール通りの実行
LOG: checkpoint complete: wrote 653 buffers (63.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.076 s, sync=0.005 s, total=0.087 s; sync files=20, longest=0.002 s, average=0.001 s; distance=7754 kB, estimate=89280 kB; lsn=16/6079DCA0, redo lsn=16/6079DC68
(省略)
チェックポイントが発生するトリガーは、この3つです。
| トリガー | 設定パラメータ | ログ上の表示 |
|---|---|---|
| 一定時間経過(スケジュール) | checkpoint_timeout |
checkpoint starting: time |
| WAL蓄積量が上限超え(強制) | max_wal_size |
checkpoint starting: wal |
| 手動実行 |
CHECKPOINT コマンド |
checkpoint starting: immediate |
checkpoint starting: wal が頻発している場合、WAL書き込み速度に対して max_wal_size が小さすぎることを示します。
2.7 チェックポイントログの読み方
ログの意味はこちらです。
| フィールド | 意味 |
|---|---|
wrote N buffers (X%) |
書き出したバッファ数と全shared_buffersに対する割合 |
distance |
前回チェックポイントからのWAL量 |
estimate |
次回チェックポイントまでの推定WAL量 |
write |
バッファ書き出し時間 |
sync |
fsync時間(ディスクへの同期待ち) |
強制チェックポイントでは wrote N buffers の割合が大きく、write 時間も長くなります。この間、クエリのレイテンシが上昇します。
pgbenchの -P オプションで5秒ごとのTPS変化を見る事で、ログのチェックポイント発生時刻と照合すると因果関係が明確になります。
progress: 45.0 s, 1826.2 tps, lat 8.217 ms
progress: 50.0 s, 1109.2 tps, lat 13.520 ms ← チェックポイント発生でTPS低下
progress: 55.0 s, 780.2 tps, lat 19.225 ms ← 強制チェックポイントでさらに低下
progress: 60.0 s, 1019.2 tps, lat 14.716 ms
3. チューニング:チェックポインタ(checkpointer)系の設定変更
観察で問題が特定できたので、設定を変えて改善します。まずチェックポインタ(checkpointer)系から着手します。
3.1 設定の全体像
| 項目 | 設定値 | 意図 |
|---|---|---|
| shared_buffers | 8MB | 一旦 8MBのまま |
| checkpoint_timeout | 15min | 30秒ごとを15分ごとに変更 |
| checkpoint_completion_target | 0.9 | 0.001から0.9に書き出しを分散させる設定へ変更 |
| bgwriter_delay | 10s | バックグラウンドライタ(bgwriter)関係は変更なし |
| bgwriter_lru_maxpages | 0 | 同上 |
| bgwriter_lru_multiplier | 2 | 同上 |
| max_wal_size | 4GB | 126MBから4GBに拡張(強制的なチェックポイントが発生しにくくさせる) |
max_wal_size を増やすと強制チェックポイントが減りますが、クラッシュリカバリ時間が増加します。checkpoint_completion_target を大きくするとI/Oが時間的に分散され、スパイクが緩和されます。
3.2 チェックポインタ(checkpointer)系改善後の実行
統計情報を初期化、キャッシュをクリアして、実行します。
# バックグラウンドライタ(bgwriter)の統計情報を初期化
$ psql -U postgres -d pgbench_test -c "SELECT pg_stat_reset_shared('bgwriter');"
# PostgreSQL 停止・OSキャッシュクリア・起動
$ sudo systemctl stop postgresql
$ sync && echo 3 | sudo tee /proc/sys/vm/drop_caches
$ sudo systemctl start postgresql
$ sudo pgbench -c 15 -j 2 -T 60 -P 5 -U postgres pgbench_test
pgbench (16.12)
starting vacuum...end.
progress: 5.0 s, 1551.0 tps, lat 9.431 ms stddev 4.498, 0 failed
progress: 10.0 s, 1313.2 tps, lat 11.421 ms stddev 6.890, 0 failed
progress: 15.0 s, 958.2 tps, lat 15.653 ms stddev 9.339, 0 failed
progress: 20.0 s, 1457.0 tps, lat 10.285 ms stddev 7.529, 0 failed
progress: 25.0 s, 803.6 tps, lat 18.663 ms stddev 14.498, 0 failed
progress: 30.0 s, 1220.4 tps, lat 12.304 ms stddev 12.692, 0 failed
progress: 35.0 s, 1523.8 tps, lat 9.828 ms stddev 6.931, 0 failed
progress: 40.0 s, 1328.6 tps, lat 11.303 ms stddev 8.059, 0 failed
progress: 45.0 s, 1087.2 tps, lat 13.800 ms stddev 9.098, 0 failed
progress: 50.0 s, 1708.6 tps, lat 8.674 ms stddev 5.123, 0 failed
progress: 55.0 s, 1245.0 tps, lat 12.178 ms stddev 8.687, 0 failed
progress: 60.0 s, 1450.8 tps, lat 10.321 ms stddev 6.630, 0 failed
(省略)
tps = 1306.309570 (without initial connection time)
3.3 チェックポインタ(checkpointer)系チューニング後の確認
pg_stat_bgwriterの統計情報を確認します。
checkpoints_timed | checkpoints_req | write_ms | sync_ms | buffers_checkpoint | buffers_clean | buffers_backend | maxwritten_clean | buffers_alloc
--------------------------------------------------------------------------------------------------------------------------------------------
0 | 0 | 0 | 0 | 0 | 0 | 84485 | 0 | 159069
checkpoints_req が 6 から 0 に、buffers_backend が 77,914 から 84,485とほぼ変わらない結果になっています。強制の書き出しは無くなりましたが、直接書き込みは大量に発生している状況です。これは、共有メモリ(shared_buffers)が小さすぎるため、バッファがすぐに埋まってしまい、ディスク書き出しが発生します。max_wal_sizeを増やしてチェックポイントを減らしても、共有メモリ(shared_buffers)が8MBのままでは、結局すぐにメモリが溢れてバックエンドプロセスが書き出しを行うため、根本的な性能改善には至らないことが数値から分かります。
⚠️ 注意点
max_wal_sizeを大きくするとクラッシュリカバリ時のWAL適用時間が増加します。
本番環境ではarchive_modeや PITR の設計と合わせて検討してください。また
max_wal_sizeを大きくした分、pg_walディレクトリのディスク使用量が増加します。ディスク残量にも注意してください。
4. チューニング:バックグラウンドライタ(bgwriter)系の設定変更
buffers_backend と maxwritten_clean がまだ残っている場合、バックグラウンドライタ(bgwriter)系の設定も調整します。
4.1 設定の全体像
| 項目 | 設定値 | 意図 |
|---|---|---|
| shared_buffers | 512MB | 共有メモリは大きく上げておく |
| checkpoint_timeout | 15min | *チェックポインタ系の改善後のまま |
| checkpoint_completion_target | 0.9 | 同上 |
| bgwriter_delay | 100ms | 10秒ごとに動作から100ミリ秒ごとに動作に変更 |
| bgwriter_lru_maxpages | 300 | 一回の書き込みサイズを0から300個書き出すように変更 |
| bgwriter_lru_multiplier | 2 | 変更なし(次ラウンドの書き出し予測倍率) |
| max_wal_size | 4GB | 変更なし |
bgwriter_lru_maxpages を増やすことで1ラウンドの書き出し量を増やせます。(今回は発生していませんが、maxwritten_clean が多い場合、バックグラウンドライタ(bgwriter)がレート制限に引っかかって十分に書き出せていません。)
4.2 バックグラウンドライタ(bgwriter)系改善後の実行
こちらに関しても設定変更後に、再度統計情報を初期化して、OS等のキャッシュをクリアして実行してみます。
# バックグラウンドライタ(bgwriter)の統計情報を初期化
$ psql -U postgres -d pgbench_test -c "SELECT pg_stat_reset_shared('bgwriter');"
# PostgreSQL 停止・OSキャッシュクリア・起動
$ sudo systemctl stop postgresql
$ sync && echo 3 | sudo tee /proc/sys/vm/drop_caches
$ sudo systemctl start postgresql
$ sudo pgbench -c 15 -j 2 -T 60 -P 5 -U postgres pgbench_test
pgbench (16.12)
starting vacuum...end.
progress: 5.0 s, 1291.8 tps, lat 11.236 ms stddev 12.909, 0 failed
progress: 10.0 s, 1214.0 tps, lat 12.447 ms stddev 11.750, 0 failed
progress: 15.0 s, 1840.6 tps, lat 8.144 ms stddev 2.937, 0 failed
progress: 20.0 s, 1960.4 tps, lat 7.653 ms stddev 2.458, 0 failed
progress: 25.0 s, 1964.4 tps, lat 7.636 ms stddev 2.755, 0 failed
progress: 30.0 s, 1749.0 tps, lat 8.565 ms stddev 4.146, 0 failed
progress: 35.0 s, 1595.3 tps, lat 9.408 ms stddev 5.594, 0 failed
progress: 40.0 s, 1797.0 tps, lat 8.346 ms stddev 4.363, 0 failed
progress: 45.0 s, 1842.6 tps, lat 8.136 ms stddev 3.162, 0 failed
progress: 50.0 s, 1676.6 tps, lat 8.947 ms stddev 3.996, 0 failed
progress: 55.0 s, 1736.0 tps, lat 8.637 ms stddev 3.802, 0 failed
progress: 60.0 s, 1740.8 tps, lat 8.624 ms stddev 3.942, 0 failed
(省略)
tps = 1701.976932 (without initial connection time)
4.3 バックグラウンドライタ(bgwriter)系チューニング後の確認
統計情報の確認結果です。
checkpoints_timed | checkpoints_req | write_ms | sync_ms | buffers_checkpoint | buffers_clean | buffers_backend | maxwritten_clean | buffers_alloc
--------------------------------------------------------------------------------------------------------------------------------------------
0 | 0 | 0 | 0 | 0 | 64850 | 1374 | 30 | 115354
(1 row)
buffers_clean が増加し buffers_backend が減少しました。バックグラウンドライタ(bgwriter)が先行して書き出すことで、バックエンドの書き出し負荷がほぼ解消されています(77,914から1,374へ改善)。
5. まとめ
チェックポインタとバックグラウンドライタ関係のチューニングの結果をまとめます。
5.1 チューニング前後のTPS比較
TPSの平均と最小値(低いほど性能遅延)や、pg_stat_bgwriterの統計情報を比較します。
| 設定 | avg TPS | min TPS | checkpoints_req | buffers_backend | maxwritten_clean |
|---|---|---|---|---|---|
| 悪化設定(shared_buffers=8MB) | 1,231 | 780 | 6 | 77,914 | 0 |
| チェックポインタ(checkpointer)系チューニング後 | 1,306 | 803 | 0 | 84,485 | 0 |
| + バックグラウンドライタ(bgwriter)系チューニング後 | 1,701 | 1214 | 0 | 1374 | 30 |
5.2 統計情報の確認から設定変更までの流れ
pg_stat_bgwriterの見るポイントをまとめます。
pg_stat_bgwriter を確認
│
├─ checkpoints_req が多い
│ └─ max_wal_size を増やす(126MB → 4GB)
│ checkpoint_timeout を延ばす(30s → 15min)
│
├─ buffers_backend が多い(checkpoints_req と連動することが多い)
│ └─ 上記のチェックポインタ(checkpointer)系設定を先に試す
│ 改善しなければ bgwriter_lru_maxpages を増やす
│
└─ maxwritten_clean が多い
└─ bgwriter_lru_maxpages を増やす(0 → 300)
bgwriter_delay を短くする(10s → 100ms)
5.3 設定変更の優先順位
postgresql.confで変更するポイントをまとめます。
| 優先度 | 設定 | 効果 |
|---|---|---|
| 高 |
max_wal_size を増やす |
強制チェックポイントを減らす |
| 高 |
checkpoint_timeout を延ばす |
スケジュール間隔を広げI/O分散 |
| 中 | checkpoint_completion_target = 0.9 |
I/Oスパイクを時間的に分散 |
| 中 |
bgwriter_lru_maxpages を増やす |
バックグラウンドライタ(bgwriter)の先行書き出しを強化 |
| 低 |
bgwriter_delay を短くする |
バックグラウンドライタ(bgwriter)の起動頻度を上げる |
実運用では、checkpoint complete のログを出力して、落ち着いている事を確認する必要があります。
次回は、ロックを確認していきたいです。