Thread: Postgresql crashdown and recovery failure

Hi,

My database (Postgresql 12.5) server uses remote storage as data directory.

I powered off the database server and started postgresql (same version) on another server, with same data. However it failed. I checked wal logs and found that the content around latest checkpoint is empty. (about 1700 zero bytes)

# pg_controldata -D .

pg_control version number:            1201

Catalog version number:               201909212

Database system identifier:           6967594878781603854

Database cluster state:               in production

pg_control last modified:             Wed 09 Jun 2021 04:23:24 PM CST

Latest checkpoint location:           0/9893978

Latest checkpoint's REDO location:    0/9893940

Latest checkpoint's REDO WAL file:    000000010000000000000009

Latest checkpoint's TimeLineID:       1

...

# pg_waldump -p ./pg_wal/ -s 0/9893900

first record is after 0/9893900, at 0/9893908, skipping over 8 bytes

rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/09893908, prev 0/098938E0, desc: RUNNING_XACTS nextXid 30176 latestCompletedXid 30175 oldestRunningXid 30176

pg_waldump: fatal: error in WAL record at 0/9893908: invalid record length at 0/9893940: wanted 24, got 0

# hexdump -C ./pg_wal/000000010000000000000009 -s 0x89393a -n 10000

0089393a  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|

*

00893ffa  00 00 00 00 00 00 01 d1  05 00 01 00 00 00 00 40  |...............@|

0089400a  89 07 00 00 00 00 4b 00  00 00 00 00 00 00 00 00  |......K.........|

...

It seems the checkpoint record in wal buffer is not flushed to disk, leading to recovery failure.

The remote storage support Posix IO, meaning the data would be written to disk as long as postgresql called fdatasync (or other similar system calls). Please notice the storage server has not been shut down.

Besides, I traced the system calls of postgresql checkpoint (triggered by “psql –c checkpoint”).

# strace -fvy -s 64 pg_ctl -D /tmp/data start 2>&1 | grep –E ‘open|sync’

...

[pid 109705] openat(AT_FDCWD, "pg_xact/0000", O_RDWR|O_CREAT, 0600 <unfinished ...>

[pid 109705] <... openat resumed> )     = 3</tmp/data/pg_xact/0000>

[pid 109705] fsync(3</tmp/data/pg_xact/0000> <unfinished ...>

[pid 109705] <... fsync resumed> )      = 0

[pid 109705] openat(AT_FDCWD, "pg_xact", O_RDONLY) = 3</tmp/data/pg_xact>

[pid 109705] fsync(3</tmp/data/pg_xact>) = 0

[pid 109705] openat(AT_FDCWD, "pg_commit_ts", O_RDONLY) = 3</tmp/data/pg_commit_ts>

[pid 109705] fsync(3</tmp/data/pg_commit_ts>) = 0

[pid 109705] openat(AT_FDCWD, "pg_subtrans/0000", O_RDWR|O_CREAT, 0600) = 3</tmp/data/pg_subtrans/0000>

[pid 109705] openat(AT_FDCWD, "pg_multixact/offsets/0000", O_RDWR|O_CREAT, 0600) = 3</tmp/data/pg_multixact/offsets/0000>

[pid 109705] fsync(3</tmp/data/pg_multixact/offsets/0000>) = 0

[pid 109705] openat(AT_FDCWD, "pg_multixact/offsets", O_RDONLY) = 3</tmp/data/pg_multixact/offsets>

[pid 109705] fsync(3</tmp/data/pg_multixact/offsets>) = 0

[pid 109705] openat(AT_FDCWD, "pg_multixact/members", O_RDONLY) = 3</tmp/data/pg_multixact/members>

[pid 109705] fsync(3</tmp/data/pg_multixact/members>) = 0

[pid 109705] openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3</tmp/data/pg_logical/snapshots>

[pid 109705] openat(AT_FDCWD, "pg_logical/mappings", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3</tmp/data/pg_logical/mappings>

[pid 109705] openat(AT_FDCWD, "pg_logical/replorigin_checkpoint.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 3</tmp/data/pg_logical/replorigin_checkpoint.tmp>

[pid 109705] openat(AT_FDCWD, "pg_logical/replorigin_checkpoint.tmp", O_RDWR) = 3</tmp/data/pg_logical/replorigin_checkpoint.tmp>

[pid 109705] fsync(3</tmp/data/pg_logical/replorigin_checkpoint.tmp>) = 0

[pid 109705] openat(AT_FDCWD, "pg_logical/replorigin_checkpoint", O_RDWR) = 3</tmp/data/pg_logical/replorigin_checkpoint>

[pid 109705] fsync(3</tmp/data/pg_logical/replorigin_checkpoint>) = 0

[pid 109705] openat(AT_FDCWD, "pg_logical/replorigin_checkpoint", O_RDWR) = 3</tmp/data/pg_logical/replorigin_checkpoint>

[pid 109705] fsync(3</tmp/data/pg_logical/replorigin_checkpoint>) = 0

[pid 109705] openat(AT_FDCWD, "pg_logical", O_RDONLY) = 3</tmp/data/pg_logical>

[pid 109705] fsync(3</tmp/data/pg_logical>) = 0

[pid 109705] openat(AT_FDCWD, "pg_wal/00000001000000000000000B", O_RDWR <unfinished ...>

[pid 109705] <... openat resumed> )     = 3</tmp/data/pg_wal/00000001000000000000000B>

[pid 109705] fdatasync(3</tmp/data/pg_wal/00000001000000000000000B> <unfinished ...>          (Let’s say it is A)

[pid 109705] <... fdatasync resumed> )  = 0

[pid 109705] openat(AT_FDCWD, "/tmp/data/global/pg_control", O_RDWR <unfinished ...>

[pid 109705] <... openat resumed> )     = 4</tmp/data/global/pg_control>

[pid 109705] fsync(4</tmp/data/global/pg_control> <unfinished ...>                               (Let’s say it is B)

[pid 109705] <... fsync resumed> )      = 0

[pid 109705] openat(AT_FDCWD, "pg_wal", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4</tmp/data/pg_wal>

[pid 109705] openat(AT_FDCWD, "pg_subtrans", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4</tmp/data/pg_subtrans>

[pid 109707] fdatasync(3</tmp/data/pg_wal/00000001000000000000000B>) = 0                        (Let’s say it is C)

...

From the output, I can see that data files, pg_control file and wal log are flushed to disk. And I noticed that pg_control file is flushed between 2 wal flush (as noted A,B,C).

Here are my questions:

1.  If power off occurs between B and C. Would it be possible that checkpoint was written to pg_control but not to wal log? And as a consequence, postgresql recovery would fail?

2.  Is there any other reason causing this problem?

3.  Is there any way to recover the data? I know pg_resetwal can reset wal log, then postgresql can start. But undoubtedly it could cause some data loss.

Thanks,

Xie Bin