Re: DDL result is lost by CREATE DATABASE with WAL_LOG strategy

On Wed, Feb 15, 2023 at 04:49:38AM +0000, Ryo Matsumura (Fujitsu) wrote:
> Hi, hackers.
>
> I found that CREATE DATABASE occurs lost of DDL result after crash server.
> The direct cause is that the checkpoint skips sync for page of template1's main fork
> because buffer status is not marked as BM_PERMANENT in BufferAlloc().

I had some trouble reproducing this when running the commands by hand.

But it reproduces fine like this:

$ ./tmp_install/usr/local/pgsql/bin/postgres -D ./testrun/regress/regress/tmp_check/data& sleep 2; psql -h /tmp postgres -c "DROP DATABASE IF EXISTS j" -c "CREATE DATABASE j STRATEGY wal_log" && psql -h /tmp template1 -c "CREATE TABLE t(i int)" -c "INSERT INTO t SELECT generate_series(1,9)" -c CHECKPOINT; kill -9 %1; wait; ./tmp_install/usr/local/pgsql/bin/postgres -D ./testrun/regress/regress/tmp_check/data& sleep 9; psql -h /tmp template1 -c "table t"; kill %1
[1] 29069
2023-02-15 10:10:27.584 CST postmaster[29069] LOG: starting PostgreSQL 16devel on x86_64-linux, compiled by gcc-9.4.0, 64-bit
2023-02-15 10:10:27.584 CST postmaster[29069] LOG: listening on IPv4 address "127.0.0.1", port 5432
2023-02-15 10:10:27.663 CST postmaster[29069] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-02-15 10:10:27.728 CST startup[29074] LOG: database system was shut down at 2023-02-15 10:10:13 CST
2023-02-15 10:10:27.780 CST postmaster[29069] LOG: database system is ready to accept connections
NOTICE: database "j" does not exist, skipping
DROP DATABASE
CREATE DATABASE
CREATE TABLE
INSERT 0 9
2023-02-15 10:10:30.160 CST checkpointer[29072] LOG: checkpoint starting: immediate force wait
2023-02-15 10:10:30.740 CST checkpointer[29072] LOG: checkpoint complete: wrote 943 buffers (5.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.070 s, sync=0.369 s, total=0.581 s; sync files=268, longest=0.274 s, average=0.002 s; distance=4322 kB, estimate=4322 kB; lsn=0/BA9E8A0, redo lsn=0/BA9E868
CHECKPOINT
[1]+ Killed ./tmp_install/usr/local/pgsql/bin/postgres -D ./testrun/regress/regress/tmp_check/data
[1] 29088
2023-02-15 10:10:31.664 CST postmaster[29088] LOG: starting PostgreSQL 16devel on x86_64-linux, compiled by gcc-9.4.0, 64-bit
2023-02-15 10:10:31.665 CST postmaster[29088] LOG: listening on IPv4 address "127.0.0.1", port 5432
2023-02-15 10:10:31.724 CST postmaster[29088] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-02-15 10:10:31.780 CST startup[29094] LOG: database system was interrupted; last known up at 2023-02-15 10:10:30 CST
2023-02-15 10:10:33.888 CST startup[29094] LOG: database system was not properly shut down; automatic recovery in progress
2023-02-15 10:10:33.934 CST startup[29094] LOG: redo starts at 0/BA9E868
2023-02-15 10:10:33.934 CST startup[29094] LOG: invalid record length at 0/BA9E918: wanted 24, got 0
2023-02-15 10:10:33.934 CST startup[29094] LOG: redo done at 0/BA9E8A0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2023-02-15 10:10:34.073 CST checkpointer[29092] LOG: checkpoint starting: end-of-recovery immediate wait
2023-02-15 10:10:34.275 CST checkpointer[29092] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.035 s, sync=0.026 s, total=0.257 s; sync files=2, longest=0.019 s, average=0.013 s; distance=0 kB, estimate=0 kB; lsn=0/BA9E918, redo lsn=0/BA9E918
2023-02-15 10:10:34.321 CST postmaster[29088] LOG: database system is ready to accept connections
2023-02-15 10:10:39.893 CST client backend[29110] psql ERROR: relation "t" does not exist at character 7
2023-02-15 10:10:39.893 CST client backend[29110] psql STATEMENT: table t
ERROR: relation "t" does not exist