PostgreSQLの修正済みのバグ分析1(Prevent archive recovery from scanning non-existent WAL files)

はじめに

この記事は執筆者がPostgreSQLの理解を深めるために実施している、修正済みのバグの分析記事です。
PostgreSQLの知識が不足している執筆者のスキルアップが目的なので、修正方法や実装の詳細に触れるというよりも、基本的な動作の理解に重点を置いています。
なるべくシンプルなバグの修正や興味のある機能ブロックのバグから初めて、徐々に深堀できたらと考えています。

対象のバグ

PostgreSQL 11.8で修正済みのバグです。
Prevent archive recovery from scanning non-existent WAL files.
https://github.com/postgres/postgres/commit/683e0ef5530f449f0f913de579b4f7bcd31c91fd

バグの概要

コミットログのURLにバグの概要や再現方法についての記載があります。
https://www.postgresql.org/message-id/[e-mail]

Reproduced 11.2,11.6.

If PostgreSQL starts recovery and finds a history file for a timeline that
is higher than current one, it will request file with the segment for the
future timeline (that most likely doesn't exist yet) and only then it will
request file with the segment for current timeline.
If archive is located on remote storage it can take huge time to find that
segments for the future timelines are not exist yet and therefore recovery
can take too long.

Example:

recovery.conf:
restore_command = 'echo -e "Searching WAL: %f, location: %p";
/usr/bin/pgbackrest --stanza=platform archive-get %f "%p"'
recovery_target_timeline = 'latest'
standby_mode = 'on'

Postgres log during startup:

2019-12-06 07:11:16 CST LOG: database system was shut down in recovery
at 2019-12-06 07:11:08 CST
Searching WAL: 00000022.history, location: pg_wal/RECOVERYHISTORY
2019-12-06 07:11:16 CST LOG: restored log file "00000022.history" from
archive
Searching WAL: 00000023.history, location: pg_wal/RECOVERYHISTORY
2019-12-06 07:11:16 CST LOG: entering standby mode
Searching WAL: 00000022.history, location: pg_wal/RECOVERYHISTORY
2019-12-06 07:11:16 CST LOG: restored log file "00000022.history" from
archive
Searching WAL: 00000022000018C60000003F, location: pg_wal/RECOVERYXLOG
Searching WAL: 00000021000018C60000003F, location: pg_wal/RECOVERYXLOG
2019-12-06 07:11:20 CST LOG: restored log file
"00000021000018C60000003F" from archive
Searching WAL: 00000021.history, location: pg_wal/RECOVERYHISTORY
2019-12-06 07:11:20 CST LOG: restored log file "00000021.history" from
archive
Searching WAL: 00000022000018BF0000001B, location: pg_wal/RECOVERYXLOG
Searching WAL: 00000021000018BF0000001B, location: pg_wal/RECOVERYXLOG
2019-12-06 07:11:27 CST LOG: restored log file
"00000021000018BF0000001B" from archive
2019-12-06 07:11:27 CST LOG: redo starts at 18BF/1B311260
Searching WAL: 00000022000018BF0000001C, location: pg_wal/RECOVERYXLOG
Searching WAL: 00000021000018BF0000001C, location: pg_wal/RECOVERYXLOG
2019-12-06 07:11:34 CST LOG: restored log file
"00000021000018BF0000001C" from archive
Searching WAL: 00000022000018BF0000001D, location: pg_wal/RECOVERYXLOG
Searching WAL: 00000021000018BF0000001D, location: pg_wal/RECOVERYXLOG
2019-12-06 07:11:40 CST LOG: restored log file
"00000021000018BF0000001D" from archive
Searching WAL: 00000022000018BF0000001E, location: pg_wal/RECOVERYXLOG
Searching WAL: 00000021000018BF0000001E, location: pg_wal/RECOVERYXLOG
2019-12-06 07:11:46 CST LOG: restored log file
"00000021000018BF0000001E" from archive
Searching WAL: 00000022000018BF0000001F, location: pg_wal/RECOVERYXLOG
Searching WAL: 00000021000018BF0000001F, location: pg_wal/RECOVERYXLOG
2019-12-06 07:11:53 CST LOG: restored log file
"00000021000018BF0000001F" from archive

As you can see Postgres tries to restore 00000022* WALs before timeline
switch LSN has been reached while restoring 00000021*.

簡潔にまとめると、次の通りです。

• スタンバイデータベースでリカバリーを実行中に発生する事象です。
• スタンバイデータベースがアーカイブされたWALセグメントを取得する際に、本来取得処理が不要なはずの将来のtime line idのWALセグメントを取得しようとしてしまいます。
• 将来のtime line idのWALセグメントは存在しないので、そのtime line idでの取得処理は失敗しますが、最終的に合致するtime line idでWALセグメントを取得するので、機能面では特に問題はないです。
• しかしながら、アーカイブログは多くの場合にネットワーク越しにWALセグメントを取得する必要があるので、実際には存在しないファイルの取得を試みるだけでもコストが高く、時間のかかる無駄な処理なので省く必要があります。

前提知識

timelineid, timeline historyファイルに関しては次の公式ドキュメント及び外部ページの記事が詳しいです。

25.3. Continuous Archiving and Point-in-Time Recovery (PITR)
https://www.postgresql.org/docs/11/continuous-archiving.html

Chapter 10 Base Backup & Point-in-Time Recovery
http://www.interdb.jp/pg/pgsql10.html

また、本バグの修正対象であるXLogFileReadAnyTLI関数のふるまいを理解する必要もあります。
https://github.com/postgres/postgres/blob/REL_11_8/src/backend/access/transam/xlog.c#L3679

加えて関数の引数であるXLogSegNoの意味及び、WALセグメントのファイル名との関係性を理解することも大事です。
https://github.com/postgres/postgres/blob/7559d8ebfa11d98728e816f6b655582ce41150f3/src/include/access/xlogdefs.h#L38
https://github.com/postgres/postgres/blob/c6b92041d38512a4176ed76ad06f713d2e6c01a8/src/include/access/xlog_internal.h#L155

再現方法

次のような操作により、リカバリー対象のクラスターのtime line idよりも新しいtimeline history fileをあらかじめ用意しておく必要があります。

1. base backupを取得 -> このバックアップを二回利用するので取っておくこと
2. 「1.」のバックアップをもとに新しいクラスターを作成し、リカバリー設定で起動します -> time line id=2となります
3. 「2.」のクラスターでWALセグメントをアーカイブしておきます(time line id=2のWALセグメントの保存)
4. 「1.」のバックアップをもとに新しいクラスターを作成し、リカバリー設定(スタンバイ)で起動します

修正方法

次のコミットにあるように、WALセグメントの取得を試みる前にtime line historyに記録された開始時LSNからWALセグメントの番号を抽出して、取得対象のWALセグメントの番号と比較し、当該timelineに含まれないWALセグメントである場合には読み飛ばします。
https://github.com/postgres/postgres/commit/683e0ef5530f449f0f913de579b4f7bcd31c91fd

再現時のログ

手元の環境で再現させたときのログです。
報告のとおり、繰り返し存在しないはずのtime line id=2のWALセグメントを取得しようと試みていることがわかります。

アーカイブディレクトリの中身

postgres@DESKTOP-P3FQ6DK:~$ ls -lt archive_dir/
total 65544
-rw------- 1 postgres postgres 16777216 Jul  8 18:00 000000020000000000000004
-rw------- 1 postgres postgres       41 Jul  8 17:58 00000002.history
-rw------- 1 postgres postgres 16777216 Jul  7 20:24 000000010000000000000003
-rw------- 1 postgres postgres      323 Jul  7 20:18 000000010000000000000002.00000028.backup
-rw------- 1 postgres postgres 16777216 Jul  7 20:18 000000010000000000000002
-rw------- 1 postgres postgres 16777216 Jul  7 20:17 000000010000000000000001

postgres@DESKTOP-P3FQ6DK:~/archive_dir$ cat 00000002.history
1       0/4000000       no recovery target specified

postgres=# SELECT pg_walfile_name_offset('0/4000000');
    pg_walfile_name_offset
------------------------------
 (000000010000000000000003,0)
(1 row)

PostgreSQLログ

2020-07-08 18:01:48.060 JST [13372] LOG:  database system was interrupted; last known up at 2020-07-07 20:17:40 JST
-e Searching WAL: 00000002.history, location: pg_wal/RECOVERYHISTORY
2020-07-08 18:01:48.352 JST [13372] LOG:  restored log file "00000002.history" from archive
-e Searching WAL: 00000003.history, location: pg_wal/RECOVERYHISTORY
cp: cannot stat '/var/lib/postgresql/archive_dir/00000003.history': No such file or directory
2020-07-08 18:01:48.353 JST [13372] LOG:  entering standby mode
-e Searching WAL: 00000002.history, location: pg_wal/RECOVERYHISTORY
2020-07-08 18:01:48.355 JST [13372] LOG:  restored log file "00000002.history" from archive
-e Searching WAL: 000000020000000000000002, location: pg_wal/RECOVERYXLOG
cp: cannot stat '/var/lib/postgresql/archive_dir/000000020000000000000002': No such file or directory
-e Searching WAL: 000000010000000000000002, location: pg_wal/RECOVERYXLOG
2020-07-08 18:01:48.383 JST [13372] LOG:  restored log file "000000010000000000000002" from archive
2020-07-08 18:01:48.529 JST [13372] LOG:  redo starts at 0/2000028
2020-07-08 18:01:48.536 JST [13372] LOG:  consistent recovery state reached at 0/2017448
2020-07-08 18:01:48.537 JST [13370] LOG:  database system is ready to accept read only connections
-e Searching WAL: 000000020000000000000003, location: pg_wal/RECOVERYXLOG
cp: cannot stat '/var/lib/postgresql/archive_dir/000000020000000000000003': No such file or directory
-e Searching WAL: 000000010000000000000003, location: pg_wal/RECOVERYXLOG
2020-07-08 18:01:48.553 JST [13372] LOG:  restored log file "000000010000000000000003" from archive
-e Searching WAL: 000000020000000000000004, location: pg_wal/RECOVERYXLOG
2020-07-08 18:01:48.589 JST [13372] LOG:  restored log file "000000020000000000000004" from archive
-e Searching WAL: 000000020000000000000005, location: pg_wal/RECOVERYXLOG
cp: cannot stat '/var/lib/postgresql/archive_dir/000000020000000000000005': No such file or directory

修正後のログ

time line historyファイルの情報をもとに、存在しないWALセグメントの取得処理は読み飛ばされていることがわかります。

2020-07-08 18:42:40.364 JST [8562] LOG:  database system was interrupted; last known up at 2020-07-07 20:17:40 JST
-e Searching WAL: 00000002.history, location: pg_wal/RECOVERYHISTORY
2020-07-08 18:42:40.510 JST [8562] LOG:  restored log file "00000002.history" from archive
-e Searching WAL: 00000003.history, location: pg_wal/RECOVERYHISTORY
cp: cannot stat '/var/lib/postgresql/archive_dir/00000003.history': No such file or directory
2020-07-08 18:42:40.512 JST [8562] LOG:  entering standby mode
-e Searching WAL: 00000002.history, location: pg_wal/RECOVERYHISTORY
2020-07-08 18:42:40.514 JST [8562] LOG:  restored log file "00000002.history" from archive
-e Searching WAL: 000000010000000000000002, location: pg_wal/RECOVERYXLOG
2020-07-08 18:42:40.617 JST [8562] LOG:  restored log file "000000010000000000000002" from archive
2020-07-08 18:42:40.667 JST [8562] LOG:  redo starts at 0/2000028
2020-07-08 18:42:40.677 JST [8562] LOG:  consistent recovery state reached at 0/2017448
2020-07-08 18:42:40.677 JST [8560] LOG:  database system is ready to accept read only connections
-e Searching WAL: 000000010000000000000003, location: pg_wal/RECOVERYXLOG
2020-07-08 18:42:40.816 JST [8562] LOG:  restored log file "000000010000000000000003" from archive
-e Searching WAL: 000000020000000000000004, location: pg_wal/RECOVERYXLOG
2020-07-08 18:42:41.138 JST [8562] LOG:  restored log file "000000020000000000000004" from archive
2020-07-08 18:42:41.162 JST [8562] LOG:  record with incorrect prev-link 0/30002A8 at 0/4000028
-e Searching WAL: 00000003.history, location: pg_wal/RECOVERYHISTORY
cp: cannot stat '/var/lib/postgresql/archive_dir/00000003.history': No such file or directory
-e Searching WAL: 000000020000000000000004, location: pg_wal/RECOVERYXLOG
2020-07-08 18:42:41.186 JST [8562] LOG:  restored log file "000000020000000000000004" from archive
2020-07-08 18:42:41.212 JST [8562] LOG:  record with incorrect prev-link 0/30002A8 at 0/4000028
-e Searching WAL: 00000003.history, location: pg_wal/RECOVERYHISTORY
cp: cannot stat '/var/lib/postgresql/archive_dir/00000003.history': No such file or directory

感想

実際にPostgreSQLを運用している方はtime line idが行ったり来たりするのを意識しながら、バックアップや、リストア、レプリカの構築等を行っているんですかね...
PostgreSQLマイスターな方はtime line idやtime line historyファイルの存在をどのように管理しているのかとても気になります。