ReaderMX.
PostgreSQL学徒

一则 PITR 的有趣案例

Pxiongcc约 13 分钟

1前言

今天晚上的时候，一位公众号粉丝找到我提了这样一个问题："pg_receivewal 发回来的wal有办法做增备么。我的操作步骤是这样的"

  1. (node-2) 复制wal日志 pg_receivewal -h node-1 -D xxx_rec
  2. (node-2) pg_basebackup -h node-1 -D xxx_full
  3. (node-1) 生成增量数据 pgbench -i -s 10
  4. (node-2)修改配置文件
  5. restore_command = 'cp xxx_rec/%f %p'
  6. recovery_target = 'immediate'
  7. (node-2)pg_ctl start -o '-c config路径'

库启动之后读取到中间 xxxxAD 就不继续读取了。我理解这个开启就是把已有的 backlabel 里面的读完就停止？

Image

以上便是基本的现象以及这位粉丝的疑惑，让我们简单分析一下这个案例。

2分析

pg_receivewal 这个工具是 9.2 引入的，以 replication protocal 实时获取 WAL，有点像实时归档的意思。

PostgreSQL 9.2还支持虚拟备库，即就是只有WAL，没有数据文件的备库。pg_receivexlog，它以类似流式复制（streaming replication）的方式，获取主库的 WAL 文件。

先准备一个基础环境，同时使用 pg_basebackup 制作一个基础备份，这些就不做演示了。然后模拟一点业务，生成一些 WAL，同时新开一个窗口使用 pg_receivewal 实时流式接受 WAL：pg_receivewal -h localhost -p 5432 -D wal_archive

不一会儿，wal_archive 目录下就有 WAL 日志了

[postgres@xiongcc ~]$ ll wal_archive/
total 245760
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000077
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000078
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000079
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 00000001000000000000007A
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 00000001000000000000007B
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 00000001000000000000007C
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 00000001000000000000007D
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 00000001000000000000007E
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 00000001000000000000007F
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000080
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000081
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000082
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000083
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000084
-rw------- 1 postgres postgres 16777216 Feb  7 20:53 000000010000000000000085.partial

最后那个以 partial 结尾的文件表示当前正在写入的 WAL

postgres=# select pg_walfile_name(pg_current_wal_lsn());
     pg_walfile_name      
--------------------------
 000000010000000000000085
(1 row)

那么既然有了变更日志（WAL），又有了基础备份（pg_basebackup），按理说做 PITR 应该没问题，试试看

postgres=# begin;
BEGIN
postgres=*# select txid_current();
 txid_current 
--------------
       246387
(1 row)
postgres=*# insert into t1 values(9999);
INSERT 0 1
postgres=*# commit ;
COMMIT
postgres=# select pg_switch_wal();
 pg_switch_wal 
---------------
 0/85000560
(1 row)
postgres=# select pg_walfile_name(pg_current_wal_insert_lsn());
     pg_walfile_name      
--------------------------
 000000010000000000000086
(1 row)

为了确保 WAL 顺利接受，做了个切换，其实也可以不用做。然后老样子，配置一下 PITR

[postgres@xiongcc ~]$ cat 14data_bak/postgresql.conf | grep recovery_target
#recovery_target = ''           # 'immediate' to end recovery as soon as a
#recovery_target_name = ''      # the named restore point to which recovery will proceed
#recovery_target_time = ''      # the time stamp up to which recovery will proceed
recovery_target_xid = '246387'  # the transaction ID up to which recovery will proceed
#recovery_target_lsn = ''       # the WAL LSN up to which recovery will proceed
#recovery_target_inclusive = on # Specifies whether to stop:
#recovery_target_timeline = 'latest'    # 'current', 'latest', or timeline ID
#recovery_target_action = 'pause'       # 'pause', 'promote', 'shutdown'

此处我仅配置了 recovery_target_xid，恢复到插入 9999 这一行的事务 ID，其中 recovery_target_inclusive 表示是否恢复到这个事务之前还是之后，on 就表示恢复完插入这个事务，因此 9999 这条数据是可见的。

日志里正常显式从归档中或许日志的操作

 2023-02-07 21:15:04.517 CST [20567] LOG:  starting point-in-time recovery to XID 246387
 cp: cannot stat ‘/home/postgres/wal_archive/000000010000000000000076’: No such file or directory
 2023-02-07 21:15:04.527 CST [20567] LOG:  redo starts at 0/76000028
 2023-02-07 21:15:04.528 CST [20567] LOG:  consistent recovery state reached at 0/76000100
 2023-02-07 21:15:04.529 CST [20565] LOG:  database system is ready to accept read-only connections
 2023-02-07 21:15:04.554 CST [20567] LOG:  restored log file "000000010000000000000077" from archive
 2023-02-07 21:15:04.617 CST [20567] LOG:  restored log file "000000010000000000000078" from archive
 2023-02-07 21:15:04.668 CST [20567] LOG:  restored log file "000000010000000000000079" from archive
 2023-02-07 21:15:04.719 CST [20567] LOG:  restored log file "00000001000000000000007A" from archive
 2023-02-07 21:15:04.764 CST [20567] LOG:  restored log file "00000001000000000000007B" from archive
 2023-02-07 21:15:04.814 CST [20567] LOG:  restored log file "00000001000000000000007C" from archive
 2023-02-07 21:15:04.873 CST [20567] LOG:  restored log file "00000001000000000000007D" from archive
 2023-02-07 21:15:04.919 CST [20567] LOG:  restored log file "00000001000000000000007E" from archive
 2023-02-07 21:15:04.973 CST [20567] LOG:  restored log file "00000001000000000000007F" from archive
 2023-02-07 21:15:05.013 CST [20567] LOG:  restored log file "000000010000000000000080" from archive
 2023-02-07 21:15:05.067 CST [20567] LOG:  restored log file "000000010000000000000081" from archive
 2023-02-07 21:15:05.113 CST [20567] LOG:  restored log file "000000010000000000000082" from archive
 2023-02-07 21:15:05.178 CST [20567] LOG:  restored log file "000000010000000000000083" from archive
 2023-02-07 21:15:05.231 CST [20567] LOG:  restored log file "000000010000000000000084" from archive
 2023-02-07 21:15:05.299 CST [20567] LOG:  restored log file "000000010000000000000085" from archive
 2023-02-07 21:15:05.834 CST [20567] LOG:  recovery stopping after commit of transaction 246387, time 2023-02-07 21:08:44.330518+08
 2023-02-07 21:15:05.834 CST [20567] LOG:  pausing at the end of recovery
 2023-02-07 21:15:05.834 CST [20567] HINT:  Execute pg_wal_replay_resume() to promote.

查询一下 9999 这条数据，没问题，数据正常恢复出来了。

postgres=# select * from t1 where id = 9999;
  id  
------
 9999
(1 row)

那么回到这位童鞋的例子，说明采用 pg_receivewal 和基础备份做时间点恢复是没有问题的，那么问题出在了哪里？

首先这个例子中是恢复到中间的某一个日志，那让我们继续再生成一些

[postgres@xiongcc ~]$ ll wal_archive/
total 540672
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000077
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000078
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000079
...
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000080
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000081
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000082
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000083
-rw------- 1 postgres postgres 16777216 Feb  7 20:50 000000010000000000000084
-rw------- 1 postgres postgres 16777216 Feb  7 21:08 000000010000000000000085
-rw------- 1 postgres postgres 16777216 Feb  7 21:22 000000010000000000000086   ---👈🏻上一次在这
-rw------- 1 postgres postgres 16777216 Feb  7 21:22 000000010000000000000087
-rw------- 1 postgres postgres 16777216 Feb  7 21:22 000000010000000000000088
...
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 00000001000000000000008E
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 00000001000000000000008F
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000090
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000091
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000092
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000093
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000094
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000095
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000096
-rw------- 1 postgres postgres 16777216 Feb  7 21:23 000000010000000000000097.partial

这一次按照这位童鞋操作的例子，配置 recovery_target = 'immediate'，回顾一下我之前写过的关于 PITR 的文章

现在不妨回过头来思考一下，为什么 recovery_target_action 是 pause 呢？假如我们设为了 promote 的话，PostgreSQL 便会自动帮你执行pg_wal_replay_resume()，时间线加1，但是一旦后之后居发现恢复错了，不是想要的时间点，也无法再继续基于当前这个实例继续恢复了，假设还只有一份全备的话，那就只能干瞪眼了。而是 pause 的话，PostgreSQL 会假设你还没有恢复完成，或者说是更严谨，需要我们自行去校验是否恢复到了我们想要的时间点，就算不是也可以再恢复一次，因为回放机制的原因，多次回放是可以的，一旦确认无误之后，便可以调用 pg_wal_replay_resume()，让实例变成可读写的状态，至此 PITR 也就正式完成了。

因为我还没有手动 promote，因此还是可以继续恢复的，这次我们改成 recovery_target = 'immediate'，再启动一次，这一次的日志如下

2023-02-07 21:15:05.834 CST [20567] LOG:  pausing at the end of recovery
2023-02-07 21:15:05.834 CST [20567] HINT:  Execute pg_wal_replay_resume() to promote.   ---👈🏻上一次操作的日志在这
2023-02-07 21:30:21.237 CST [20565] LOG:  received fast shutdown request
2023-02-07 21:30:21.240 CST [20565] LOG:  aborting any active transactions
2023-02-07 21:30:21.789 CST [20570] LOG:  shutting down
2023-02-07 21:30:21.793 CST [20565] LOG:  database system is shut down
2023-02-07 21:30:21.860 CST [20644] LOG:  starting PostgreSQL 14.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
2023-02-07 21:30:21.860 CST [20644] LOG:  listening on IPv6 address "::1", port 5433
2023-02-07 21:30:21.861 CST [20644] LOG:  listening on IPv4 address "127.0.0.1", port 5433
2023-02-07 21:30:21.865 CST [20644] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5433"
2023-02-07 21:30:21.871 CST [20646] LOG:  database system was shut down in recovery at 2023-02-07 21:30:21 CST
cp: cannot stat ‘/home/postgres/wal_archive/00000002.history’: No such file or directory
2023-02-07 21:30:21.874 CST [20646] LOG:  starting point-in-time recovery to earliest consistent point
2023-02-07 21:30:21.890 CST [20646] LOG:  restored log file "000000010000000000000085" from archive
2023-02-07 21:30:21.929 CST [20646] LOG:  redo starts at 0/85000060
2023-02-07 21:30:21.929 CST [20646] LOG:  consistent recovery state reached at 0/85000548
2023-02-07 21:30:21.929 CST [20646] LOG:  recovery stopping after reaching consistency
2023-02-07 21:30:21.929 CST [20646] LOG:  pausing at the end of recovery
2023-02-07 21:30:21.929 CST [20646] HINT:  Execute pg_wal_replay_resume() to promote.
2023-02-07 21:30:21.930 CST [20644] LOG:  database system is ready to accept read-only connections

可以看到恢复到了 000000010000000000000085 就停了，没有继续往后应用 WAL，所以按照这位童鞋的想法，应该是想要恢复到最新的日志，即 000000010000000000000097.partial。那么就是 recovery_target 这个参数的影响了，看看这个参数吧

This parameter specifies that recovery should end as soon as a consistent state is reached, i.e., as early as possible. When restoring from an online backup, this means the point where taking the backup ended.

此参数指定恢复应在达到一致状态后立即结束，即尽可能早地结束。从在线备份恢复时，这意味着备份结束的点。

达到一致性状态后就立马结束，因为上一次一致性恢复到了 000000010000000000000085，所以就如这个参数所说，停止，没有继续往后恢复了。简而言之，就是当数据库只要发现了一个一致性的状态，就立马停止结束回放。比如前面这个例子，上一次一致性是到了 000000010000000000000085，所以这次就恢复到了 000000010000000000000085。

2023-02-07 21:30:21.929 CST [20646] LOG:  redo starts at 0/85000060                                                                                                                                                                                         
2023-02-07 21:30:21.929 CST [20646] LOG:  consistent recovery state reached at 0/85000548   ---此时已经达到一致性状态了                                                                                                                                                                
2023-02-07 21:30:21.929 CST [20646] LOG:  recovery stopping after reaching consistency  

而假如不像我这么操作，做完基础备份之后，然后配置 recovery_target = 'immediate' 进行恢复的话，便会恢复到备份结束的点，为什么？因为备份结束数据库认为达到一致性状态了。如这句话所说，When restoring from an online backup, this means the point where taking the backup ended. 备份结束的点

日志里也是如此 👇🏻

[postgres@xiongcc ~]$ ll wal_archive/
total 229376
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 000000010000000000000099
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009A
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009B
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009C
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009D
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009E
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009F
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A0
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A1
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A2
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A3
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A4
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A5
-rw------- 1 postgres postgres 16777216 Feb  7 21:45 0000000100000000000000A6.partial   ---👈🏻上一次正在写的日志在这里
[postgres@xiongcc ~]$ ll wal_archive/
total 262144
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 000000010000000000000099
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009A
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009B
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009C
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009D
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009E
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 00000001000000000000009F
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A0
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A1
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A2
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A3
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A4
-rw------- 1 postgres postgres 16777216 Feb  7 21:40 0000000100000000000000A5
-rw------- 1 postgres postgres 16777216 Feb  7 21:47 0000000100000000000000A6
-rw------- 1 postgres postgres 16777216 Feb  7 21:47 0000000100000000000000A7     ---👈🏻做pg_basebackup全备的时候会切换日志
-rw------- 1 postgres postgres 16777216 Feb  7 21:47 0000000100000000000000A8.partial

然后启动，你便会发现恢复到了备份结束的点，0000000100000000000000A7

[postgres@xiongcc ~]$ tail -f 14data_bak/log/postgresql-07.log 
2023-02-07 21:50:13.739 CST [20788] LOG:  database system was interrupted; last known up at 2023-02-07 21:47:38 CST
cp: cannot stat ‘/home/postgres/wal_archive/00000002.history’: No such file or directory
2023-02-07 21:50:13.796 CST [20788] LOG:  starting point-in-time recovery to earliest consistent point
2023-02-07 21:50:13.812 CST [20788] LOG:  restored log file "0000000100000000000000A7" from archive
2023-02-07 21:50:13.839 CST [20788] LOG:  redo starts at 0/A7000028
2023-02-07 21:50:13.841 CST [20788] LOG:  consistent recovery state reached at 0/A7000100
2023-02-07 21:50:13.841 CST [20788] LOG:  recovery stopping after reaching consistency
2023-02-07 21:50:13.841 CST [20788] LOG:  pausing at the end of recovery
2023-02-07 21:50:13.841 CST [20788] HINT:  Execute pg_wal_replay_resume() to promote.
2023-02-07 21:50:13.842 CST [20786] LOG:  database system is ready to accept read-only connections

3小结

其实这位童鞋的问题还挺"刁钻"，因为按照我们一般的习惯，是习惯于配置那些 xid/time 之类的，不会配置这个 recovery_target。总之还是挺不错，我也温习了一下 pg_receivewal 以及 PITR 的基础原理，还搞懂了这个生疏的参数。

另外，明天晚上 8 点，和各位唠唠嗑，不见不散

Image

KEEP THE THREAD GOING

更多来源文章