Date: Wed, 3 Aug 2022 12:01:18 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Dilip Kumar <dilipbalaut@gmail.com>
Cc: Andres Freund <andres@anarazel.de>, Tom Lane <tgl@sss.pgh.pa.us>,
	Robert Haas <robertmhaas@gmail.com>,
	Ashutosh Sharma <ashu.coek88@gmail.com>,
	Maciek Sakrejda <m.sakrejda@gmail.com>,
	Bruce Momjian <bruce@momjian.us>,
	Alvaro Herrera <alvherre@alvh.no-ip.org>,
	Andrew Dunstan <andrew@dunslane.net>,
	Heikki Linnakangas <hlinnaka@iki.fi>,
	pgsql-hackers@lists.postgresql.org
Subject: Re: [Proposal] Fully WAL logged CREATE DATABASE - No Checkpoints
Message-ID: <20220803170118.GG19644@telsasoft.com>
References: <20220802175043.GA13682@telsasoft.com>
 <CA+TgmobZufK6PcCRpvjP6dJqOBO-woWZF0cqMHWGvzkbgeaBKw@mail.gmail.com>
 <2767668.1659476794@sss.pgh.pa.us>
 <20220802220416.GC13682@telsasoft.com>
 <20220802222334.umf5wsa2r63koppn@awork3.anarazel.de>
 <CAFiTN-sG9-ocJFN+KBAQ2mTuF-9Ja+i1Qo81yqr0WDOsqqYpLg@mail.gmail.com>
 <CAFiTN-sL8M+Z6nongs=rSqfP26Vr0O_EYLfcwbO-Emz1GYxtxA@mail.gmail.com>
 <CAFiTN-v4u2WJT6y1n4wtM4Z3tffJonT7zuRKegYao9p-Oyb07Q@mail.gmail.com>
 <CAFiTN-thCGvRF0_WftbDc0KFagB3vgHHGrpNdRMJ6vtkObEMoA@mail.gmail.com>
 <20220803160200.GD19644@telsasoft.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20220803160200.GD19644@telsasoft.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20220803170118.GG19644%40telsasoft.com>
Precedence: bulk

On Wed, Aug 03, 2022 at 11:02:00AM -0500, Justin Pryzby wrote:
> But I reproduced the first problem with a handful of tries interrupting the
> while loop:
> 
> 2022-08-03 10:39:50.129 CDT client backend[5530] [unknown] PANIC:  could not open critical system index 2662
...
> So far, I haven't succeeded in eliciting anything useful from valgrind.

Now, I've reproduced the problem under valgrind, but it doesn't show anything
useful:

pryzbyj@pryzbyj:~$ while :; do psql -h /tmp template1 -c "DROP DATABASE a" -c "CREATE DATABASE a TEMPLATE postgres STRATEGY wal_log"; done
ERROR:  database "a" does not exist
CREATE DATABASE
^CCancel request sent
ERROR:  canceling statement due to user request
ERROR:  database "a" already exists
^C
pryzbyj@pryzbyj:~$ ^C
pryzbyj@pryzbyj:~$ ^C
pryzbyj@pryzbyj:~$ ^C
pryzbyj@pryzbyj:~$ psql -h /tmp a -c ''
2022-08-03 11:57:39.178 CDT client backend[31321] [unknown] PANIC:  could not open critical system index 2662
psql: error: falló la conexión al servidor en el socket «/tmp/.s.PGSQL.5432»: PANIC:  could not open critical system index 2662


On the server process, nothing interesting but the backtrace (the error was
before this, while writing the relation file, but there's nothing suspicious).

2022-08-03 11:08:06.628 CDT client backend[2841] [unknown] PANIC:  could not open critical system index 2662
==2841==
==2841== Process terminating with default action of signal 6 (SIGABRT)
==2841==    at 0x5FBBE97: raise (raise.c:51)
==2841==    by 0x5FBD800: abort (abort.c:79)
==2841==    by 0x2118DEF: errfinish (elog.c:675)
==2841==    by 0x20F6002: load_critical_index (relcache.c:4328)
==2841==    by 0x20F727A: RelationCacheInitializePhase3 (relcache.c:4103)
==2841==    by 0x213DFA5: InitPostgres (postinit.c:1087)
==2841==    by 0x1D20D72: PostgresMain (postgres.c:4081)
==2841==    by 0x1B15CFD: BackendRun (postmaster.c:4490)
==2841==    by 0x1B1D6E1: BackendStartup (postmaster.c:4218)
==2841==    by 0x1B1DD59: ServerLoop (postmaster.c:1808)
==2841==    by 0x1B1F86D: PostmasterMain (postmaster.c:1480)
==2841==    by 0x17B7150: main (main.c:197)

Below, I reproduced it without valgrind (and without LANG):

pryzbyj@pryzbyj:~/src/postgres$ while :; do psql -qh /tmp template1 -c "DROP DATABASE a" -c "CREATE DATABASE a TEMPLATE postgres STRATEGY wal_log"; done
2022-08-03 11:59:52.675 CDT checkpointer[1881] LOG:  checkpoint starting: immediate force wait
2022-08-03 11:59:52.862 CDT checkpointer[1881] LOG:  checkpoint complete: wrote 4 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.045 s, sync=0.038 s, total=0.188 s; sync files=3, longest=0.019 s, average=0.013 s; distance=3 kB, estimate=3 kB; lsn=0/24862508, redo lsn=0/248624D0
2022-08-03 11:59:53.213 CDT checkpointer[1881] LOG:  checkpoint starting: immediate force wait
2022-08-03 11:59:53.409 CDT checkpointer[1881] LOG:  checkpoint complete: wrote 4 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.030 s, sync=0.054 s, total=0.196 s; sync files=4, longest=0.029 s, average=0.014 s; distance=4042 kB, estimate=4042 kB; lsn=0/24C54D88, redo lsn=0/24C54D50
^CCancel request sent
2022-08-03 11:59:53.750 CDT checkpointer[1881] LOG:  checkpoint starting: immediate force wait
2022-08-03 11:59:53.930 CDT checkpointer[1881] LOG:  checkpoint complete: wrote 4 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.029 s, sync=0.027 s, total=0.181 s; sync files=4, longest=0.022 s, average=0.007 s; distance=4042 kB, estimate=4042 kB; lsn=0/250476D0, redo lsn=0/25047698
2022-08-03 11:59:54.270 CDT checkpointer[1881] LOG:  checkpoint starting: immediate force wait
^C2022-08-03 11:59:54.294 CDT client backend[1903] psql ERROR:  canceling statement due to user request
2022-08-03 11:59:54.294 CDT client backend[1903] psql STATEMENT:  DROP DATABASE a
Cancel request sent
ERROR:  canceling statement due to user request
2022-08-03 11:59:54.296 CDT client backend[1903] psql ERROR:  database "a" already exists
2022-08-03 11:59:54.296 CDT client backend[1903] psql STATEMENT:  CREATE DATABASE a TEMPLATE postgres STRATEGY wal_log
ERROR:  database "a" already exists
^C
pryzbyj@pryzbyj:~/src/postgres$ ^C
pryzbyj@pryzbyj:~/src/postgres$ ^C
pryzbyj@pryzbyj:~/src/postgres$ 2022-08-03 11:59:54.427 CDT checkpointer[1881] LOG:  checkpoint complete: wrote 4 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.024 s, sync=0.036 s, total=0.158 s; sync files=4, longest=0.027 s, average=0.009 s; distance=4042 kB, estimate=4042 kB; lsn=0/2543A108, redo lsn=0/2543A0A8
^C
pryzbyj@pryzbyj:~/src/postgres$ ^C
pryzbyj@pryzbyj:~/src/postgres$ ^C
pryzbyj@pryzbyj:~/src/postgres$ psql -h /tmp a -c ''                                                                                                                                                               2022-08-03 11:59:56.617 CDT client backend[1914] [unknown] PANIC:  could not open critical system index 2662