PITR是幂等的吗?
分析
在分析之前,需要先提前配置好归档,然后使用pg_basebackup做一个基础备份(全备)
[postgres@xiongcc ~]$ pg_basebackup -Fp -P -v -D pgdata_bak
pg_basebackup: initiating base backup, waiting for checkpoint to complete
WARNING: could not read symbolic link "pg_tblspc/40968": Invalid argument
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 1/64000028 on timeline 1
pg_basebackup: starting background WAL receiver
pg_basebackup: created temporary replication slot "pg_basebackup_3027"
62829/62829 kB (100%), 1/1 tablespace
pg_basebackup: write-ahead log end point: 1/64000100
pg_basebackup: waiting for background process to finish streaming ...
pg_basebackup: syncing data to disk ...
pg_basebackup: renaming backup_manifest.tmp to backup_manifest
pg_basebackup: base backup completed
下面以t1表为例
postgres=# begin;
BEGIN
postgres=*# select txid_current();
txid_current
--------------
157120
(1 row)postgres=*# insert into t1 values(1);
INSERT 0 1
postgres=*# insert into t1 values(2);
INSERT 0 1
postgres=*# commit ;
COMMIT
postgres=# insert into t1 values(3); ---157121事务
INSERT 0 1
postgres=# insert into t1 values(4); ---157122事务
INSERT 0 1
postgres=# select pg_switch_wal(); ---切换一下WAL日志
pg_switch_wal
---------------
1/74000240
(1 row)
然后按照常规流程,使用PITR恢复到157122这个事务,也就是4这条数据
[postgres@xiongcc ~]$ cat pgdata_bak/postgresql.conf | egrep 'restore_command|target_xid'
restore_command = 'cp /home/postgres/archive_dir/%f %p' # command to use to restore an archived logfile segment
recovery_target_xid = '157122' # the transaction ID up to which recovery will proceed
[postgres@xiongcc ~]$ touch pgdata_bak/recovery.signal
配置好之后,启动一下。日志里显式正常从归档中获取所需的WAL日志
2022-06-28 22:42:33.789 CST [7122] LOG: starting point-in-time recovery to XID 157122
2022-06-28 22:42:33.813 CST [7122] LOG: restored log file "000000010000000100000073" from archive
2022-06-28 22:42:33.843 CST [7122] LOG: redo starts at 1/73000028
2022-06-28 22:42:33.852 CST [7122] LOG: consistent recovery state reached at 1/73000100
2022-06-28 22:42:33.852 CST [7120] LOG: database system is ready to accept read-only connections
2022-06-28 22:42:33.872 CST [7122] LOG: restored log file "000000010000000100000074" from archive
2022-06-28 22:42:33.895 CST [7122] LOG: recovery stopping after commit of transaction 157122, time 2022-06-28 22:41:05.04387+08
恢复完成之后,可以看到数据确实恢复了出来。到这里没什么问题,基本的PITR流程。
postgres=# select * from t1;
id
----
1
2
3
4
(4 rows)
那么现在来模拟一下之前说的那个情况,现在我发现恢复到4这条数据不行,我想继续恢复到后面的时间点,那么我能基于当前这个已经恢复一次的实例继续恢复吗?源库继续模拟一点写入
postgres=# insert into t1 values(5);
INSERT 0 1
postgres=# insert into t1 values(6);
INSERT 0 1
postgres=# insert into t1 values(7);
INSERT 0 1
postgres=# select pg_switch_wal();
pg_switch_wal
---------------
1/75000200
(1 row)
然后现在我想恢复到7这条数据,那么依葫芦画瓢配置一下
[postgres@xiongcc ~]$ touch pgdata_bak/recovery.signal
[postgres@xiongcc ~]$ mv pgdata_bak/backup_label.old pgdata_bak/backup_label
[postgres@xiongcc ~]$ cat pgdata_bak/postgresql.conf | egrep 'restore_command|target_xid'
restore_command = 'cp /home/postgres/archive_dir/%f %p' # command to use to restore an archived logfile segment
recovery_target_xid = '157125' # the transaction ID up to which recovery will proceed
再次启动,可以发现数据依旧能恢复成功!
postgres=# select * from t1;
id
----
1
2
3
4
5
6
7
(7 rows)
不过在日志中可以看到,又从000000010000000100000073开始恢复了
2022-06-28 22:45:46.398 CST [7406] LOG: starting point-in-time recovery to XID 157125
2022-06-28 22:45:46.420 CST [7406] LOG: restored log file "000000010000000100000073" from archive
2022-06-28 22:45:46.456 CST [7406] LOG: redo starts at 1/73000028
2022-06-28 22:45:46.476 CST [7406] LOG: restored log file "000000010000000100000074" from archive
2022-06-28 22:45:46.502 CST [7406] LOG: consistent recovery state reached at 1/740001F0
2022-06-28 22:45:46.502 CST [7404] LOG: database system is ready to accept read-only connections
2022-06-28 22:45:46.529 CST [7406] LOG: restored log file "000000010000000100000075" from archive
2022-06-28 22:45:46.546 CST [7406] LOG: recovery stopping after commit of transaction 157125, time 2022-06-28 22:44:39.823453+08
2022-06-28 22:45:46.546 CST [7406] LOG: pausing at the end of recovery
2022-06-28 22:45:46.546 CST [7406] HINT: Execute pg_wal_replay_resume() to promote.
那么为什么是从000000010000000100000073开始的呢?不难明白,我前面的操作将backup_label.old改回了backup_label,PITR进行恢复的时候便会从START WAL LOCATION标识的位点开始恢复,也就是000000010000000100000073
[postgres@xiongcc pgdata_bak]$ cat backup_label.old
START WAL LOCATION: 1/73000028 (file 000000010000000100000073) ---从此处开始恢复
CHECKPOINT LOCATION: 1/73000060
BACKUP METHOD: streamed
BACKUP FROM: primary
START TIME: 2022-06-28 22:40:35 CST
LABEL: pg_basebackup base backup
START TIMELINE: 1
那么为什么可以基于已经恢复过一次的库继续恢复一次呢?
根据日志显式,最末尾提示pausing at the end of recovery,表示暂停了恢复,但是这个时候库还是只读的,需要手动执行pg_wal_replay_resume()函数才行。
关键的地方来了,划重点,在之前的文章 关于时间线的一点探究 有提到过,只有执行了此函数之后,库才会变成可读写的状态,同时时间线会加1,其实也就是recovery_target_action参数要做的事情,默认是pause,需要DBA手动确认已经恢复到一致的状态了(确认已经是想要的恢复点了),再调用pg_wal_replay_resume(),当然也可以一步到位直接将recovery_target_action设置为promote,数据库会自动帮你执行pg_wal_replay_resume()。
postgres=# create table t2(id int);
ERROR: cannot execute CREATE TABLE in a read-only transaction[postgres@xiongcc ~]$ pg_controldata -D pgdata_bak/ | grep location
Latest checkpoint location: 1/73000060 ---未发生改变,因为依旧是只读的状态,和backup_label中一致
Latest checkpoint's REDO location: 1/73000028 ---未发生改变,因为依旧是只读的状态,和backup_label中一致
Minimum recovery ending location: 1/750001B0
Backup start location: 0/0
Backup end location: 0/0
另外根据日志显式,每次都是从000000010000000100000073开始恢复,然后恢复到指定时间点,相信各位老铁也想到了,000000010000000100000073和000000010000000100000074回放了两次!假设WAL里面记录的是插入语句,那不就重复插入数据了吗,WAL的回放并不是幂等的!这不就有问题了吗?
其实不然,PostgreSQL的回放机制会比较数据页头部的LSN和每一条WAL记录的LSN,只有当WAL的LSN大于页面的LSN,才会进行回放,否则就直接跳过,而FPI遇到了就回放,因为是幂等的,所以可以多次回放。
Before trying to replay the XLOG record, PostgreSQL shall compare the XLOG record's LSN with the corresponding page's LSN, the reason why doing this will be described in Section 9.8. The rules of the replaying XLOG records are shown below. If the XLOG record's LSN is larger than the page's LSN, the data-portion of the XLOG record is to be inserted into the page and the page's LSN is updated to the XLOG record's LSN. On the other hand, if the XLOG record’s LSN is smaller, there is nothing to do other than to read next WAL data.
As can be seen from this example, if the replaying order of non-backup blocks is incorrect or non-backup blocks are replayed out more than once, the database cluster will no longer be consistent. In short, the redo (replay) operation of non-backup block is not idempotent. Therefore, to preserve the correct replaying order, non-backup block records should replay if and only if its LSN is greater than the corresponding page's pd_lsn.
On the other hand, as the redo operation of backup block is idempotent, backup blocks can be replayed any number of times regardless of its LSN.
那让我们比较一下,页面的LSN是1/75000180,而我们担忧会重复回放的000000010000000100000074最大的LSN也只有1/74000228,比页面小,所以会被跳过
postgres=# select lsn from page_header(get_raw_page('t1', 0));
lsn
------------
1/75000180
(1 row)[postgres@xiongcc ~]$ pg_waldump archive_dir/000000010000000100000074 | tail -n 3
rmgr: Transaction len (rec/tot): 46/ 46, tx: 157122, lsn: 1/740001C0, prev 1/74000180, desc: COMMIT 2022-06-28 22:41:05.043870 CST
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 1/740001F0, prev 1/740001C0, desc: RUNNING_XACTS nextXid 157123 latestCompletedXid 157122 oldestRunningXid 157123
rmgr: XLOG len (rec/tot): 24/ 24, tx: 0, lsn: 1/74000228, prev 1/740001F0, desc: SWITCH
而000000010000000100000075则是1/75000060,大于页面的LSN,因此会被回放,也就是插入5这条数据。
[postgres@xiongcc ~]$ pg_waldump archive_dir/000000010000000100000075 | head -n 3
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 1/75000028, prev 1/74000228, desc: RUNNING_XACTS nextXid 157123 latestCompletedXid 157122 oldestRunningXid 157123
rmgr: Heap len (rec/tot): 59/ 59, tx: 157123, lsn: 1/75000060, prev 1/75000028, desc: INSERT off 5 flags 0x08, blkref #0: rel 1663/13892/41735 blk 0
rmgr: Transaction len (rec/tot): 46/ 46, tx: 157123, lsn: 1/750000A0, prev 1/75000060, desc: COMMIT 2022-06-28 22:44:37.242096 CST
那么不难想到,执行了pg_wal_replay_resume()之后时间线便会加1,再恢复就不行了
[postgres@xiongcc ~]$ ll pgdata_bak/pg_wal/
total 49216
-rw------- 1 postgres postgres 16777216 Jun 28 22:45 000000010000000100000073
-rw------- 1 postgres postgres 16777216 Jun 28 22:45 000000010000000100000074
-rw------- 1 postgres postgres 16777216 Jun 28 22:45 000000010000000100000075
drwx------ 2 postgres postgres 4096 Jun 28 22:45 archive_status
[postgres@xiongcc ~]$ psql -p 5433 -c "select pg_wal_replay_resume()"
pg_wal_replay_resume
---------------------- (1 row)
[postgres@xiongcc ~]$ ll pgdata_bak/pg_wal/
total 65624
-rw------- 1 postgres postgres 16777216 Jun 28 22:45 000000010000000100000075
-rw------- 1 postgres postgres 16777216 Jun 28 23:07 000000020000000100000075
-rw------- 1 postgres postgres 16777216 Jun 28 22:45 000000020000000100000076
-rw------- 1 postgres postgres 16777216 Jun 28 22:45 000000020000000100000077
-rw------- 1 postgres postgres 38 Jun 28 23:07 00000002.history
drwx------ 2 postgres postgres 4096 Jun 28 23:07 archive_status
老样子,源库插入部分数据
postgres=# insert into t1 values(8); ---xid为157126
INSERT 0 1
postgres=# insert into t1 values(9); ---xid为157127
INSERT 0 1
postgres=# insert into t1 values(10); ---xid为157128
INSERT 0 1
这次想恢复到10这条数据就再也不行了,时间线已经出现了分叉。requested timeline 1 does not contain minimum recovery point 1/75007768 on timeline 2
[postgres@xiongcc ~]$ mv pgdata_bak/backup_label.old pgdata_bak/backup_label
[postgres@xiongcc ~]$ touch pgdata_bak/recovery.signal
[postgres@xiongcc ~]$ cat pgdata_bak/postgresql.conf | egrep 'restore_command|target_xid|target_timeline'
restore_command = 'cp /home/postgres/archive_dir/%f %p' # command to use to restore an archived logfile segment
recovery_target_xid = '157128' # the transaction ID up to which recovery will proceed
recovery_target_timeline = '1' # 'current', 'latest', or timeline ID[postgres@xiongcc log]$ tail -f postgresql-2022-06-28.log
2022-06-28 23:13:03.062 CST [9391] LOG: listening on IPv4 address "127.0.0.1", port 5433
2022-06-28 23:13:03.066 CST [9391] LOG: listening on Unix socket "/tmp/.s.PGSQL.5433"
2022-06-28 23:13:03.072 CST [9393] LOG: database system was interrupted while in recovery at log time 2022-06-28 23:09:58 CST
2022-06-28 23:13:03.072 CST [9393] HINT: If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2022-06-28 23:13:03.127 CST [9393] LOG: starting point-in-time recovery to XID 157128
2022-06-28 23:13:03.147 CST [9393] LOG: restored log file "000000010000000100000073" from archive
2022-06-28 23:13:03.180 CST [9393] FATAL: requested timeline 1 does not contain minimum recovery point 1/75007768 on timeline 2
2022-06-28 23:13:03.180 CST [9391] LOG: startup process (PID 9393) exited with exit code 1
2022-06-28 23:13:03.180 CST [9391] LOG: aborting startup due to startup process failure
2022-06-28 23:13:03.182 CST [9391] LOG: database system is shut down
[postgres@xiongcc ~]$ pg_controldata -D pgdata_bak/ | grep location
Latest checkpoint location: 1/75007768
Latest checkpoint's REDO location: 1/75007768
Minimum recovery ending location: 1/75007768
Backup start location: 0/0
Backup end location: 0/0
向后恢复
另外前滚(forward restore)可以,但不能回滚(backward restore),比如说当前已经恢复到了157134这个事务
[postgres@xiongcc ~]$ cat pgdata_bak/postgresql.conf | egrep 'restore_command|target_xid|target_timeline'
restore_command = 'cp /home/postgres/archive_dir/%f %p' # command to use to restore an archived logfile segment
recovery_target_xid = '157134' # the transaction ID up to which recovery will proceed
#recovery_target_timeline = 'latest' # 'current', 'latest', or timeline ID
并且正常恢复成功,想再次恢复到157132的话是不行的,日志中也提示的很清楚,requested recovery stop point is before consistent recovery point
2022-06-29 09:16:29.430 CST [19415] LOG: starting point-in-time recovery to XID 157132
2022-06-29 09:16:29.457 CST [19415] LOG: restored log file "000000010000000100000077" from archive
2022-06-29 09:16:29.485 CST [19415] LOG: redo starts at 1/77000028
2022-06-29 09:16:29.505 CST [19415] LOG: restored log file "000000010000000100000078" from archive
2022-06-29 09:16:29.530 CST [19415] LOG: recovery stopping before commit of transaction 157132, time 2000-01-01 08:00:00+08
2022-06-29 09:16:29.530 CST [19415] FATAL: requested recovery stop point is before consistent recovery point
2022-06-29 09:16:29.530 CST [19413] LOG: startup process (PID 19415) exited with exit code 1
2022-06-29 09:16:29.530 CST [19413] LOG: terminating any other active server processes
2022-06-29 09:16:29.530 CST [19413] LOG: shutting down due to startup process failure
2022-06-29 09:16:29.532 CST [19413] LOG: database system is shut down
代码逻辑很简单,reachedConsistency变量用于确认是否恢复到了的最小一致位点
if (reachedRecoveryTarget)
{
if (!reachedConsistency)
ereport(FATAL,
(errmsg("requested recovery stop point is before consistent recovery point"))); /*
* Have we reached a consistent database state? In crash recovery, we have
* to replay all the WAL, so reachedConsistency is never set. During archive
* recovery, the database is consistent once is reached.
*/
bool reachedConsistency = false;
当需要归档恢复时,数据库必须确保达到minRecoveryPoint这个位点。除此之外,PostgreSQL还有一些其他需要最小恢复到的位点,这些在控制文件中有所记录
/*
* Contents of pg_control.
*/typedef struct ControlFileData
{
/*
* Unique system identifier --- to ensure we match up xlog files with the
* installation that produced them.
*/
uint64 system_identifier;
...
/*
* These two values determine the minimum point we must recover up to
* before starting up:
*
* minRecoveryPoint is updated to the latest replayed LSN whenever we
* flush a data change during archive recovery. That guards against
* starting archive recovery, aborting it, and restarting with an earlier
* stop location. If we've already flushed data changes from WAL record X
* to disk, we mustn't start up until we reach X again. Zero when not
* doing archive recovery.
*
* backupStartPoint is the redo pointer of the backup start checkpoint, if
* we are recovering from an online backup and haven't reached the end of
* backup yet. It is reset to zero when the end of backup is reached, and
* we mustn't start up before that. A boolean would suffice otherwise, but
* we use the redo pointer as a cross-check when we see an end-of-backup
* record, to make sure the end-of-backup record corresponds the base
* backup we're recovering from.
*
* backupEndPoint is the backup end location, if we are recovering from an
* online backup which was taken from the standby and haven't reached the
* end of backup yet. It is initialized to the minimum recovery point in
* pg_control which was backed up last. It is reset to zero when the end
* of backup is reached, and we mustn't start up before that.
*
* If backupEndRequired is true, we know for sure that we're restoring
* from a backup, and must see a backup-end record before we can safely
* start up. If it's false, but backupStartPoint is set, a backup_label
* file was found at startup but it may have been a leftover from a stray
* pg_start_backup() call, not accompanied by pg_stop_backup().
*/
XLogRecPtr minRecoveryPoint;
TimeLineID minRecoveryPointTLI;
XLogRecPtr backupStartPoint;
XLogRecPtr backupEndPoint;
bool backupEndRequired;
minRecoveryPoint:数据库在归档恢复过程中,minRecoveryPoint会被更新为最新已经被刷到磁盘的LSN,每次数据库启动时必须已经回放了该位置的XLOG日志记录,对应的是控制文件里的Minimum recovery ending location。
printf(_("Fake LSN counter for unlogged rels: %X/%X\n"),
LSN_FORMAT_ARGS(ControlFile->unloggedLSN));
printf(_("Minimum recovery ending location: %X/%X\n"),
LSN_FORMAT_ARGS(ControlFile->minRecoveryPoint));
printf(_("Min recovery ending loc's timeline: %u\n"),
ControlFile->minRecoveryPointTLI);backupStartPoint:数据库在线备份开始时,会调用pg_start_backup()执行一次checkpoint,并生成backup_label文件。当使用在线备份集进行恢复时,backupStartPoint就是上述checkpoint记录对应的LSN,当达到了该LSN,该值置为0,在置为0之前,数据库不能启动。该值被记录在backup_label文件中如下,直到在线备份结束,pg_stop_backup将该文件删除。这样就保证了在备份过程中,数据库崩溃了,可以默认从备份开始时的日志检查点开始恢复。
backupEndPoint:当数据库从一个备库做的在线备份集进行恢复时,backupEndPoint表示备份结束的LSN,当达到该LSN,该值置为0,在置为0之前,数据库不能启动。
因此,当我们前面往前恢复(forward)之后,minRecoveryPoint已经被更新为最新回放的LSN了,再往前恢复(backward),LSN比minRecoveryPoint小,当然就无法恢复了。那么回到这张图,我能恢复到11:20吗?答案不言而喻。
举个栗子,假设当前已经恢复到了157230事务,数据是1、2、3、4
postgres=# select xmin,id from t1;
xmin | id
--------+----
157227 | 1
157228 | 2
157229 | 3
157230 | 4
(4 rows)
目前的最小还原点是2/401ACD0,假如现在想往前恢复至157228的话,也就是2这条数据
[postgres@xiongcc ~]$ pg_controldata -D pgdata_bak/ | grep recovery
Database cluster state: in archive recovery
Minimum recovery ending location: 2/401ACD0
Min recovery ending loc's timeline: 1
而2这一条数据的LSN是2/0401AC60,比2/401ACD0小,所以会报错。
rmgr: Heap len (rec/tot): 59/ 59, tx: 157228, lsn: 2/0401AC60, prev 2/0401AC28, desc: INSERT off 2 flags 0x08, blkref #0: rel 1663/13892/41749 blk 0
rmgr: Transaction len (rec/tot): 46/ 46, tx: 157228, lsn: 2/0401ACA0, prev 2/0401AC60, desc: COMMIT 2022-06-29 17:49:37.140245 CST
另外假如是指定了recovery_target_time的话,还要注意时区可能带来的问题,也会提示requested recovery stop point is before consistent recovery point
In my case, there is timezone mismatch between barman and postgres db. I have to convert the time to GMT then the restore and db start is a success.
如果在recovery.conf指定recovery_targetTimeLine为latest,则可以基于当前TimeLineID为起点寻找最新时间线:
寻找当前TimeLineID的时间线历史文件"XXX.history",如果存在则继续寻找,否则错误退出 TimeLineID是线性增长的,将当前TimeLineID自增1寻找是否存在时间线历史文件,直到不存在对应的时间线历史文件为止,即可找到最新的时间线。
小结
现在不妨回过头来思考一下,为什么recovery_target_action是pause呢?假如我们设为了promote的话,PostgreSQL便会自动帮你执行pg_wal_replay_resume(),时间线加1,但是一旦后之后居发现恢复错了,不是想要的时间点,也无法再继续基于当前这个实例继续恢复了,假设还只有一份全备的话,那就只能干瞪眼了。
而是pause的话,PostgreSQL会假设你还没有恢复完成,或者说是更严谨,需要我们自行去校验是否恢复到了我们想要的时间点,就算不是也可以再恢复一次,因为回放机制的原因,多次回放是可以的,一旦确认无误之后,便可以调用pg_wal_replay_resume(),让实例变成可读写的状态,至此PITR也就正式完成了。
还有一点值得注意的是,PITR和正常的crash recovery,有所不同
正常恢复模式,从pg_control文件获取redo点,然后从pg_wal目录下读取WAL日志进行恢复 PITR,通过read_backup_label函数,从backup_label文件中获取redo点,然后从archive_command中指向的归档目录,读取WAL日志进行恢复
因此,假如存在了backup_label,数据库crash了,PostgreSQL会优先从backup_label里面取出redo location开始回放,危害不言而喻,可以参照我之前的文章《你真的搞懂备份了吗》,所以在15里面,移除了排它备份(下图引自彭冲的PostgreSQL15新特性预览),并且假如各位模拟上方的复现操作的话,假如没有backup_label,PostgreSQL会从控制文件里面取redo location开始PITR。因为PostgreSQL的crash recovery机制如下:
检测是否存在backup_label文件,如果存在,则从备份标记定义的检查点(CHECKPOINT LOCATION)读取检查点的记录到record中 若record不空,则从record中的检查点记录为恢复起始位置,参数InRecovery参数设置为true 若record为空,则系统报错 如果不存在backup_label文件,读取pg_control文件中的最近一次检查点,并把它的记录读到record中,因此上方操作过程中若没有将backup_label.old改回成backup_label,也是可以恢复的,因为会从pg_control里面获取redo location,而这两者是一致的(还是只读状态,未promote) 若record不空,则从record中的检查点记录为恢复起始位置 若record为空,则读取最近一次检查点的前面一次检查点(prevCheckPoint),并把它的记录读到record中(11以前的版本) 如果新record不为空,把参数InRecovery参数设置为true,否则系统报错
参考
https://dba.stackexchange.com/questions/204210/requested-recovery-stop-point-is-before-consistent-recovery-point
PostgreSQL 如何从崩溃状态恢复(上)