引子
将PostgreSQL的GUC参数wal_recycle设置为on,然后对数据库执行一定业务量的操作,会发现在pg_wal目录下,有很多未来使用的wal文件,且创建时间比现在正在使用的wal文件更早,下文将描述和分析这种情况。
问题描述
问题1:为什么未来使用的wal文件,创建时间会更早?
- 使用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]$
- 查看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]$
- 使用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文件,创建时间会更早?
- 查看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]$
- 分析PostgreSQL的checkpoint执行流程,
- 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文件?
- 使用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
- 堆栈分析,定位到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)
- 关键以下代码:
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...
}
- 经过调试发现,pg_waldump在解析00000001000000000000007B文件时,发现其中的第一个XLogPageHeader的xlp_pageaddr是0x4b000000,也就是对应archive/00000001000000000000004B文件,与其文件名00000001000000000000007B不符,所以打印错误信息,退出该wal文件的解析。
小结
- PostgreSQL对于不再使用的wal文件,会根据具体情况,以及wal_recycle参数,决定是执行回收还是删除操作。如果是回收wal文件,则是直接重命名该wal文件的,并不会修改或者重置wal文件中的内容。
- 使用pg_waldump工具,无法解析回收的wal文件,原因是回收的wal文件,根据其文件名称,与文件中的实际内容,计算出的xlp_pageaddr不一致,pg_waldump发现不一致后,直接退出wal文件的解析。