Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-12 Thread Michael Paquier
On Thu, Dec 09, 2021 at 05:42:56PM +0900, Masahiko Sawada wrote:
> Thank you for updating the patch. The patch looks good to me.

Done this way.  Please note that while testing this patch, I have
found a completely different issue.  I'll spawn a thread about that in
a minute..
--
Michael


signature.asc
Description: PGP signature


Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-09 Thread Masahiko Sawada
On Thu, Dec 9, 2021 at 4:02 PM Michael Paquier  wrote:
>
> On Wed, Dec 08, 2021 at 05:03:30PM +0900, Masahiko Sawada wrote:
> > Agreed. I've attached an updated patch that incorporated your review
> > comments. Please review it.
>
> That looks correct to me.  One thing that I have noticed while
> reviewing is that we don't check XactCompletionApplyFeedback() in
> xact_desc_commit(), which would happen if a transaction needs to do
> a remote_apply on a standby.  synchronous_commit is a user-settable
> parameter, so it seems to me that it could be useful for debugging?
>

Agreed.

Thank you for updating the patch. The patch looks good to me.

Regards,

-- 
Masahiko Sawada
EDB:  https://www.enterprisedb.com/




Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-08 Thread Michael Paquier
On Wed, Dec 08, 2021 at 05:03:30PM +0900, Masahiko Sawada wrote:
> Agreed. I've attached an updated patch that incorporated your review
> comments. Please review it.

That looks correct to me.  One thing that I have noticed while
reviewing is that we don't check XactCompletionApplyFeedback() in
xact_desc_commit(), which would happen if a transaction needs to do
a remote_apply on a standby.  synchronous_commit is a user-settable
parameter, so it seems to me that it could be useful for debugging?

That's not related to your patch, but while we are looking at the
area..
--
Michael
From c821c67698535ded147e8686c182d91462a16599 Mon Sep 17 00:00:00 2001
From: Michael Paquier 
Date: Thu, 9 Dec 2021 16:00:53 +0900
Subject: [PATCH v3] Make pg_waldump report replication origin ID, LSN, and
 timestamp.

Commit 7b8a899bdeb made pg_waldump report the detail of information
about PREPARE TRANSACTION record, like global transaction
identifier. However, replication origin LSN and timestamp were not
reporeted. These are helpful when diagnosing 2PC-related troubles on
the subsciber side.

This commit makes xact_desc_prepare() and xact_desc_abort() report
replication origin ID, LSN, and timestamp.
---
 src/backend/access/rmgrdesc/xactdesc.c | 32 ++
 1 file changed, 28 insertions(+), 4 deletions(-)

diff --git a/src/backend/access/rmgrdesc/xactdesc.c b/src/backend/access/rmgrdesc/xactdesc.c
index 4b0d10f073..fca03a00d9 100644
--- a/src/backend/access/rmgrdesc/xactdesc.c
+++ b/src/backend/access/rmgrdesc/xactdesc.c
@@ -16,6 +16,7 @@
 
 #include "access/transam.h"
 #include "access/xact.h"
+#include "replication/origin.h"
 #include "storage/sinval.h"
 #include "storage/standbydefs.h"
 #include "utils/timestamp.h"
@@ -299,6 +300,9 @@ xact_desc_commit(StringInfo buf, uint8 info, xl_xact_commit *xlrec, RepOriginId
 			   parsed.tsId,
 			   XactCompletionRelcacheInitFileInval(parsed.xinfo));
 
+	if (XactCompletionApplyFeedback(parsed.xinfo))
+		appendStringInfoString(buf, "; apply_feedback");
+
 	if (XactCompletionForceSyncCommit(parsed.xinfo))
 		appendStringInfoString(buf, "; sync");
 
@@ -312,7 +316,7 @@ xact_desc_commit(StringInfo buf, uint8 info, xl_xact_commit *xlrec, RepOriginId
 }
 
 static void
-xact_desc_abort(StringInfo buf, uint8 info, xl_xact_abort *xlrec)
+xact_desc_abort(StringInfo buf, uint8 info, xl_xact_abort *xlrec, RepOriginId origin_id)
 {
 	xl_xact_parsed_abort parsed;
 
@@ -326,10 +330,18 @@ xact_desc_abort(StringInfo buf, uint8 info, xl_xact_abort *xlrec)
 
 	xact_desc_relations(buf, "rels", parsed.nrels, parsed.xnodes);
 	xact_desc_subxacts(buf, parsed.nsubxacts, parsed.subxacts);
+
+	if (parsed.xinfo & XACT_XINFO_HAS_ORIGIN)
+	{
+		appendStringInfo(buf, "; origin: node %u, lsn %X/%X, at %s",
+		 origin_id,
+		 LSN_FORMAT_ARGS(parsed.origin_lsn),
+		 timestamptz_to_str(parsed.origin_timestamp));
+	}
 }
 
 static void
-xact_desc_prepare(StringInfo buf, uint8 info, xl_xact_prepare *xlrec)
+xact_desc_prepare(StringInfo buf, uint8 info, xl_xact_prepare *xlrec, RepOriginId origin_id)
 {
 	xl_xact_parsed_prepare parsed;
 
@@ -345,6 +357,16 @@ xact_desc_prepare(StringInfo buf, uint8 info, xl_xact_prepare *xlrec)
 
 	standby_desc_invalidations(buf, parsed.nmsgs, parsed.msgs, parsed.dbId,
 			   parsed.tsId, xlrec->initfileinval);
+
+	/*
+	 * Check if the replication origin has been set in this record in the
+	 * same way as PrepareRedoAdd().
+	 */
+	if (origin_id != InvalidRepOriginId)
+		appendStringInfo(buf, "; origin: node %u, lsn %X/%X, at %s",
+		 origin_id,
+		 LSN_FORMAT_ARGS(parsed.origin_lsn),
+		 timestamptz_to_str(parsed.origin_timestamp));
 }
 
 static void
@@ -375,13 +397,15 @@ xact_desc(StringInfo buf, XLogReaderState *record)
 	{
 		xl_xact_abort *xlrec = (xl_xact_abort *) rec;
 
-		xact_desc_abort(buf, XLogRecGetInfo(record), xlrec);
+		xact_desc_abort(buf, XLogRecGetInfo(record), xlrec,
+		XLogRecGetOrigin(record));
 	}
 	else if (info == XLOG_XACT_PREPARE)
 	{
 		xl_xact_prepare *xlrec = (xl_xact_prepare *) rec;
 
-		xact_desc_prepare(buf, XLogRecGetInfo(record), xlrec);
+		xact_desc_prepare(buf, XLogRecGetInfo(record), xlrec,
+		  XLogRecGetOrigin(record));
 	}
 	else if (info == XLOG_XACT_ASSIGNMENT)
 	{
-- 
2.34.1



signature.asc
Description: PGP signature


Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-08 Thread Masahiko Sawada
On Wed, Dec 8, 2021 at 4:31 PM Michael Paquier  wrote:
>
> On Mon, Dec 06, 2021 at 11:24:09PM +0900, Masahiko Sawada wrote:
> > On Mon, Dec 6, 2021 at 5:09 PM Michael Paquier  wrote:
> >> Shouldn't you check for parsed.origin_lsn instead?  The replication
> >> origin is stored there as far as I read EndPrepare().
> >
> > Also, looking at PrepareRedoAdd(), we check the replication origin id.
> > So I think that it'd be better to check origin_id for consistency.
>
> Okay, this consistency would make sense, then.  Perhaps some comments
> should be added to tell that?

Agreed. I've attached an updated patch that incorporated your review
comments. Please review it.

Regards,

-- 
Masahiko Sawada
EDB:  https://www.enterprisedb.com/


v2-0001-Make-pg_waldump-report-replication-origin-ID-LSN-.patch
Description: Binary data


Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-07 Thread Michael Paquier
On Mon, Dec 06, 2021 at 11:24:09PM +0900, Masahiko Sawada wrote:
> On Mon, Dec 6, 2021 at 5:09 PM Michael Paquier  wrote:
>> Shouldn't you check for parsed.origin_lsn instead?  The replication
>> origin is stored there as far as I read EndPrepare().
> 
> Also, looking at PrepareRedoAdd(), we check the replication origin id.
> So I think that it'd be better to check origin_id for consistency.

Okay, this consistency would make sense, then.  Perhaps some comments
should be added to tell that?

>> Commit records check after XACT_XINFO_HAS_ORIGIN, but
>> xact_desc_abort() may include this information for ROLLBACK PREPARED
>> transactions so we could use the same logic as xact_desc_commit() for
>> the abort case, no?
> 
> Good catch! I'll submit an updated patch.

Thanks!
--
Michael


signature.asc
Description: PGP signature


Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-06 Thread Masahiko Sawada
On Mon, Dec 6, 2021 at 11:24 PM Masahiko Sawada  wrote:
>
> On Mon, Dec 6, 2021 at 5:09 PM Michael Paquier  wrote:
> >
> > On Mon, Dec 06, 2021 at 04:35:07PM +0900, Masahiko Sawada wrote:
> > > I've attached a patch to add replication origin information to
> > > xact_desc_prepare().
> >
> > Yeah.
> >
> > +   if (origin_id != InvalidRepOriginId)
> > +   appendStringInfo(buf, "; origin: node %u, lsn %X/%X, at %s",
> > +origin_id,
> > +LSN_FORMAT_ARGS(parsed.origin_lsn),
> > +timestamptz_to_str(parsed.origin_timestamp));
> >
> > Shouldn't you check for parsed.origin_lsn instead?  The replication
> > origin is stored there as far as I read EndPrepare().
>
> Yeah, I was thinking check origin_lsn instead. That way, we don't show
> invalid origin_timestamp and origin_lsn even if origin_id is set. But
> as far as I read, the same is true for xact_desc_commit() (and
> xact_desc_rollback()). That is, since apply workers always its origin
> id and could do commit transactions that are not replicated from the
> publisher, it's possible that xact_desc_commit() reports like:
>
> rmgr: Transaction len (rec/tot):117/   117, tx:725, lsn:
> 0/014BE938, prev 0/014BE908, desc: COMMIT 2021-12-06 22:04:44.462200
> JST; inval msgs: catcache 55 catcache 54 catcache 64; origin: node 1,
> lsn 0/0, at 2000-01-01 09:00:00.00 JST

Hmm, is that okay in the first place? This happens since the apply
worker updates twophaesstate value of pg_subscription after setting
the origin id and before entering the apply loop. No changes in this
transaction will be replicated but an empty transaction that has
origin id and doesn't have origin lsn and time will be replicated.

Regards,

--
Masahiko Sawada
EDB:  https://www.enterprisedb.com/




Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-06 Thread Masahiko Sawada
On Mon, Dec 6, 2021 at 5:09 PM Michael Paquier  wrote:
>
> On Mon, Dec 06, 2021 at 04:35:07PM +0900, Masahiko Sawada wrote:
> > I've attached a patch to add replication origin information to
> > xact_desc_prepare().
>
> Yeah.
>
> +   if (origin_id != InvalidRepOriginId)
> +   appendStringInfo(buf, "; origin: node %u, lsn %X/%X, at %s",
> +origin_id,
> +LSN_FORMAT_ARGS(parsed.origin_lsn),
> +timestamptz_to_str(parsed.origin_timestamp));
>
> Shouldn't you check for parsed.origin_lsn instead?  The replication
> origin is stored there as far as I read EndPrepare().

Yeah, I was thinking check origin_lsn instead. That way, we don't show
invalid origin_timestamp and origin_lsn even if origin_id is set. But
as far as I read, the same is true for xact_desc_commit() (and
xact_desc_rollback()). That is, since apply workers always its origin
id and could do commit transactions that are not replicated from the
publisher, it's possible that xact_desc_commit() reports like:

rmgr: Transaction len (rec/tot):117/   117, tx:725, lsn:
0/014BE938, prev 0/014BE908, desc: COMMIT 2021-12-06 22:04:44.462200
JST; inval msgs: catcache 55 catcache 54 catcache 64; origin: node 1,
lsn 0/0, at 2000-01-01 09:00:00.00 JST

Also, looking at PrepareRedoAdd(), we check the replication origin id.
So I think that it'd be better to check origin_id for consistency.

>
> Commit records check after XACT_XINFO_HAS_ORIGIN, but
> xact_desc_abort() may include this information for ROLLBACK PREPARED
> transactions so we could use the same logic as xact_desc_commit() for
> the abort case, no?

Good catch! I'll submit an updated patch.

Regards,

-- 
Masahiko Sawada
EDB:  https://www.enterprisedb.com/




Re: Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-06 Thread Michael Paquier
On Mon, Dec 06, 2021 at 04:35:07PM +0900, Masahiko Sawada wrote:
> I've attached a patch to add replication origin information to
> xact_desc_prepare().

Yeah.

+   if (origin_id != InvalidRepOriginId)
+   appendStringInfo(buf, "; origin: node %u, lsn %X/%X, at %s",
+origin_id,
+LSN_FORMAT_ARGS(parsed.origin_lsn),
+timestamptz_to_str(parsed.origin_timestamp));

Shouldn't you check for parsed.origin_lsn instead?  The replication
origin is stored there as far as I read EndPrepare().

Commit records check after XACT_XINFO_HAS_ORIGIN, but
xact_desc_abort() may include this information for ROLLBACK PREPARED 
transactions so we could use the same logic as xact_desc_commit() for
the abort case, no?
--
Michael


signature.asc
Description: PGP signature


Make pg_waldump report replication origin ID, LSN, and timestamp.

2021-12-05 Thread Masahiko Sawada
Hi all,

I realized that pg_waldump doesn't show replication origin ID, LSN,
and timestamp of PREPARE TRANSACTION record. Commit 7b8a899bdeb
improved pg_waldump two years ago so that it reports the detail of
information of PREPARE TRANSACTION but ISTM that it overlooked showing
replication origin information. As far as I can see in the discussion
thread[1], there was no discussion on that. These are helpful when
diagnosing 2PC related issues on the subscriber side.

I've attached a patch to add replication origin information to
xact_desc_prepare().

Regards,

[1] 
https://www.postgresql.org/message-id/CAHGQGwEvhASad4JJnCv%3D0dW2TJypZgW_Vpb-oZik2a3utCqcrA%40mail.gmail.com

--
Masahiko Sawada
EDB:  https://www.enterprisedb.com/
From b37d5a8cd5b84eeb850bd7ddeb903024652f20d2 Mon Sep 17 00:00:00 2001
From: Masahiko Sawada 
Date: Mon, 6 Dec 2021 14:32:57 +0900
Subject: [PATCH] Make pg_waldump report replication origin ID, LSN, and
 timestamp.

Commit 7b8a899bdeb made pg_waldump report the detail of information
about PREPARE TRANSACTION record, like global transaction
identifier. However, replication origin LSN and timestamp were not
reporeted. These are helpful when diagnosing 2PC-related troubles on
the subsciber side.

This commit makes xact_desc_prepare() report replication origin ID,
LSN, and timestamp.
---
 src/backend/access/rmgrdesc/xactdesc.c | 12 ++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/src/backend/access/rmgrdesc/xactdesc.c b/src/backend/access/rmgrdesc/xactdesc.c
index 4b0d10f073..ea3649d822 100644
--- a/src/backend/access/rmgrdesc/xactdesc.c
+++ b/src/backend/access/rmgrdesc/xactdesc.c
@@ -16,6 +16,7 @@
 
 #include "access/transam.h"
 #include "access/xact.h"
+#include "replication/origin.h"
 #include "storage/sinval.h"
 #include "storage/standbydefs.h"
 #include "utils/timestamp.h"
@@ -329,7 +330,7 @@ xact_desc_abort(StringInfo buf, uint8 info, xl_xact_abort *xlrec)
 }
 
 static void
-xact_desc_prepare(StringInfo buf, uint8 info, xl_xact_prepare *xlrec)
+xact_desc_prepare(StringInfo buf, uint8 info, xl_xact_prepare *xlrec, RepOriginId origin_id)
 {
 	xl_xact_parsed_prepare parsed;
 
@@ -345,6 +346,12 @@ xact_desc_prepare(StringInfo buf, uint8 info, xl_xact_prepare *xlrec)
 
 	standby_desc_invalidations(buf, parsed.nmsgs, parsed.msgs, parsed.dbId,
 			   parsed.tsId, xlrec->initfileinval);
+
+	if (origin_id != InvalidRepOriginId)
+		appendStringInfo(buf, "; origin: node %u, lsn %X/%X, at %s",
+		 origin_id,
+		 LSN_FORMAT_ARGS(parsed.origin_lsn),
+		 timestamptz_to_str(parsed.origin_timestamp));
 }
 
 static void
@@ -381,7 +388,8 @@ xact_desc(StringInfo buf, XLogReaderState *record)
 	{
 		xl_xact_prepare *xlrec = (xl_xact_prepare *) rec;
 
-		xact_desc_prepare(buf, XLogRecGetInfo(record), xlrec);
+		xact_desc_prepare(buf, XLogRecGetInfo(record), xlrec,
+		  XLogRecGetOrigin(record));
 	}
 	else if (info == XLOG_XACT_ASSIGNMENT)
 	{
-- 
2.24.3 (Apple Git-128)