关于时间线的一点探究
前言
前天分享了一篇关于流复制的文章——关于PostgreSQL流复制的方方面面，具体细节可以参照之前的文字，其中有一处写到了关于“流复制时间线Timeline”的，原文如下：
举个将数据库恢复到以前时间点的例子。假设在一个数据库的运行过程中，DBA在周三12:00AM删掉了一个关键的表，但是直到周五中午才发现这个问题。这个时候DBA拿出最初的数据库备份，加上存在归档目录的日志文件，将数据库恢复到周三11:00AM的时间点，这样就能正常启动和运行。但是，DBA后来意识到这样恢复是不对的，想恢复到周四8:00AM的数据，这时会发现无法做到：因为在数据库不断运行中，会产生与旧的WAL文件重名的文件，这些文件进入归档目录时，会覆盖原来的旧日志，导致恢复数据库需要的WAL文件丢失。为了避免这种情况，需要区分原始数据库历史生成的WAL文件和完成恢复之后继续运行产生的（重名的）新WAL文件。
后面经过“神医”和占元的指点迷津，发现确实不是很严谨，也怪我太懒了，直接引用了阿里内核组的文章《PostgreSQL 时间线解析》，严谨一点的说法应该是：恢复好之后，并且不再处于recovery模式，此时已准备接收新的连接了（非只读连接），这个时候时间线才会+1。
实践
先使用pg_basebackup做一个基础备份
[postgres@xiongcc ~]$ pg_basebackup -Fp -Xs -D testdata/ -P -v
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/33000028 on timeline 1
pg_basebackup: starting background WAL receiver
pg_basebackup: created temporary replication slot "pg_basebackup_30658"
190711/190711 kB (100%), 1/1 tablespace
pg_basebackup: write-ahead log end point: 0/33000100
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
先打开WAL的归档，同时记录一下操作的事务ID，后面PITR恢复时需要指定对应的事务ID
[postgres@xiongcc ~]$ psql
psql (13.2)
Type "help" for help.
postgres=# begin;
BEGIN
postgres=*# select txid_current();
txid_current
--------------
10989
(1 row)
postgres=*# insert into t values(2,2);
INSERT 0 1
postgres=*# commit ;
COMMIT
postgres=# select pg_switch_wal();
pg_switch_wal
---------------
0/380000E8
(1 row)
对应的归档目录里
[postgres@xiongcc ~]$ ll archive/
total 49156
-rw------- 1 postgres postgres 16777216 May 19 12:33 000000010000000000000036
-rw------- 1 postgres postgres 16777216 May 19 12:33 000000010000000000000037
-rw------- 1 postgres postgres 340 May 19 12:33 000000010000000000000037.00000028.backup
-rw------- 1 postgres postgres 16777216 May 19 12:34 000000010000000000000038
然后，基于时间点做恢复，恢复到事务ID为10989的时刻
[postgres@xiongcc ~]$ cat testdata/postgresql.conf | grep -i 'restore_command'
restore_command = 'cp /home/postgres/archive/%f %p'# command to use to restore an archived logfile segment
[postgres@xiongcc ~]$ cat testdata/postgresql.conf | grep -i 'recovery_target_xid'
recovery_target_xid = '10989'# the transaction ID up to which recovery will proceed
因为我的版本是13.2，所以需要touch一个recovery.signal文件
[postgres@xiongcc ~]$ touch testdata/recovery.signal
[postgres@xiongcc ~]$ pg_ctl -D testdata/ start
waiting for server to start....2021-05-19 12:35:31.338 CST [30743] LOG: redirecting log output to logging collector process
2021-05-19 12:35:31.338 CST [30743] HINT: Future log output will appear in directory "log".
... done
server started
[postgres@xiongcc ~]$ psql -p 5444
psql (13.2)
Type "help" for help.
postgres=# select * from t;
x | y
---+---
2 | 2
(1 row)
postgres=# show transaction_read_only ;
transaction_read_only
-----------------------
on
(1 row)
对应的日志里，有很清楚的描述，见最后一行，2021-05-19 12:35:34.717 CST,,,30745,,60a49593.7819,8,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"pausing at the end of recovery",,"Execute pg_wal_replay_resume() to promote.",,,,,,,"","startup"
2021-05-19 12:35:31.339 CST,,,30743,,60a49593.7817,1,,2021-05-19 12:35:31 CST,,0,LOG,00000,"ending log output to stderr",,"Future log output will go to log destination ""csvlog"".",,,,,,,"","postmaster"
2021-05-19 12:35:31.339 CST,,,30743,,60a49593.7817,2,,2021-05-19 12:35:31 CST,,0,LOG,00000,"starting PostgreSQL 13.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit",,,,,,,,,"","postmaster"
2021-05-19 12:35:31.339 CST,,,30743,,60a49593.7817,3,,2021-05-19 12:35:31 CST,,0,LOG,00000,"listening on IPv4 address ""127.0.0.1"", port 5444",,,,,,,,,"","postmaster"
2021-05-19 12:35:31.339 CST,,,30743,,60a49593.7817,4,,2021-05-19 12:35:31 CST,,0,LOG,XX000,"could not bind IPv6 address ""::1"": Cannot assign requested address",,"Is another postmaster already running on port 5444? If not, wait a few seconds and retry.",,,,,,,"","postmaster"
2021-05-19 12:35:31.371 CST,,,30743,,60a49593.7817,5,,2021-05-19 12:35:31 CST,,0,LOG,00000,"listening on Unix socket ""/tmp/.s.PGSQL.5444""",,,,,,,,,"","postmaster"
2021-05-19 12:35:31.397 CST,,,30745,,60a49593.7819,1,,2021-05-19 12:35:31 CST,,0,LOG,00000,"database system was interrupted; last known up at 2021-05-19 12:33:52 CST",,,,,,,,,"","startup"
2021-05-19 12:35:34.333 CST,,,30745,,60a49593.7819,2,,2021-05-19 12:35:31 CST,,0,LOG,00000,"starting point-in-time recovery to XID 10989",,,,,,,,,"","startup"
2021-05-19 12:35:34.347 CST,,,30745,,60a49593.7819,3,,2021-05-19 12:35:31 CST,,0,LOG,00000,"restored log file ""000000010000000000000037"" from archive",,,,,,,,,"","startup"
2021-05-19 12:35:34.516 CST,,,30745,,60a49593.7819,4,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"redo starts at 0/37000028",,,,,,,,,"","startup"
2021-05-19 12:35:34.526 CST,,,30745,,60a49593.7819,5,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"consistent recovery state reached at 0/37000138",,,,,,,,,"","startup"
2021-05-19 12:35:34.526 CST,,,30743,,60a49593.7817,6,,2021-05-19 12:35:31 CST,,0,LOG,00000,"database system is ready to accept read only connections",,,,,,,,,"","postmaster"
2021-05-19 12:35:34.544 CST,,,30745,,60a49593.7819,6,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"restored log file ""000000010000000000000038"" from archive",,,,,,,,,"","startup"
2021-05-19 12:35:34.717 CST,,,30745,,60a49593.7819,7,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"recovery stopping after commit of transaction 10989, time 2021-05-19 12:34:28.143373+08",,,,,,,,,"","startup"
2021-05-19 12:35:34.717 CST,,,30745,,60a49593.7819,8,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"pausing at the end of recovery",,"Execute pg_wal_replay_resume() to promote.",,,,,,,"","startup"
所以，现在这个实例还是处于recovery的模式，不能进行写入的操作，transaction_read_only为on，对应的recovery.signal文件还在
[postgres@xiongcc ~]$ psql -p 5444
psql (13.2)
Type "help" for help.
postgres=# show transaction_read_only ;
transaction_read_only
-----------------------
on
(1 row)
postgres=# insert into t values(3,3);
ERROR: cannot execute INSERT in a read-only transaction
postgres=# \q
[postgres@xiongcc ~]$ ls -l testdata/ | grep recovery.signal
-rw-rw-r-- 1 postgres postgres 0 May 19 12:35 recovery.signal
显式调用一下pg_wal_replay_resume()该函数，可以发现recovery.signal文件没有了，并且日志里也显示，时间线加1
[postgres@xiongcc ~]$ psql -p 5444
psql (13.2)
Type "help" for help.
postgres=# select pg_wal_replay_resume();
pg_wal_replay_resume
----------------------
(1 row)
postgres=# show transaction_read_only ;
transaction_read_only
-----------------------
off
(1 row)
postgres=# \q
[postgres@xiongcc ~]$ ls -l testdata/ | grep recovery.signal
[postgres@xiongcc log]$ tail -n 5 postgresql-Wed.csv
2021-05-19 12:44:47.248 CST,,,30745,,60a49593.7819,9,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"redo done at 0/380000A0",,,,,,,,,"","startup"
2021-05-19 12:44:47.248 CST,,,30745,,60a49593.7819,10,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"last completed transaction was at log time 2021-05-19 12:34:28.143373+08",,,,,,,,,"","startup"
2021-05-19 12:44:47.257 CST,,,30745,,60a49593.7819,11,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"selected new timeline ID: 2",,,,,,,,,"","startup"
2021-05-19 12:44:47.363 CST,,,30745,,60a49593.7819,12,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"archive recovery complete",,,,,,,,,"","startup"
2021-05-19 12:44:47.405 CST,,,30743,,60a49593.7817,7,,2021-05-19 12:35:31 CST,,0,LOG,00000,"database system is ready to accept connections",,,,,,,,,"","postmaster"
看一下pg_wal目录，确实时间线+1
[postgres@xiongcc testdata]$ ls -l pg_wal/
total 49160
-rw------- 1 postgres postgres 16777216 May 19 12:35 000000010000000000000038
-rw------- 1 postgres postgres 16777216 May 19 12:44 000000020000000000000038
-rw------- 1 postgres postgres 16777216 May 19 12:35 000000020000000000000039
-rw------- 1 postgres postgres 37 May 19 12:44 00000002.history
drwx------ 2 postgres postgres 4096 May 19 12:44 archive_status
同样的，也可以直接指定recovery_target_action = 'promote'，这样的话，PostgreSQL就会帮你一并处理了，不用再自己调用pg_wal_replay_resume()，时间线也加1
recovery_target_action:指定当到达恢复目标时服务器应该采取什么动作。
默认值是pause， 这意味着将暂停恢复。
promote意味着将结束恢复进程并且服务器开始接受新的连接。
shutdown将在到达恢复目标后停止服务器。
2021-05-19 13:35:13.732 CST,,,31030,,60a4a391.7936,1,,2021-05-19 13:35:13 CST,,0,LOG,00000,"ending log output to stderr",,"Future log output will go to log destination ""csvlog"".",,,,,,,"","postmaster"
2021-05-19 13:35:13.732 CST,,,31030,,60a4a391.7936,2,,2021-05-19 13:35:13 CST,,0,LOG,00000,"starting PostgreSQL 13.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit",,,,,,,,,"","postmaster"
2021-05-19 13:35:13.732 CST,,,31030,,60a4a391.7936,3,,2021-05-19 13:35:13 CST,,0,LOG,00000,"listening on IPv4 address ""127.0.0.1"", port 5444",,,,,,,,,"","postmaster"
2021-05-19 13:35:13.732 CST,,,31030,,60a4a391.7936,4,,2021-05-19 13:35:13 CST,,0,LOG,XX000,"could not bind IPv6 address ""::1"": Cannot assign requested address",,"Is another postmaster already running on port 5444? If not, wait a few seconds and retry.",,,,,,,"","postmaster"
2021-05-19 13:35:13.759 CST,,,31030,,60a4a391.7936,5,,2021-05-19 13:35:13 CST,,0,LOG,00000,"listening on Unix socket ""/tmp/.s.PGSQL.5444""",,,,,,,,,"","postmaster"
2021-05-19 13:35:13.793 CST,,,31032,,60a4a391.7938,1,,2021-05-19 13:35:13 CST,,0,LOG,00000,"database system was interrupted; last known up at 2021-05-19 13:29:34 CST",,,,,,,,,"","startup"
2021-05-19 13:35:17.361 CST,,,31032,,60a4a391.7938,2,,2021-05-19 13:35:13 CST,,0,LOG,00000,"starting point-in-time recovery to XID 10991",,,,,,,,,"","startup"
2021-05-19 13:35:17.374 CST,,,31032,,60a4a391.7938,3,,2021-05-19 13:35:13 CST,,0,LOG,00000,"restored log file ""00000001000000000000003A"" from archive",,,,,,,,,"","startup"
2021-05-19 13:35:17.550 CST,,,31032,,60a4a391.7938,4,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"redo starts at 0/3A000028",,,,,,,,,"","startup"
2021-05-19 13:35:17.560 CST,,,31032,,60a4a391.7938,5,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"consistent recovery state reached at 0/3A000100",,,,,,,,,"","startup"
2021-05-19 13:35:17.560 CST,,,31030,,60a4a391.7936,6,,2021-05-19 13:35:13 CST,,0,LOG,00000,"database system is ready to accept read only connections",,,,,,,,,"","postmaster"
2021-05-19 13:35:17.576 CST,,,31032,,60a4a391.7938,6,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"restored log file ""00000001000000000000003B"" from archive",,,,,,,,,"","startup"
2021-05-19 13:35:17.771 CST,,,31032,,60a4a391.7938,7,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"recovery stopping after commit of transaction 10991, time 2021-05-19 13:31:13.096448+08",,,,,,,,,"","startup"
2021-05-19 13:35:17.771 CST,,,31032,,60a4a391.7938,8,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"redo done at 0/3B0000D8",,,,,,,,,"","startup"
2021-05-19 13:35:17.771 CST,,,31032,,60a4a391.7938,9,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"last completed transaction was at log time 2021-05-19 13:31:13.096448+08",,,,,,,,,"","startup"
2021-05-19 13:35:17.784 CST,,,31032,,60a4a391.7938,10,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"selected new timeline ID: 2",,,,,,,,,"","startup"
2021-05-19 13:35:17.981 CST,,,31032,,60a4a391.7938,11,,2021-05-19 13:35:13 CST,1/0,0,LOG,00000,"archive recovery complete",,,,,,,,,"","startup"
2021-05-19 13:35:18.159 CST,,,31030,,60a4a391.7936,7,,2021-05-19 13:35:13 CST,,0,LOG,00000,"database system is ready to accept connections",,,,,,,,,"","postmaster"
当然，你也可以在打印这条日志的时候，2021-05-19 12:35:34.717 CST,,,30745,,60a49593.7819,8,,2021-05-19 12:35:31 CST,1/0,0,LOG,00000,"pausing at the end of recovery",,"Execute pg_wal_replay_resume() to promote.",,,,,,,"","startup"，去把recovery.signal文件删了，再重启一下，也可以达到类似的效果：
[postgres@xiongcc ~]$ rm -rf testdata/recovery.signal
[postgres@xiongcc ~]$ psql -p 5444
psql (13.2)
Type "help" for help.
postgres=# show transaction_read_only ;
transaction_read_only
-----------------------
on
(1 row)
postgres=# \q
[postgres@xiongcc ~]$ pg_ctl -D testdata/ restart
waiting for server to shut down.... done
server stopped
waiting for server to start....2021-05-19 14:17:10.765 CST [31247] LOG: redirecting log output to logging collector process
2021-05-19 14:17:10.765 CST [31247] HINT: Future log output will appear in directory "log".
done
server started
[postgres@xiongcc ~]$ psql -p 5444
psql (13.2)
Type "help" for help.
postgres=# show transaction_read_only ;
transaction_read_only
-----------------------
off
(1 row)
postgres=# \q
不过这种我认为就有点本末倒置了，会引起什么其他幺蛾子不好说，还是规范操作，规范化。
小结
回到最开始的话题，时间线加1这个动作，在PITR模式下，有一个前提：恢复完成后，并且不再处于recovery模式了，时间线才会正式加1，否则只能以只读的模式进行操作。
因为一般情况下我们都习惯于设置好recovery_target_action = 'promote'，这样就省去了我们手动调用pg_wal_replay_resume()然后提升的步骤，时间线就自然加1了。
另外，长期以来，recovery.conf文件一直被认为是一个PostgreSQL中的缺陷，因为配置参数分布在多个不同的文件中是不合理的，另外还不能使用ALTER SYSTEM命令对参数进行修改。所以从v12开始，针对此问题进行了改进，把recovery.conf中的参数合到了postgresql.conf配置文件中。新增了两个信号文件：
recovery.signal：告诉PostgreSQL进入正常的归档恢复
standby.signal：告诉PostgreSQL进入standby模式
如果两个文件都存在，则standby.signal优先。另外，如果设置了这些参数中的recovery_target\recovery_target_lsn\recovery_target_name\recovery_target_time\recovery_target_xid多个的话，实例会报错的
[postgres@xiongcc ~]$ pg_ctl -D testdata/ start
waiting for server to start....2021-05-19 05:33:25.283 GMT [31022] FATAL: multiple recovery targets specified
2021-05-19 05:33:25.283 GMT [31022] DETAIL: At most one of recovery_target, recovery_target_lsn, recovery_target_name, recovery_target_time, recovery_target_xid may be set.
stopped waiting
pg_ctl: could not start server
Examine the log output.
最后
这次事情过后 (再次感谢CCTV、“神医”和占元) ，我决定创建一个关于PostgreSQL学徒公众号的交流群，美其名曰——PG学徒纠错探讨群，因为公众号没有留言功能，要么就公众号迁移，要么嵌入小程序，我太懒了，又懒得折腾。
对于那些饱受文字摧残想逼逼几句的，欢迎入群，闲聊扯淡，吃枣药丸😀
原文作者：PostgreSQL学徒；如有侵权，请联系管理员删除。
下一篇：
PostgreSQL流复制的方方面面
请登录后发表评论
登录
全部评论
