Re: [Proposal] Fully WAL logged CREATE DATABASE - No Checkpoints

On Tue, Aug 2, 2022 at 1:50 PM Justin Pryzby <pryzby(at)telsasoft(dot)com> wrote:
> Unfortunately, that isn't very consistent, and you have have to run it a bunch
> of times...

I was eventually able to reproduce this in part by using the
interactive psql method you describe. It didn't crash, but it did spit
out a bunch of funny error messages:

postgres=# SET statement_timeout=0; DROP DATABASE a; SET
statement_timeout='60ms'; CREATE DATABASE a TEMPLATE postgres STRATEGY
wal_log ; \c a \c postgres
SET
ERROR: database "a" does not exist
SET
ERROR: canceling statement due to statement timeout
WARNING: problem in alloc set PortalContext: req size > alloc size
for chunk 0x7f99508911f0 in block 0x7f9950890800
WARNING: problem in alloc set PortalContext: bad size 0 for chunk
0x7f99508911f0 in block 0x7f9950890800
WARNING: problem in alloc set PortalContext: bad single-chunk
0x7f9950891208 in block 0x7f9950890800
WARNING: problem in alloc set PortalContext: found inconsistent
memory block 0x7f9950890800
WARNING: problem in alloc set PortalContext: req size > alloc size
for chunk 0x7f99508911f0 in block 0x7f9950890800
WARNING: problem in alloc set PortalContext: bad size 0 for chunk
0x7f99508911f0 in block 0x7f9950890800
WARNING: problem in alloc set PortalContext: bad single-chunk
0x7f9950891208 in block 0x7f9950890800
WARNING: problem in alloc set PortalContext: found inconsistent
memory block 0x7f9950890800
connection to server on socket "/tmp/.s.PGSQL.5432" failed: FATAL:
database "a" does not exist
Previous connection kept
postgres=# select * from pg_database;
oid | datname | datdba | encoding | datlocprovider | datistemplate
| datallowconn | datconnlimit | datfrozenxid | datminmxid |
dattablespace | datcollate | datctype | daticulocale |
datcollversion | datacl
-----+-----------+--------+----------+----------------+---------------+--------------+--------------+--------------+------------+---------------+-------------+-------------+--------------+----------------+----------------------------
5 | postgres | 10 | 6 | c | f
| t | -1 | 718 | 1 |
1663 | en_US.UTF-8 | en_US.UTF-8 | | |
1 | template1 | 10 | 6 | c | t
| t | -1 | 718 | 1 |
1663 | en_US.UTF-8 | en_US.UTF-8 | | |
{=c/rhaas,rhaas=CTc/rhaas}
4 | template0 | 10 | 6 | c | t
| f | -1 | 718 | 1 |
1663 | en_US.UTF-8 | en_US.UTF-8 | | |
{=c/rhaas,rhaas=CTc/rhaas}
(3 rows)

I then set backtrace_functions='AllocSetCheck' and reproduced it
again, which led to stack traces like this:

2022-08-02 16:50:32.490 EDT [98814] WARNING: problem in alloc set
PortalContext: bad single-chunk 0x7f9950886608 in block 0x7f9950885c00
2022-08-02 16:50:32.490 EDT [98814] BACKTRACE:
2 postgres 0x000000010cd37ef5 AllocSetCheck + 549
3 postgres 0x000000010cd37730 AllocSetReset + 48
4 postgres 0x000000010cd3f6f1
MemoryContextResetOnly + 81
5 postgres 0x000000010cd378b9 AllocSetDelete + 73
6 postgres 0x000000010cd41e09 PortalDrop + 425
7 postgres 0x000000010cd427bb
AtCleanup_Portals + 203
8 postgres 0x000000010c86476d
CleanupTransaction + 29
9 postgres 0x000000010c865d4f
AbortCurrentTransaction + 63
10 postgres 0x000000010cba1395 PostgresMain + 885
11 postgres 0x000000010caf5472 PostmasterMain + 7586
12 postgres 0x000000010ca31e3d main + 2205
13 libdyld.dylib 0x00007fff699afcc9 start + 1
14 ??? 0x0000000000000001 0x0 + 1

I recompiled with -O0 and hacked the code that emits the BACKTRACE:
bit to go into an infinite loop if it's hit, which enabled me to hook
up a debugger at the point of the failure. The debugger says:

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
frame #0: 0x000000010e98a157
postgres`send_message_to_server_log(edata=0x000000010ec0f658) at
elog.c:2916:4
frame #1: 0x000000010e9866d6 postgres`EmitErrorReport at elog.c:1537:3
frame #2: 0x000000010e986016 postgres`errfinish(filename="aset.c",
lineno=1470, funcname="AllocSetCheck") at elog.c:592:2
frame #3: 0x000000010e9c8465
postgres`AllocSetCheck(context=0x00007ff77c80d200) at aset.c:1469:5
frame #4: 0x000000010e9c7c05
postgres`AllocSetDelete(context=0x00007ff77c80d200) at aset.c:638:2
frame #5: 0x000000010e9d368b
postgres`MemoryContextDelete(context=0x00007ff77c80d200) at
mcxt.c:252:2
* frame #6: 0x000000010e9d705b
postgres`PortalDrop(portal=0x00007ff77e028920, isTopCommit=false) at
portalmem.c:596:2
frame #7: 0x000000010e9d7e0e postgres`AtCleanup_Portals at portalmem.c:907:3
frame #8: 0x000000010e22030d postgres`CleanupTransaction at xact.c:2890:2
frame #9: 0x000000010e2219da postgres`AbortCurrentTransaction at
xact.c:3328:4
frame #10: 0x000000010e763237
postgres`PostgresMain(dbname="postgres", username="rhaas") at
postgres.c:4232:3
frame #11: 0x000000010e6625aa
postgres`BackendRun(port=0x00007ff77c1042c0) at postmaster.c:4490:2
frame #12: 0x000000010e661b18
postgres`BackendStartup(port=0x00007ff77c1042c0) at
postmaster.c:4218:3
frame #13: 0x000000010e66088a postgres`ServerLoop at postmaster.c:1808:7
frame #14: 0x000000010e65def2 postgres`PostmasterMain(argc=1,
argv=0x00007ff77ae05cf0) at postmaster.c:1480:11
frame #15: 0x000000010e50521f postgres`main(argc=1,
argv=0x00007ff77ae05cf0) at main.c:197:3
frame #16: 0x00007fff699afcc9 libdyld.dylib`start + 1
(lldb) fr sel 6
frame #6: 0x000000010e9d705b
postgres`PortalDrop(portal=0x00007ff77e028920, isTopCommit=false) at
portalmem.c:596:2
593 MemoryContextDelete(portal->holdContext);
594
595 /* release subsidiary storage */
-> 596 MemoryContextDelete(portal->portalContext);
597
598 /* release portal struct (it's in TopPortalContext) */
599 pfree(portal);
(lldb) fr sel 3
frame #3: 0x000000010e9c8465
postgres`AllocSetCheck(context=0x00007ff77c80d200) at aset.c:1469:5
1466 * Check chunk size
1467 */
1468 if (dsize > chsize)
-> 1469 elog(WARNING, "problem in alloc set %s: req size > alloc size
for chunk %p in block %p",
1470 name, chunk, block);
1471 if (chsize < (1 << ALLOC_MINBITS))
1472 elog(WARNING, "problem in alloc set %s: bad size %zu for chunk
%p in block %p",
(lldb) p dsize
(Size) $3 = 20
(lldb) p chsize
(Size) $4 = 0

It seems like CreateDatabaseUsingWalLog() must be doing something that
corrupts PortalContext, but at the moment I'm not sure what that thing
could be.

--
Robert Haas
EDB: http://www.enterprisedb.com