From: Noah Misch <noah@leadboat.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Michael Paquier <michael@paquier.xyz>
Cc: pgsql-hackers@postgresql.org
Subject: Re: XLogReadRecord() error in XlogReadTwoPhaseData()
Date: Wed, 17 Nov 2021 23:05:06 -0800
Message-ID: <20211118070506.GA1294133@rfd.leadboat.com> (raw)
In-Reply-To: <2782601.1637189230@sss.pgh.pa.us>
References: <20211107013157.GB790288@rfd.leadboat.com>
<YYiqxtEqhgb5gIWL@paquier.xyz>
<20211112012234.GA1020314@rfd.leadboat.com>
<2782601.1637189230@sss.pgh.pa.us>
On Wed, Nov 17, 2021 at 05:47:10PM -0500, Tom Lane wrote:
> Noah Misch <noah@leadboat.com> writes:
> > Each of the three failures happened on a sparc64 Debian+gcc machine. I had
> > tried ~8000 iterations on thorntail, another sparc64 Debian+gcc animal,
> > without reproducing this.
> # 'pgbench: error: client 0 script 1 aborted in command 4 query 0: ERROR: could not read two-phase state from WAL at 0/159EF88: unexpected pageaddr 0/0 in log segment 000000010000000000000001, offset 5890048
> [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tadarida&dt=2021-11-17%2013%3A01%3A24
Two others:
ERROR: could not read two-phase state from WAL at 0/16F1850: invalid record length at 0/16F1850: wanted 24, got 0
-- https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tadarida&dt=2021-11-12%2013%3A01%3A15
ERROR: could not read two-phase state from WAL at 0/1668020: incorrect resource manager data checksum in record at 0/1668020
-- https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-11-16%2015%3A00%3A52> I suppose "unexpected pageaddr 0/0" is most easily explained by supposing
> that XlogReadTwoPhaseData tried to read a WAL page that hadn't been
> written out yet. Have we got any synchronization around that?
If the WAL address isn't on disk, that error doesn't happen. Instead,
read_local_xlog_page() blocks waiting for the WAL to become available. It's
still possible that we make the WAL region exist, but it somehow doesn't
contain the right data until shortly later. FinishPreparedTransaction() takes
TwoPhaseStateLock and looks for an entry having gxact->valid. EndPrepare()
fills gxact->prepare_end_lsn, then calls MarkAsPrepared() to set gxact->valid
under TwoPhaseStateLock. All freelist (freeGXacts) interaction holds
TwoPhaseStateLock. I'm not seeing a gap in that synchronization.
I don't have a great theory, but here are candidates to examine next:
- Run with wal_debug=on to confirm logged write location matches read location.
- Run "PGDATA=contrib/amcheck/tmp_check/t_003_cic_2pc_CIC_2PC_test_data/pgdata
pg_waldump -s 0/01000000" at the end of the test.
- Dump WAL page binary image at the point of failure.
- Log which branches in XLogReadRecord() are taken.
What else might help?
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: noah@leadboat.com, tgl@sss.pgh.pa.us, michael@paquier.xyz
Subject: Re: XLogReadRecord() error in XlogReadTwoPhaseData()
In-Reply-To: <20211118070506.GA1294133@rfd.leadboat.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox