はじめに

2019年～2020年にかけてサーバーリプレイスの移行作業(Windows Server 2008R2 + Oracle 11g → Windows Server 2016 + PostgreSQL 9.6)を行いました。
そして、PostgreSQL 9.6のサポート終了期限(EOL＝End Of Life)が2021/11と近づいてきたことにより、某N社のサポート最新版(2021/07現在)であるPostgreSQL 12にメジャーバージョンアップすることになりました。

バージョン	初期リリース日	サポート終了期限
14	2021年09月30日	2026年11月12日
13	2020年09月24日	2025年11月13日
12	2019年10月3日	2024年11月14日
11	2018年10月18日	2023年11月9日
10	2017年10月5日	2022年11月10日
9.6	2016年09月29日	2021年11月11日

以前書いた記事はPostgreSQL 9.6用であり、今回のPostgreSQL 12までに以下の変更があったため、指定した時間までリカバリする方法を再度確立しておきたいと思います。記事内容は前記事をほぼ踏襲しています。

ログファイル出力先のディレクトリ名がpg_logからlogへ変更
WALに関連するディレクトリ／関数／コマンドなどでxlogがwal、locationがlsnに変更
コミットログの出力先ディレクトリ名がpg_clogからpg_xactへ変更
recovery.confはなくなりpostgresql.confに統合
リカバリ時はrecovery.signal、スタンバイ時はstandby.signal を置くようにする

バックアップ

バックアップには、大きく論理バックアップと物理バックアップがあります。

論理バックアップ

サーバーを起動したまま、pg_dumpコマンドでバックアップを取得します。
デフォルト形式の場合、データベースに格納されたデータをSQLの形で抽出します。
pg_dumpオプションによってテーブル指定やスキーマ指定が可能です。

pg_dumpコマンドでは、globalデータと呼ばれるロールやテーブルスペースなどの情報はバックアップされません。これらの情報も含めてデータベースクラスタ全体をバックアップしたい場合は、pg_dumpallコマンドを使えばそれらも全てコピーすることができます。pg_dumpallコマンドは、内部動作としてはpg_dumpコマンドを呼び出しています。

論理バックアップは、簡単に取得できてサイズも小さくなりますが、リカバリには一からデータをDBに投入し直すので時間がかかる傾向があります。

物理バックアップ

オフライン・バックアップ

サーバーを停止後、dataフォルダ以下をまるまるコピーします。

オンライン・バックアップ

pg_basebackupコマンドを使用して、サーバーを起動したままdataフォルダ以下をまるまるコピーします。また、WALアーカイブログも取得します。
オンラインなのでバックアップ中に更新があったデータを反映させる必要があります。そこで WALという仕組みを利用します。

WAL(Write Ahead Logging)とはログ先行書き込みのことで、トランザクションの処理の内容をデータファイルに反映する前に、ログファイル(WALセグメントファイル)に書き出そうという動きをさせるものです。

WALアーカイブログは、PostgreSQLが出力したトランザクションログ(WAL)ファイルを別の場所にコピーすることです。WALファイルはデフォルト設定では直近の一定数しか保存されず、古くなったものは削除もしくは再利用されていきます。そのため、リカバリに使えるようにWALファイルを別の場所に保存しておく必要があります。

WALアーカイブログを適用することで、DBの状態を任意の時刻の時点に戻すことができます。

pg_basebackup コマンド使用前の設定

「FATAL: pg_hba.conf にホスト"127.0.0.1"、ユーザ"postgres", SSL無効用のエントリがありません.」のエラーが出た場合、以下のコメントアウトを外す。

pg_hda.conf

host    replication     postgres        127.0.0.1/32            md5
host    replication     postgres        ::1/128                 md5

postgresql.confの max_wal_sender 設定のデフォルトは 10 です。PostgreSQL 9.6時のデフォルトは 0 でした。最低でも 1 以上でないと pg_basebackupコマンドは実行できない。

postgresql.conf

max_wal_sender = 10

WALアーカイブの設定をします。
WALアーカイブを例「D:\PostgreSQL\ARCHIVELOG」フォルダにコピーします。

postgresql.conf

wal_level = replica  # リカバリに使える情報を保存するようにminimal以外の値にしておく
archive_mode = on   # PostgreSQLによるWALアーカイブ処理を有効にする
archive_command = 'copy "%p" "D:\\PostgreSQL\\ARCHIVELOG\\%f"'  # WALアーカイブ処理時に使われるコマンドを指定する　%pはwalファイル名、%fはwalアーカイブファイル名が自動で入力される

※archive_commandのフォルダは先に作成しておく。
※archive_commandで「"%p"」などのようにパスの部分をダブルクォテーションでくくらないと正しく実行されません。
※SELECT pg_switch_wal()でarchive_commandの内容を実行できます。

他のWALアーカイブの設定
postgresql.confにある archive_timeout と wal_keep_segments の設定

【archive_timeoutの設定】
archive_timeoutはトランザクションがほとんど発生しない「なぎ」のとき、WALにたまった内容がいつまで経ってもアーカイブされないことを防ぐ。デフォルトでは0（機能無効）

検証で archive_timeout = 60 に設定したのですが、容量が無駄との思いにいたりデフォルトの0に戻しました。
archive_timeout = 60 とした場合、16MB60回/時24時間=23040MB/日≒23GB/日が発生しうる。

【wal_keep_segmentsの設定】
検証でarchive_timeout = 60 としていた際にバックアップ後のpg_logに下記のエラーが発生していました。※archive_timeout と関連しているかは不明

2019-08-06 02:18:35 JST ERROR:  requested WAL segment 000000010000005A000000D1 has already been removed
日本語訳：要求された wal セグメント * はすでに削除されています。

対処として、wal_keep_segmentsをゼロ以外の値に設定する。
これは、ストリームの危険性が追いつかなくなるのを防ぐためです。
ただしpg_basebackupを使用する場合は、 – checkpoint = fastも忘れないでください。
https://codeday.me/jp/qa/20190609/972945.html

postgresql.conf

#wal_keep_segments = 0		# in logfile segments, 16MB each; 0 disables
↓
wal_keep_segments = 128

backup.bat の見直し、※PostgreSQL 12では、-xオプションはなくなり、「-X f」が同じ機能となる。

backup.bat

pg_basebackup -U postgres -D "%bkPath%" -F t -z　-x --checkpoint=fast
↓
pg_basebackup -U postgres -D "%bkPath%" -F t -z　-X f --checkpoint=fast

リストア

論理バックアップからのリストア

pg_dumpコマンドのバックアップは、スクリプト形式(デフォルト)とアーカイブ形式があり、それによりリストア方法が違います。

スクリプト形式は平文のSQL文なので、psqlコマンドでリストアします。
アーカイブ形式はバイナリの形で出力されているため、pg_restoreコマンドでリストアします。

物理バックアップからのリストア

リストアは以下の手順で行います。

PostgreSQLサービスの停止
リストア(Dataフォルダの書き戻し)
PostgreSQLサービスの開始

リカバリ

リストアとリカバリとは区別しないで使うときもあるが、今回は分けました。

リストアはバックアップデータを、バックアップを取ったときと同じ状態に物理的に復元すること
リカバリはリストアしたデータに何かの処理をして最新の状態や正常な状態に復旧させること

ポイントインタイムリカバリ(PITR)

ポイントインタイムリカバリ(PITR:Point In Time Recovery)はベースバックアップにアーカイブログ(WALログ)を適用することで任意の時点まで復元することが可能です。復元ポイントやリカバリの設定はpostgresql.confに記述します。
※PostgreSQL 12では、recovery.confはなくなりpostgresql.confに統合されました。

WALレコードの適用までの流れ

リカバリを開始してWALレコードを適用するまでの流れは次のようになっている。

pg_controlファイルを読み込む
recovery.confを読み込む
backup_labelを読み込む
pg_controlファイルを更新し、backup_labelを削除する
必要なWALを繰り返し適用する

※backup_labelファイルから適用を開始すべきWALの位置を取得できなかった場合は、pg_controlファイルの情報を元にリカバリを開始します。

pg_controlファイルは、バイナリファイルなので通常のエディタでは内容を確認できません。そのためにpg_controldataコマンドが用意されています。
pg_controldataコマンドを実行すると最終チェックポイントのREDO WALファイルが分かります。

pg_controldata -D C:\PostgreSQL\12\data

最終チェックポイント

PostgreSQLはトランザクションをメモリ上で処理している。メモリ上に持っている間にPostgreSQLがクラッシュするとコミットしたはずのデータが消えてしまう。それを防ぐためにコミットした分だけをWALという形で書き込んでいる。しかし、いつまでもWALだけに持っておくわけにいかないので、あるタイミングでWALの内容をテーブルファイルに反映しなければならない。そのタイミングがチェックポイント(CHECKPOINT)である。
その間隔は設定checkpoint_timeoutでデフォルトは5分だが30分が推奨される。最終チェックポイントは直近でチェックポイントされた情報を示す。

クラッシックリカバリ時は最終チェックポイント以降のWALを適用すれば最新に戻せる。

PITRの実施

下記サイトの手順を実際にやってみました。
PostgreSQL 9.6.3で時刻指定のPITR(Point In Time Recovery)を実行する

PITRで利用するデータの格納先を以下に示します。

種類	フォルダ
データベースクラスタ	C:\PostgreSQL\12\data
データベースクラスタの退避先	C:\PostgreSQL\12\data_bk
WALファイル	C:\PostgreSQL\12\data\pg_wal
アーカイブファイル	D:\PostgreSQL\ARCHIVELOG
ベースバックアップ	D:\data_backup

今回の操作の時系列を以下にまとめます。

2021/08/01 13:15:00 テーブルの作成
2021/08/01 13:20:12 1件目のデータ挿入
2021/08/01 13:21:32 2件目のデータ挿入
2021/08/01 13:22:33 3件目のデータ挿入
2021/07/07 13:30:00 ベースバックアップの取得（pg_basebackupの実行）
2021/08/01 14:00:12 4件目のデータ挿入
2021/08/01 14:01:16 5件目のデータ挿入
2021/08/01 14:02:39 6件目のデータ挿入
2021/08/01 14:03:28 7件目のデータ挿入
2021/08/01 14:04:33 8件目のデータ挿入
★----------ここの状態に戻したい----------★
2021/08/01 14:10:34 9件目のデータ挿入 ★誤操作★
2021-08-01 14:15:00 1件目のデータ削除 ★誤操作★
2021-08-01 14:35:00 PostgreSQLを停止し、リカバリ作業開始

手順

(1) テーブルの作成と初期データ挿入
PITRの動作検証用のテーブル（テーブル名：testtbl）を1つ作成し、初期データを3件挿入します。リカバリポイントが分かりやすいように、テーブルにはデータを挿入したタイムスタンプを格納するカラムを持たせます。

-- testtblテーブルを作成
create table testtbl (
  id integer primary key,
  last_update timestamp
);

insert into testtbl values (1, now()); -- 1件目のデータ挿入
insert into testtbl values (2, now()); -- 2件目のデータ挿入
insert into testtbl values (3, now()); -- 3件目のデータ挿入

select * from testtbl; -- テーブルに格納されたデータの確認

id	last_update
1	2021/08/01 13:20:12.117
2	2021/08/01 13:21:32.260
3	2021/08/01 13:22:33.743

(2) ベースバックアップの取得
動作検証用のテーブルにデータが3件入っている状態で、データベースクラスタのベースバックアップを取得します。

pg_basebackup -U postgres -D D:\data_backup --checkpoint=fast --progress

(3) 正常なテーブル更新処理
ベースバックアップ取得後にデータの挿入処理を続けます。ここまでは処理として何の問題もないと仮定します。

insert into testtbl values (4, now()); -- 4件目のデータ挿入
insert into testtbl values (5, now()); -- 5件目のデータ挿入
insert into testtbl values (6, now()); -- 6件目のデータ挿入
insert into testtbl values (7, now()); -- 7件目のデータ挿入
insert into testtbl values (8, now()); -- 8件目のデータ挿入

select * from testtbl; -- テーブルに格納されたデータの確認

id	last_update
1	2021/08/01 13:20:12.117
2	2021/08/01 13:21:32.260
3	2021/08/01 13:22:33.743
4	2021/08/01 14:00:12.991
5	2021/08/01 14:01:16.385
6	2021/08/01 14:02:39.047
7	2021/08/01 14:03:28.537
8	2021/08/01 14:04:33.336

(4) 間違ったテーブル更新処理
ここで必要のない9件目のデータをウッカリ挿入してしまい、これを削除しようとしたが、間違って1件目のデータを削除してしまったとします。

insert into testtbl values (9, now()); -- 間違って9件目のデータ挿入

select * from testtbl; -- テーブルに格納されたデータの確認
id	last_update
1	2021/08/01 13:20:12.117
2	2021/08/01 13:21:32.260
3	2021/08/01 13:22:33.743
4	2021/08/01 14:00:12.991
5	2021/08/01 14:01:16.385
6	2021/08/01 14:02:39.047
7	2021/08/01 14:03:28.537
8	2021/08/01 14:04:33.336
9	2021/08/01 14:10:34.682 -- 不要なデータをウッカリ挿入してしまった

delete from testtbl where id = 1; -- 9件目のデータではなく1件目のデータを間違って削除

select * from testtbl; -- テーブルに格納されたデータの確認

id	last_update
2	2021/08/01 13:21:32.260 -- 1件目のデータが消えてしまった
3	2021/08/01 13:22:33.743
4	2021/08/01 14:00:12.991
5	2021/08/01 14:01:16.385
6	2021/08/01 14:02:39.047
7	2021/08/01 14:03:28.537
8	2021/08/01 14:04:33.336
9	2021/08/01 14:10:34.682 -- 不要な9件目のデータは削除できていない

この状態からPITRでリカバリを行い、データベースを正しい状態に戻します。

データベースのリカバリ

これからデータベースをデータが正しい時の状態にリカバリします。
最新の状態にリカバリするためには下記4つを使用します。

ベースバックアップ
最新のWALファイル
最新のアーカイブファイル
リカバリ設定ファイル(recovery.conf)

これらファイルを使用してデータベースが正常だった時刻（2021年8月1日 14時05分00秒）の状態に戻します。

(1) PostgreSQLの停止
データベースを復旧するに当たり、まずはPostgreSQLを停止します。
GUI上ならタスクマネージャーのサービスタブ「postgresql-x64-12」を選択して「停止」します。

net stop postgresql-x64-12

(2) データベースクラスタの退避
データベースクラスタ内のデータはWALファイル(data/pg_wal)以外はもう使用しません。データベースクラスタ全体をコピーして退避しておきます。これはリカバリが成功してから消せば良いです。
dataフォルダには、NETWORK SERVICEのアクセス権限がついているため、フォルダの中身だけを削除します。

cd C:\PostgreSQL\12
xcopy data data_bk /E /Y /I /D
del /s data\*.*

(3) ベースバックアップからのリストア
pg_basebackupコマンドで取得したベースバックアップをリストアします。リストアといってもベースバックアップのデータをデータベースクラスタのパス（C:\PostgreSQL\12\data）にコピーするだけです。

cd C:\PostgreSQL\12
xcopy D:\data_backup data /E /Y /I /D

(4) 最新のWALファイルを格納
ベースバックアップのファイルを戻しただけだと、ベースバックアップを取得した時点にしかリカバリできないため、最新のWALファイルと最新のアーカイブファイルを使用してロールフォワード(データの更新ログを元にデータベースを再更新)します。
ベースバックアップを取得した時点のWALファイルは使用しないためフォルダごと削除してしまいます。そして最新のWALファイルを適用するため先ほど退避しておいたデータベースクラスタからWALファイルだけを取り出してデータベースクラスタにコピーします。

cd C:\PostgreSQL\12
REM ベースバックアップ時点のWALファイルを削除
rd data\pg_wal /s /q
REM 退避しておいた最新のWALファイルをコピー
xcopy data_bk\pg_wal data\pg_wal /E /Y /I /D

(5) リカバリ設定ファイル作成
データベースクラスタのパス直下(C:\PostgreSQL\12\data)に postgresql.confファイルに、どのアーカイブファイルを使用してリカバリするか、どの時点（時刻）にリカバリするかを記述します。今回はデータベースが正常だった2021年8月1日 14時05分00秒に戻したいとします。アーカイブファイルは「D:\PostgreSQL\ARCHIVELOG」フォルダに格納されています。

データベースクラスタのパス直下(C:\PostgreSQL\12\data)に recovery.signalファイル(中身は空のまま)を作成します。

postgresql.conf

restore_command = 'copy "D:\\PostgreSQL\\ARCHIVELOG\\%f" "%p"'
recovery_target_time = '2021-08-01 14:05:00'

※recovery_target_timeの設定がない場合、リストアできるところまでリストアしようとします。

(6) PostgreSQLの起動
ここまででPITRに必要な情報が揃ったため、PostgreSQLを起動します。起動時にrecovery.signalファイルがあることでPITRが実行されます。
GUI上ならタスクマネージャーのサービスタブ「postgresql-x64-12」を選択して「開始」します。

net start postgresql-x64-12

(7) PITRでのリカバリ完了の確認
先ほど作成したrecovery.signalファイルは、リカバリが正常に終了すると自動で削除されます。そのため、これ以降PostgreSQLを再起動しても、間違ってまたリカバリが実行されることはありません。

pg_logの出力ログ

2021-08-01 14:35:38.717 JST [4188] LOG:  データベースシステムは中断されました: 2021-08-01 13:36:22 JST まで動作していたことは確認できます
2021-08-01 14:35:40.599 JST [4188] LOG:  2021-08-01 14:05:00+09までのポイントインタイムリカバリを開始します
2021-08-01 14:35:40.636 JST [4188] LOG:  ログファイル"000000010000000000000003"をアーカイブからリストアしました
2021-08-01 14:35:40.691 JST [4188] LOG:  REDOを0/3000028から開始します
2021-08-01 14:35:40.695 JST [4188] LOG:  0/3000100 でリカバリの一貫性が確保されました
2021-08-01 14:35:40.703 JST [11656] LOG:  データベースシステムはリードオンリー接続の受け付け準備ができました
2021-08-01 14:35:40.781 JST [4188] LOG:  ログファイル"000000010000000000000004"をアーカイブからリストアしました
2021-08-01 14:35:40.823 JST [4188] LOG:  リカバリ処理はトランザクション504のコミット、時刻2021-08-01 14:10:34.682748+09の前に停止します
2021-08-01 14:35:40.823 JST [4188] LOG:  リカバリは一時停止中です
2021-08-01 14:35:40.823 JST [4188] ヒント:  再開するには pg_xlog_replay_resume() を実行してください

リカバリ、つまりWALからREDOしているのがわかるかと思います。

しかし、recovery.signalファイルは削除されずに残ったままになっていました。ログを見るとリカバリは一時停止中になっています。ヒントとして再開するには pg_xlog_replay_resume() を実行するように指示されています。

PostgreSQL 12でコマンド名が変更されていますので、実際にはpg_xlog_replay_resume()→pg_wal_replay_resume()となります。
下記コマンドを実行すると、recovery.signalファイルが削除されました。

select pg_wal_replay_resume()

pg_logの出力ログ

2021-08-01 14:53:25.989 JST [4188] LOG:  REDOが0/4000FB0で終了しました
2021-08-01 14:53:25.992 JST [4188] LOG:  最後に完了したトランザクションのログ時刻は2021-08-01 14:04:33.335593+09でした
2021-08-01 14:53:26.039 JST [4188] LOG:  新しいタイムラインIDを選択: 2
2021-08-01 14:53:26.124 JST [4188] LOG:  アーカイブリカバリが完了しました
2021-08-01 14:53:26.215 JST [11656] LOG:  データベースシステムの接続受け付け準備が整いました

(8) リカバリ後のデータの確認
ではデータベースに接続してデータの状態を確認します。間違って削除してしまった1件目のデータも復活していますし、間違って挿入してしまった9件目のデータも削除されていることが分かります。ここで行われた動作は、ベースバックアップの状態（1～3件目のデータが挿入された状態）を元に、アーカイブファイルとWALファイルに書かれた更新情報を使用して、4～8件目のデータ挿入処理を実行しています。間違って実行してしまった9件目のデータ挿入と1件目のデータ削除は実行されなかったため、データベースが正しい状態になっています。

select * from testtbl; -- テーブルに格納されたデータの確認

id	last_update
1	2021/08/01 13:20:12.117
2	2021/08/01 13:21:32.260
3	2021/08/01 13:22:33.743
4	2021/08/01 14:00:12.991
5	2021/08/01 14:01:16.385
6	2021/08/01 14:02:39.047
7	2021/08/01 14:03:28.537
8	2021/08/01 14:04:33.336

(9) 連続リカバリ
試しにもう少し前にリカバリできるか確認してみました。
PostgreSQLのサービスを停止して、recovery.signalにファイルを再作成して、6番目以降未登録の状態にしようとしました。

recovery.conf

restore_command = 'copy "D:\\PostgreSQL\\ARCHIVELOG\\%f" "%p"'
recovery_target_time = '2021-08-01 14:02:00'

PostgreSQLのサービスを開始しましたが、「REDOは必要ありません」というログ結果が出て戻りませんでした。直に連続でやるのは出来ないようです。

それではと、PostgreSQL停止後に「(4) 最新のWALファイルを格納」からやり直してみましたが、「有効なチェックポイントが見つかりませんでした」となり、6番目以降未登録の状態に戻すことが出来ませんでした。PostgreSQL 9.6の時はできたんですけどね。

pg_logの出力ログ

2021-08-01 16:21:55.211 JST [3008] LOG:  データベースシステムは 2021-08-01 16:18:28 JST にシャットダウンしました
2021-08-01 16:21:55.228 JST [3008] LOG:  2021-08-01 14:02:00+09までのポイントインタイムリカバリを開始します
2021-08-01 16:21:55.247 JST [3008] LOG:  ログファイル"00000003.history"をアーカイブからリストアしました
2021-08-01 16:21:55.291 JST [3008] LOG:  最初のチェックポイントレコードが不正です
2021-08-01 16:21:55.292 JST [3008] PANIC:  有効なチェックポイントが見つかりませんでした
2021-08-01 16:21:55.384 JST [5168] LOG:  起動プロセス (PID 3008)は例外C0000409で終了しました
2021-08-01 16:21:55.384 JST [5168] ヒント:  16進値の説明についてはC インクルードファイル"ntstatus.h"を参照してください。
2021-08-01 16:21:55.385 JST [5168] LOG:  起動プロセスの失敗のため起動を中断しています
2021-08-01 16:21:55.387 JST [5168] LOG:  データベースシステムはシャットダウンしました

連続はできないので、PostgreSQL停止後に「(3) ベースバックアップからのリストア」の手順まで戻して、6番目以降未登録の時間帯に指定し直せばできます。

select * from testtbl; -- テーブルに格納されたデータの確認

id	last_update
1	2021/08/01 13:20:12.117
2	2021/08/01 13:21:32.260
3	2021/08/01 13:22:33.743
4	2021/08/01 14:00:12.991
5	2021/08/01 14:01:16.385

最後に

今回、PostgreSQL 12で直近までのリカバリ方法を理解することができました。
しかし、データ自体は正常にリストアされているのに、'recovery.signal'ファイルが本来なら自動で削除されるはずが、何故か残ってしまう理由が不明です。その後のログのヒントによって、'pg_wal_replay_resume()'の実行により、'recovery.signal'ファイルが削除されましたけど。

今回の簡易的なデータではなく、実際に運用しているデータでリストアした際には、'recovery.signal'ファイルが自動で削除されていたので大丈夫だと思っています。