PostgreSQL的wal文件回收问题

引子

将PostgreSQL的GUC参数wal_recycle设置为on，然后对数据库执行一定业务量的操作，会发现在pg_wal目录下，有很多未来使用的wal文件，且创建时间比现在正在使用的wal文件更早，下文将描述和分析这种情况。

问题描述

问题1：为什么未来使用的wal文件，创建时间会更早？

1. 使用pg_controldata程序，查看数据库控制文件，发现PostgreSQL数据库当前正使用的wal文件为00000001000000000000007A;

[coder@localhost build_postgres]$ ./bin/pg_controldata data_test/
pg_control version number:            1201
Catalog version number:               201909212
Database system identifier:           7331656414979148006
Database cluster state:               shut down
pg_control last modified:             2024年02月04日 星期日 16时38分49秒
Latest checkpoint location:           0/7A000028
Latest checkpoint's REDO location:    0/7A000028
Latest checkpoint's REDO WAL file:    00000001000000000000007A
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:497
Latest checkpoint's NextOID:          16396
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        479
Latest checkpoint's oldestXID's DB:   1
Latest checkpoint's oldestActiveXID:  0
Latest checkpoint's oldestMultiXid:   1
Latest checkpoint's oldestMulti's DB: 1
Latest checkpoint's oldestCommitTsXid:486
Latest checkpoint's newestCommitTsXid:496
Time of latest checkpoint:            2024年02月04日 星期日 16时38分49秒
Fake LSN counter for unlogged rels:   0/3E8
Minimum recovery ending location:     0/0
Min recovery ending loc's timeline:   0
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
wal_level setting:                    logical
wal_log_hints setting:                off
max_connections setting:              100
max_worker_processes setting:         8
max_wal_senders setting:              10
max_prepared_xacts setting:           0
max_locks_per_xact setting:           64
track_commit_timestamp setting:       on
Maximum data alignment:               8
Database block size:                  8192
Blocks per segment of large relation: 131072
WAL block size:                       8192
Bytes per WAL segment:                16777216
Maximum length of identifiers:        64
Maximum columns in an index:          32
Maximum size of a TOAST chunk:        1996
Size of a large-object chunk:         2048
Date/time type storage:               64-bit integers
Float4 argument passing:              by value
Float8 argument passing:              by value
Data page checksum version:           0
Mock authentication nonce:            def3a46f189241ca0085fac72f98a6f359897b3104fdc4ae6b4ea9ff7423e724
[coder@localhost build_postgres]$

2. 查看data/pg_wal目录，发现在wal文件00000001000000000000007A后面，预分配了一些未来使用的wal文件。00000001000000000000007A后面的wal文件，是PostgreSQL在执行ckpt时，预分配的wal文件。观察发现，00000001000000000000007B及其以后的wal文件的时间，反而比00000001000000000000007A的创建时间更早。

[coder@localhost build_postgres]$ ll data_test/pg_wal/
总用量 1048576
-rw-------. 1 coder coder 16777216 2月   4 16:38 000000010000000000000079
-rw-------. 1 coder coder 16777216 2月   4 16:38 00000001000000000000007A
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000007B
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000007C
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000007D
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000007E
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000007F
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000080
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000081
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000082
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000083
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000084
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000085
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000086
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000087
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000088
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000089
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000008A
-rw-------. 1 coder coder 16777216 2月   4 16:24 00000001000000000000008B
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000008C
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000008D
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000008E
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000008F
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000090
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000091
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000092
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000093
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000094
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000095
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000096
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000097
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000098
-rw-------. 1 coder coder 16777216 2月   4 16:25 000000010000000000000099
-rw-------. 1 coder coder 16777216 2月   4 16:25 00000001000000000000009A
-rw-------. 1 coder coder 16777216 2月   4 16:26 00000001000000000000009B
-rw-------. 1 coder coder 16777216 2月   4 16:26 00000001000000000000009C
-rw-------. 1 coder coder 16777216 2月   4 16:26 00000001000000000000009D
-rw-------. 1 coder coder 16777216 2月   4 16:26 00000001000000000000009E
-rw-------. 1 coder coder 16777216 2月   4 16:26 00000001000000000000009F
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A0
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A1
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A2
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A3
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A4
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A5
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A6
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A7
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A8
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000A9
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000AA
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000AB
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000AC
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000AD
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000AE
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000AF
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B0
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B1
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B2
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B3
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B4
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B5
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B6
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B7
-rw-------. 1 coder coder 16777216 2月   4 16:26 0000000100000000000000B8
drwx------. 2 coder coder       43 2月   4 16:38 archive_status
[coder@localhost build_postgres]$

3. 使用stat，查看wal文件的更改时间信息

[coder@localhost build_postgres]$ stat data_test/pg_wal/00000001000000000000007A
文件："data_test/pg_wal/00000001000000000000007A"
大小：16777216        块：32768      IO 块：4096   普通文件
设备：fd00h/64768d      Inode：33554500    硬链接：1
权限：(0600/-rw-------)  Uid：( 1000/   coder)   Gid：( 1000/   coder)
环境：unconfined_u:object_r:user_home_t:s0
最近访问：2024-02-04 16:39:38.050057576 +0800
最近更改：2024-02-04 16:38:49.974694468 +0800
最近改动：2024-02-04 16:38:49.974694468 +0800
创建时间：-

[coder@localhost build_postgres]$ stat data_test/pg_wal/00000001000000000000007B
文件："data_test/pg_wal/00000001000000000000007B"
大小：16777216        块：32768      IO 块：4096   普通文件
设备：fd00h/64768d      Inode：33554504    硬链接：1
权限：(0600/-rw-------)  Uid：( 1000/   coder)   Gid：( 1000/   coder)
环境：unconfined_u:object_r:user_home_t:s0
最近访问：2024-02-04 16:39:44.187103929 +0800
最近更改：2024-02-04 16:25:39.695772523 +0800
最近改动：2024-02-04 16:26:20.931006693 +0800
创建时间：-
[coder@localhost build_postgres]$

问题2：为什么无法使用pg_waldump，解析未来使用的wal文件？

使用pg_waldump程序，解析PostgreSQL预分配给未来使用的wal文件，发现pg_waldump提示“fatal: could not find a valid record after 0/7C000000”，无法成功解析未来使用的wal文件；

[coder@localhost build_postgres]$ ./bin/pg_waldump data_test/pg_wal/00000001000000000000007C | tail -n 10
pg_waldump: fatal: could not find a valid record after 0/7C000000
[coder@localhost build_postgres]$

问题分析

问题1：为什么未来使用的wal文件，创建时间会更早？

1. 查看00000001000000000000007B文件的MD5,并与archive归档目录下的wal文件比较，我们发现00000001000000000000007B文件，与00000001000000000000004B的MD5是一致的。

[coder@localhost build_postgres]$ md5sum data_test/pg_wal/00000001000000000000007B
bac5e93ba8d551dabd8ffe5a24a678d1  data_test/pg_wal/00000001000000000000007B
[coder@localhost build_postgres]$ md5sum archive/* |grep bac5e93ba8d551dabd8ffe5a24a678d1
bac5e93ba8d551dabd8ffe5a24a678d1  archive/00000001000000000000004B
[coder@localhost build_postgres]$

2. 分析PostgreSQL的checkpoint执行流程，

3. RemoveXlogFile函数中，关键代码如下：

static void
RemoveXlogFile(const char *segname, XLogRecPtr lastredoptr, XLogRecPtr endptr)
{skip.../** Before deleting the file, see if it can be recycled as a future log* segment. Only recycle normal files, pg_standby for example can create* symbolic links pointing to a separate archive directory.*/if (wal_recycle &&endlogSegNo <= recycleSegNo &&lstat(path, &statbuf) == 0 && S_ISREG(statbuf.st_mode) &&InstallXLogFileSegment(&endlogSegNo, path,true, recycleSegNo, true)){ereport(DEBUG2,(errmsg("recycled write-ahead log file \"%s\"",segname)));CheckpointStats.ckpt_segs_recycled++;/* Needn't recheck that slot on future iterations */endlogSegNo++;}else{skip...}skip...
}

问题2：为什么无法使用pg_waldump，解析未来使用的wal文件？

1. 使用pg_waldump解析00000001000000000000007B文件，发现无法成功解析，提示如下：

[coder@localhost build_postgres]$ ./bin/pg_waldump data_test/pg_wal/00000001000000000000007B
pg_waldump: fatal: could not find a valid record after 0/7B000000

2. 堆栈分析，定位到XLogReaderValidatePageHeader函数中：

(gdb) bt
#0  XLogReaderValidatePageHeader (state=0x6401f0, recptr=2063597568, phdr=0x640b10 "\001\321\a") at xlogreader.c:865
#1  0x000000000040574a in ReadPageInternal (state=0x6401f0, pageptr=2063597568, reqLen=0) at xlogreader.c:629
#2  0x00000000004060d9 in XLogFindNextRecord (state=0x6401f0, RecPtr=2063597568) at xlogreader.c:959
#3  0x00000000004044a7 in main (argc=2, argv=0x7fffffffe3e8) at pg_waldump.c:1116
(gdb)

3. 关键以下代码：

bool
XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr,char *phdr)
{...skip...if (hdr->xlp_pageaddr != recaddr){char        fname[MAXFNAMELEN];XLogFileName(fname, state->readPageTLI, segno, state->wal_segment_size);report_invalid_record(state,"unexpected pageaddr %X/%X in log segment %s, offset %u",(uint32) (hdr->xlp_pageaddr >> 32), (uint32) hdr->xlp_pageaddr,fname,offset);return false;}...skip...
}

4. 经过调试发现，pg_waldump在解析00000001000000000000007B文件时，发现其中的第一个XLogPageHeader的xlp_pageaddr是0x4b000000，也就是对应archive/00000001000000000000004B文件，与其文件名00000001000000000000007B不符，所以打印错误信息，退出该wal文件的解析。

小结

1. PostgreSQL对于不再使用的wal文件，会根据具体情况，以及wal_recycle参数，决定是执行回收还是删除操作。如果是回收wal文件，则是直接重命名该wal文件的，并不会修改或者重置wal文件中的内容。
2. 使用pg_waldump工具，无法解析回收的wal文件，原因是回收的wal文件，根据其文件名称，与文件中的实际内容，计算出的xlp_pageaddr不一致，pg_waldump发现不一致后，直接退出wal文件的解析。