public inbox for [email protected]
help / color / mirror / Atom feed[PATCH 2/8] Make sure published XIDs are persistent
5+ messages / 4 participants
[nested] [flat]
* [PATCH 2/8] Make sure published XIDs are persistent
@ 2021-03-08 06:43 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 5+ messages in thread
From: Kyotaro Horiguchi @ 2021-03-08 06:43 UTC (permalink / raw)
pg_xact_status() premises that XIDs obtained by
pg_current_xact_id(_if_assigned)() are persistent beyond a crash. But
XIDs are not guaranteed to go beyond WAL buffers before commit and
thus XIDs may vanish if server crashes before commit. This patch
guarantees the XID shown by the functions to be flushed out to disk.
Copied from: https://www.postgresql.org/message-id/20210308.173242.463790587797836129.horikyota.ntt%40gmail.com
---
src/backend/access/transam/xact.c | 55 +++++++++++++++++++++++++------
src/backend/access/transam/xlog.c | 2 +-
src/backend/utils/adt/xid8funcs.c | 12 ++++++-
src/include/access/xact.h | 3 +-
4 files changed, 59 insertions(+), 13 deletions(-)
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 6395a9b240..38e978d238 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -201,7 +201,7 @@ typedef struct TransactionStateData
int prevSecContext; /* previous SecurityRestrictionContext */
bool prevXactReadOnly; /* entry-time xact r/o state */
bool startedInRecovery; /* did we start in recovery? */
- bool didLogXid; /* has xid been included in WAL record? */
+ XLogRecPtr minLSN; /* LSN needed to reach to record the xid */
int parallelModeLevel; /* Enter/ExitParallelMode counter */
bool chain; /* start a new block after this one */
bool assigned; /* assigned to top-level XID */
@@ -520,14 +520,46 @@ GetCurrentFullTransactionIdIfAny(void)
* MarkCurrentTransactionIdLoggedIfAny
*
* Remember that the current xid - if it is assigned - now has been wal logged.
+ *
+ * upto is the LSN up to which we need to flush WAL to ensure the current xid
+ * to be persistent. See EnsureCurrentTransactionIdLogged().
*/
void
-MarkCurrentTransactionIdLoggedIfAny(void)
+MarkCurrentTransactionIdLoggedIfAny(XLogRecPtr upto)
{
- if (FullTransactionIdIsValid(CurrentTransactionState->fullTransactionId))
- CurrentTransactionState->didLogXid = true;
+ if (FullTransactionIdIsValid(CurrentTransactionState->fullTransactionId) &&
+ XLogRecPtrIsInvalid(CurrentTransactionState->minLSN))
+ CurrentTransactionState->minLSN = upto;
}
+/*
+ * EnsureCurrentTransactionIdLogged
+ *
+ * Make sure that the current top XID is WAL-logged.
+ */
+void
+EnsureTopTransactionIdLogged(void)
+{
+ /*
+ * We need at least one WAL record for the current top transaction to be
+ * flushed out. Write one if we don't have one yet.
+ */
+ if (XLogRecPtrIsInvalid(TopTransactionStateData.minLSN))
+ {
+ xl_xact_assignment xlrec;
+
+ xlrec.xtop = XidFromFullTransactionId(XactTopFullTransactionId);
+ Assert(TransactionIdIsValid(xlrec.xtop));
+ xlrec.nsubxacts = 0;
+
+ XLogBeginInsert();
+ XLogRegisterData((char *) &xlrec, MinSizeOfXactAssignment);
+ TopTransactionStateData.minLSN =
+ XLogInsert(RM_XACT_ID, XLOG_XACT_ASSIGNMENT);
+ }
+
+ XLogFlush(TopTransactionStateData.minLSN);
+}
/*
* GetStableLatestTransactionId
@@ -616,14 +648,14 @@ AssignTransactionId(TransactionState s)
* When wal_level=logical, guarantee that a subtransaction's xid can only
* be seen in the WAL stream if its toplevel xid has been logged before.
* If necessary we log an xact_assignment record with fewer than
- * PGPROC_MAX_CACHED_SUBXIDS. Note that it is fine if didLogXid isn't set
+ * PGPROC_MAX_CACHED_SUBXIDS. Note that it is fine if minLSN isn't set
* for a transaction even though it appears in a WAL record, we just might
* superfluously log something. That can happen when an xid is included
* somewhere inside a wal record, but not in XLogRecord->xl_xid, like in
* xl_standby_locks.
*/
if (isSubXact && XLogLogicalInfoActive() &&
- !TopTransactionStateData.didLogXid)
+ XLogRecPtrIsInvalid(TopTransactionStateData.minLSN))
log_unknown_top = true;
/*
@@ -693,6 +725,7 @@ AssignTransactionId(TransactionState s)
log_unknown_top)
{
xl_xact_assignment xlrec;
+ XLogRecPtr endptr;
/*
* xtop is always set by now because we recurse up transaction
@@ -707,11 +740,13 @@ AssignTransactionId(TransactionState s)
XLogRegisterData((char *) unreportedXids,
nUnreportedXids * sizeof(TransactionId));
- (void) XLogInsert(RM_XACT_ID, XLOG_XACT_ASSIGNMENT);
+ endptr = XLogInsert(RM_XACT_ID, XLOG_XACT_ASSIGNMENT);
nUnreportedXids = 0;
- /* mark top, not current xact as having been logged */
- TopTransactionStateData.didLogXid = true;
+
+ /* set minLSN of top, not of current xact if not yet */
+ if (XLogRecPtrIsInvalid(TopTransactionStateData.minLSN))
+ TopTransactionStateData.minLSN = endptr;
}
}
}
@@ -2022,7 +2057,7 @@ StartTransaction(void)
* initialize reported xid accounting
*/
nUnreportedXids = 0;
- s->didLogXid = false;
+ s->minLSN = InvalidXLogRecPtr;
/*
* must initialize resource-management stuff first
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index e04250f4e9..e3128564e1 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -1161,7 +1161,7 @@ XLogInsertRecord(XLogRecData *rdata,
*/
WALInsertLockRelease();
- MarkCurrentTransactionIdLoggedIfAny();
+ MarkCurrentTransactionIdLoggedIfAny(EndPos);
END_CRIT_SECTION();
diff --git a/src/backend/utils/adt/xid8funcs.c b/src/backend/utils/adt/xid8funcs.c
index cc2b4ac797..992482f8c8 100644
--- a/src/backend/utils/adt/xid8funcs.c
+++ b/src/backend/utils/adt/xid8funcs.c
@@ -357,6 +357,8 @@ bad_format:
Datum
pg_current_xact_id(PG_FUNCTION_ARGS)
{
+ FullTransactionId xid;
+
/*
* Must prevent during recovery because if an xid is not assigned we try
* to assign one, which would fail. Programs already rely on this function
@@ -365,7 +367,12 @@ pg_current_xact_id(PG_FUNCTION_ARGS)
*/
PreventCommandDuringRecovery("pg_current_xact_id()");
- PG_RETURN_FULLTRANSACTIONID(GetTopFullTransactionId());
+ xid = GetTopFullTransactionId();
+
+ /* the XID is going to be published, make sure it is psersistent */
+ EnsureTopTransactionIdLogged();
+
+ PG_RETURN_FULLTRANSACTIONID(xid);
}
/*
@@ -380,6 +387,9 @@ pg_current_xact_id_if_assigned(PG_FUNCTION_ARGS)
if (!FullTransactionIdIsValid(topfxid))
PG_RETURN_NULL();
+ /* the XID is going to be published, make sure it is psersistent */
+ EnsureTopTransactionIdLogged();
+
PG_RETURN_FULLTRANSACTIONID(topfxid);
}
diff --git a/src/include/access/xact.h b/src/include/access/xact.h
index 34cfaf542c..a61e4d6da5 100644
--- a/src/include/access/xact.h
+++ b/src/include/access/xact.h
@@ -386,7 +386,8 @@ extern FullTransactionId GetTopFullTransactionId(void);
extern FullTransactionId GetTopFullTransactionIdIfAny(void);
extern FullTransactionId GetCurrentFullTransactionId(void);
extern FullTransactionId GetCurrentFullTransactionIdIfAny(void);
-extern void MarkCurrentTransactionIdLoggedIfAny(void);
+extern void MarkCurrentTransactionIdLoggedIfAny(XLogRecPtr upto);
+extern void EnsureTopTransactionIdLogged(void);
extern bool SubTransactionIsActive(SubTransactionId subxid);
extern CommandId GetCurrentCommandId(bool used);
extern void SetParallelStartTimestamps(TimestampTz xact_ts, TimestampTz stmt_ts);
--
2.17.0
--f0KYrhQ4vYSV2aJu
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
filename="0003-Allow-alternate-compression-methods-for-wal_compress.patch"
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg16: invalid page/page verification failed
@ 2023-10-06 00:20 Michael Paquier <[email protected]>
2023-10-06 15:00 ` Re: pg16: invalid page/page verification failed Justin Pryzby <[email protected]>
2023-10-06 15:47 ` Re: pg16: invalid page/page verification failed Andres Freund <[email protected]>
0 siblings, 2 replies; 5+ messages in thread
From: Michael Paquier @ 2023-10-06 00:20 UTC (permalink / raw)
To: Justin Pryzby <[email protected]>; +Cc: [email protected]; Andres Freund <[email protected]>
On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote:
> This table is what it sounds like: a partition into which CSV logs are
> COPY'ed. It would've been created around 8am. There's no special
> params set for the table nor for autovacuum.
This may be an important bit of information. 31966b151e6a is new as
of Postgres 16, has changed the way relations are extended and COPY
was one area touched. I am adding Andres in CC.
--
Michael
Attachments:
[application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
download
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg16: invalid page/page verification failed
2023-10-06 00:20 Re: pg16: invalid page/page verification failed Michael Paquier <[email protected]>
@ 2023-10-06 15:00 ` Justin Pryzby <[email protected]>
1 sibling, 0 replies; 5+ messages in thread
From: Justin Pryzby @ 2023-10-06 15:00 UTC (permalink / raw)
To: Michael Paquier <[email protected]>; +Cc: [email protected]; Andres Freund <[email protected]>
On Fri, Oct 06, 2023 at 09:20:05AM +0900, Michael Paquier wrote:
> On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote:
> > This table is what it sounds like: a partition into which CSV logs are
> > COPY'ed. It would've been created around 8am. There's no special
> > params set for the table nor for autovacuum.
>
> This may be an important bit of information. 31966b151e6a is new as
> of Postgres 16, has changed the way relations are extended and COPY
> was one area touched. I am adding Andres in CC.
Also, I realized that someone kicked off a process just after 9am which
would've done a lot of INSERT ON CONFLICT DO UPDATE, VACUUM FULL, and
VACUUM. Which consumed and dirtied buffers about 100x faster than normal.
log_time | 2023-10-05 10:00:55.794-05
pid | 31754
left | duration: 51281.001 ms statement: VACUUM (FULL,FREEZE) othertable...
log_time | 2023-10-05 10:01:01.784-05
backend_type | checkpointer
left | checkpoint starting: time
log_time | 2023-10-05 10:01:02.935-05
pid | 10023
left | page verification failed, calculated checksum 5074 but expected 5050
context | COPY postgres_log, line 947
left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095600.csv' WITH csv
log_time | 2023-10-05 10:01:02.935-05
pid | 10023
left | invalid page in block 119 of relation base/16409/801594131
context | COPY postgres_log, line 947
left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095600.csv' WITH csv
log_time | 2023-10-05 10:01:11.636-05
pid | 31754
left | duration: 15838.374 ms statement: VACUUM (FREEZE) othertable...
I meant to point out that the issue is on the last block.
postgres=# SELECT pg_relation_size('"BROKEN_postgres_log_2023_10_05_0900"')/8192;
?column? | 120
It sounds like there may be an issue locking (pinning?) a page, or
rather not locking it, or releasing the lock too early.
--
Justin
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg16: invalid page/page verification failed
2023-10-06 00:20 Re: pg16: invalid page/page verification failed Michael Paquier <[email protected]>
@ 2023-10-06 15:47 ` Andres Freund <[email protected]>
2023-10-06 21:36 ` Re: pg16: invalid page/page verification failed Justin Pryzby <[email protected]>
1 sibling, 1 reply; 5+ messages in thread
From: Andres Freund @ 2023-10-06 15:47 UTC (permalink / raw)
To: Michael Paquier <[email protected]>; +Cc: Justin Pryzby <[email protected]>; [email protected]
Hi,
On 2023-10-06 09:20:05 +0900, Michael Paquier wrote:
> On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote:
> > This table is what it sounds like: a partition into which CSV logs are
> > COPY'ed. It would've been created around 8am. There's no special
> > params set for the table nor for autovacuum.
>
> This may be an important bit of information. 31966b151e6a is new as
> of Postgres 16, has changed the way relations are extended and COPY
> was one area touched. I am adding Andres in CC.
Hm, is there any chance the COPY targets more than one partition? If so, this
sounds like it might be the issue described here
https://postgr.es/m/20230925213746.fwqauhhifjgefyzk%40alap3.anarazel.de
I think at this stage the easiest fix might be just to copy the approach of
calling ReleaseBulkInsertStatePin(), even though I think that's
architecturally wrong.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg16: invalid page/page verification failed
2023-10-06 00:20 Re: pg16: invalid page/page verification failed Michael Paquier <[email protected]>
2023-10-06 15:47 ` Re: pg16: invalid page/page verification failed Andres Freund <[email protected]>
@ 2023-10-06 21:36 ` Justin Pryzby <[email protected]>
0 siblings, 0 replies; 5+ messages in thread
From: Justin Pryzby @ 2023-10-06 21:36 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: Michael Paquier <[email protected]>; [email protected]
On Fri, Oct 06, 2023 at 08:47:39AM -0700, Andres Freund wrote:
> Hi,
>
> On 2023-10-06 09:20:05 +0900, Michael Paquier wrote:
> > On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote:
> > > This table is what it sounds like: a partition into which CSV logs are
> > > COPY'ed. It would've been created around 8am. There's no special
> > > params set for the table nor for autovacuum.
> >
> > This may be an important bit of information. 31966b151e6a is new as
> > of Postgres 16, has changed the way relations are extended and COPY
> > was one area touched. I am adding Andres in CC.
>
> Hm, is there any chance the COPY targets more than one partition? If so, this
> sounds like it might be the issue described here
> https://postgr.es/m/20230925213746.fwqauhhifjgefyzk%40alap3.anarazel.de
The first error was from:
log_time | 2023-10-05 09:57:01.939-05
left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095200.csv' WITH csv
Unfortunately, I no longer have the CSV files which caused errors.
After I moved the broken table out of the way and created a new
partition, they would've been imported successfully, and then removed.
Also, it's sad, but the original 2023_10_05_0900 partition I created was
itself rotated out of existence a few hours ago (I still have the most
interesting lines, though).
I've seen that it's possible for a CSV to include some data that ideally
would've gone into the "next" CSV: 2023-01-01_180000.csv might include a line
of data after 6pm. For example, with log_rotation_age=2min,
postgresql-2023-10-06_120800.csv had a row after 12:10:
2023-10-06 12:10:00.101 CDT,"pryzbyj","pryzbyj",5581,"[local]",65203f66.15cd,2,...
But I'm not sure how that can explain this issue, because this was
095600.csv, and not 095800.csv. My script knows to create the "next"
partition, to handle the case that the file includes some data that
should've gone to the next logfile. I'm handling that case with the
anticipation that there might be a few tenths of a second or even a few
seconds of logs in the wrong file - typically 0 lines and sometimes 1
line. I don't know if it's even possible to have multiple lines in the
"wrong" file. In any case, I'm not not expecting log rotation to be 2
minutes behind.
Also, not only was the data in the CSV earlier than 10am, but the error
*itself* was also earlier. The error importing the CSV was at 9:57, so
the CSV couldn't have had data after 10:00. Not that it matters, but my
script doesn't import the most recent logfile, and also avoids importing
files written within the last minute.
I don't see how a CSV with a 2 minute interval of data beginning at 9:56
could straddle hourly partitions.
log_time | 2023-10-05 09:57:01.939-05
left | invalid page in block 119 of relation base/16409/801594131
left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095200.csv' WITH csv
log_time | 2023-10-05 09:57:01.939-05
left | page verification failed, calculated checksum 5074 but expected 50
left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095200.csv' WITH csv
--
Justin
^ permalink raw reply [nested|flat] 5+ messages in thread
end of thread, other threads:[~2023-10-06 21:36 UTC | newest]
Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-03-08 06:43 [PATCH 2/8] Make sure published XIDs are persistent Kyotaro Horiguchi <[email protected]>
2023-10-06 00:20 Re: pg16: invalid page/page verification failed Michael Paquier <[email protected]>
2023-10-06 15:00 ` Re: pg16: invalid page/page verification failed Justin Pryzby <[email protected]>
2023-10-06 15:47 ` Re: pg16: invalid page/page verification failed Andres Freund <[email protected]>
2023-10-06 21:36 ` Re: pg16: invalid page/page verification failed Justin Pryzby <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox