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
TABLEt(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,
0removed, 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=0kB, 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