Diagnostic comment in LogicalIncreaseXminForSlot

Started by Ashutosh Bapatover 4 years ago22 messages
#1Ashutosh Bapat
ashutosh.bapat.oss@gmail.com
1 attachment(s)

Hi
LogicalIncreaseRestartDecodingForSlot() has a debug log to report a
new restart_lsn. But the corresponding function for catalog_xmin.
Here's a patch to add the same.

--
Best Wishes,
Ashutosh Bapat

Attachments:

0001-Report-new-catalog_xmin-candidate-in-LogicalIncrease.patchtext/x-patch; charset=US-ASCII; name=0001-Report-new-catalog_xmin-candidate-in-LogicalIncrease.patchDownload
From 5d211016367fe352871647225ead64a2215c3184 Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <ashutosh.bapat@2ndquadrant.com>
Date: Thu, 13 May 2021 13:40:33 +0530
Subject: [PATCH 1/2] Report new catalog_xmin candidate in
 LogicalIncreaseXminForSlot()

Similar to LogicalIncreaseRestartDecodingForSlot() add a debug message
to LogicalIncreaseXminForSlot() reporting a new catalog_xmin candidate.

We should submit this to the community.

BDR-723
---
 src/backend/replication/logical/logical.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/src/backend/replication/logical/logical.c b/src/backend/replication/logical/logical.c
index a43df58537..59fd16d1ef 100644
--- a/src/backend/replication/logical/logical.c
+++ b/src/backend/replication/logical/logical.c
@@ -1562,6 +1562,8 @@ LogicalIncreaseXminForSlot(XLogRecPtr current_lsn, TransactionId xmin)
 	{
 		slot->candidate_catalog_xmin = xmin;
 		slot->candidate_xmin_lsn = current_lsn;
+		elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+			 (uint32) (current_lsn >> 32), (uint32) current_lsn);
 	}
 	SpinLockRelease(&slot->mutex);
 
-- 
2.25.1

#2Amit Kapila
amit.kapila16@gmail.com
In reply to: Ashutosh Bapat (#1)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Thu, May 20, 2021 at 5:43 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:

Hi
LogicalIncreaseRestartDecodingForSlot() has a debug log to report a
new restart_lsn. But the corresponding function for catalog_xmin.
Here's a patch to add the same.

I think this can be useful. One minor comment:
+ elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+ (uint32) (current_lsn >> 32), (uint32) current_lsn);

Isn't it better to use LSN_FORMAT_ARGS for current_lsn? Also, there
doesn't seem to be any urgency for adding this, so you can register it
for the next CF so that we can add this when the branch opens for
PG-15.

--
With Regards,
Amit Kapila.

#3Ashutosh Bapat
ashutosh.bapat@enterprisedb.com
In reply to: Amit Kapila (#2)
1 attachment(s)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Fri, May 21, 2021 at 11:26 AM Amit Kapila <amit.kapila16@gmail.com>
wrote:

On Thu, May 20, 2021 at 5:43 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:

Hi
LogicalIncreaseRestartDecodingForSlot() has a debug log to report a
new restart_lsn. But the corresponding function for catalog_xmin.
Here's a patch to add the same.

I think this can be useful. One minor comment:
+ elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+ (uint32) (current_lsn >> 32), (uint32) current_lsn);

Isn't it better to use LSN_FORMAT_ARGS for current_lsn?

Thanks for reminding me about that. :).

Attached revised patch.

Also, there
doesn't seem to be any urgency for adding this, so you can register it
for the next CF so that we can add this when the branch opens for
PG-15.

It's there in CF. I am fine with PG-15. It will be good to patch the
back-branches to have this extra diagnostic information available.

--
Best Wishes,
Ashutosh

Attachments:

0001-Report-new-catalog_xmin-candidate-in-LogicalIncrease.patchtext/x-patch; charset=US-ASCII; name=0001-Report-new-catalog_xmin-candidate-in-LogicalIncrease.patchDownload
From edc05ab21445e859ba6f80bf2c97563c94a1e66b Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <ashutosh.bapat@2ndquadrant.com>
Date: Thu, 13 May 2021 13:40:33 +0530
Subject: [PATCH] Report new catalog_xmin candidate in
 LogicalIncreaseXminForSlot()

Similar to LogicalIncreaseRestartDecodingForSlot() add a debug message
to LogicalIncreaseXminForSlot() reporting a new catalog_xmin candidate.

We should submit this to the community.

BDR-723
---
 src/backend/replication/logical/logical.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/src/backend/replication/logical/logical.c b/src/backend/replication/logical/logical.c
index ffc6160e9f..a776c54c01 100644
--- a/src/backend/replication/logical/logical.c
+++ b/src/backend/replication/logical/logical.c
@@ -1573,6 +1573,8 @@ LogicalIncreaseXminForSlot(XLogRecPtr current_lsn, TransactionId xmin)
 	{
 		slot->candidate_catalog_xmin = xmin;
 		slot->candidate_xmin_lsn = current_lsn;
+		elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+			 LSN_FORMAT_ARGS(current_lsn));
 	}
 	SpinLockRelease(&slot->mutex);
 
-- 
2.25.1

#4Masahiko Sawada
sawada.mshk@gmail.com
In reply to: Ashutosh Bapat (#3)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Fri, May 21, 2021 at 6:00 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

On Fri, May 21, 2021 at 11:26 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Thu, May 20, 2021 at 5:43 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:

Hi
LogicalIncreaseRestartDecodingForSlot() has a debug log to report a
new restart_lsn. But the corresponding function for catalog_xmin.
Here's a patch to add the same.

I think this can be useful. One minor comment:
+ elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+ (uint32) (current_lsn >> 32), (uint32) current_lsn);

Isn't it better to use LSN_FORMAT_ARGS for current_lsn?

Thanks for reminding me about that. :).

Attached revised patch.

Also, there
doesn't seem to be any urgency for adding this, so you can register it
for the next CF so that we can add this when the branch opens for
PG-15.

It's there in CF. I am fine with PG-15. It will be good to patch the back-branches to have this extra diagnostic information available.

The patch looks to me.

Regards,

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

#5Amit Kapila
amit.kapila16@gmail.com
In reply to: Masahiko Sawada (#4)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Mon, Jul 5, 2021 at 12:54 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

On Fri, May 21, 2021 at 6:00 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

On Fri, May 21, 2021 at 11:26 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Thu, May 20, 2021 at 5:43 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:

Hi
LogicalIncreaseRestartDecodingForSlot() has a debug log to report a
new restart_lsn. But the corresponding function for catalog_xmin.
Here's a patch to add the same.

I think this can be useful. One minor comment:
+ elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+ (uint32) (current_lsn >> 32), (uint32) current_lsn);

Isn't it better to use LSN_FORMAT_ARGS for current_lsn?

Thanks for reminding me about that. :).

Attached revised patch.

Also, there
doesn't seem to be any urgency for adding this, so you can register it
for the next CF so that we can add this when the branch opens for
PG-15.

It's there in CF. I am fine with PG-15. It will be good to patch the back-branches to have this extra diagnostic information available.

The patch looks to me.

Do you or others have any opinion on whether this should be
back-patched? I personally prefer it to be a HEAD-only patch.

--
With Regards,
Amit Kapila.

#6Daniel Gustafsson
daniel@yesql.se
In reply to: Amit Kapila (#5)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On 8 Jul 2021, at 12:56, Amit Kapila <amit.kapila16@gmail.com> wrote:

Do you or others have any opinion on whether this should be
back-patched? I personally prefer it to be a HEAD-only patch.

+1 for only applying this to HEAD. The restart_lsn debug elog has been there
since 2014 so there doesn’t seem to be any immediate rush.

--
Daniel Gustafsson https://vmware.com/

#7Masahiko Sawada
sawada.mshk@gmail.com
In reply to: Daniel Gustafsson (#6)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Thu, Jul 8, 2021 at 8:14 PM Daniel Gustafsson <daniel@yesql.se> wrote:

On 8 Jul 2021, at 12:56, Amit Kapila <amit.kapila16@gmail.com> wrote:

Do you or others have any opinion on whether this should be
back-patched? I personally prefer it to be a HEAD-only patch.

+1 for only applying this to HEAD. The restart_lsn debug elog has been there
since 2014 so there doesn’t seem to be any immediate rush.

+1

Regards,

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

#8Amit Kapila
amit.kapila16@gmail.com
In reply to: Masahiko Sawada (#4)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Mon, Jul 5, 2021 at 12:54 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

On Fri, May 21, 2021 at 6:00 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

It's there in CF. I am fine with PG-15. It will be good to patch the back-branches to have this extra diagnostic information available.

The patch looks to me.

{
  slot->candidate_catalog_xmin = xmin;
  slot->candidate_xmin_lsn = current_lsn;
+ elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+ LSN_FORMAT_ARGS(current_lsn));
  }
  SpinLockRelease(&slot->mutex);

Today, again looking at this patch, I don't think doing elog inside
spinlock is a good idea. We can either release spinlock before it or
use some variable to remember that we need to write such an elog and
do it after releasing the lock. What do you think? I have noticed that
a nearby function LogicalIncreaseRestartDecodingForSlot() logs similar
information after releasing spinlock, so it is better to follow the
same here as well.

--
With Regards,
Amit Kapila.

#9Ashutosh Bapat
ashutosh.bapat@enterprisedb.com
In reply to: Amit Kapila (#8)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Mon, Jul 12, 2021 at 8:39 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Mon, Jul 5, 2021 at 12:54 PM Masahiko Sawada <sawada.mshk@gmail.com>
wrote:

On Fri, May 21, 2021 at 6:00 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

It's there in CF. I am fine with PG-15. It will be good to patch the

back-branches to have this extra diagnostic information available.

The patch looks to me.

{
slot->candidate_catalog_xmin = xmin;
slot->candidate_xmin_lsn = current_lsn;
+ elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+ LSN_FORMAT_ARGS(current_lsn));
}
SpinLockRelease(&slot->mutex);

Today, again looking at this patch, I don't think doing elog inside
spinlock is a good idea. We can either release spinlock before it or
use some variable to remember that we need to write such an elog and
do it after releasing the lock. What do you think?

The elog will be effective only under DEBUG1, otherwise it will be almost a
NOOP. I am wondering whether it's worth adding a bool assignment and move
the elog out only for DEBUG1. Anyway, will defer it to you.

I have noticed that
a nearby function LogicalIncreaseRestartDecodingForSlot() logs similar
information after releasing spinlock, so it is better to follow the
same here as well.

Now that you mention it, the code their looks rather suspicious :)
We acquire the spinlock at the beginning of the function but do not release
it if (restart_lsn <= slot->data.restart_lsn) or if (current_lsn <=
slot->data.confirmed_flush). I might be missing something there. But it
looks unrelated.

--
--
Best Wishes,
Ashutosh

#10Amit Kapila
amit.kapila16@gmail.com
In reply to: Ashutosh Bapat (#9)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Mon, Jul 12, 2021 at 5:28 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

On Mon, Jul 12, 2021 at 8:39 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

I have noticed that
a nearby function LogicalIncreaseRestartDecodingForSlot() logs similar
information after releasing spinlock, so it is better to follow the
same here as well.

Now that you mention it, the code their looks rather suspicious :)
We acquire the spinlock at the beginning of the function but do not release it if (restart_lsn <= slot->data.restart_lsn) or if (current_lsn <= slot->data.confirmed_flush).

Note that we end else if with (current_lsn <=
slot->data.confirmed_flush) and after that there is a new if. We
release lock in both the if/else conditions, so the code is fine as it
is.

--
With Regards,
Amit Kapila.

#11Ashutosh Bapat
ashutosh.bapat@enterprisedb.com
In reply to: Amit Kapila (#10)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Mon, Jul 12, 2021 at 6:23 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Mon, Jul 12, 2021 at 5:28 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

On Mon, Jul 12, 2021 at 8:39 AM Amit Kapila <amit.kapila16@gmail.com>

wrote:

I have noticed that
a nearby function LogicalIncreaseRestartDecodingForSlot() logs similar
information after releasing spinlock, so it is better to follow the
same here as well.

Now that you mention it, the code their looks rather suspicious :)
We acquire the spinlock at the beginning of the function but do not

release it if (restart_lsn <= slot->data.restart_lsn) or if (current_lsn <=
slot->data.confirmed_flush).

Note that we end else if with (current_lsn <=
slot->data.confirmed_flush) and after that there is a new if. We
release lock in both the if/else conditions, so the code is fine as it
is.

Ah! I overlooked the closing else if (). Sorry for the noise.

--
Best Wishes,
Ashutosh

#12Amit Kapila
amit.kapila16@gmail.com
In reply to: Ashutosh Bapat (#9)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Mon, Jul 12, 2021 at 5:28 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

On Mon, Jul 12, 2021 at 8:39 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Mon, Jul 5, 2021 at 12:54 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

On Fri, May 21, 2021 at 6:00 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

It's there in CF. I am fine with PG-15. It will be good to patch the back-branches to have this extra diagnostic information available.

The patch looks to me.

{
slot->candidate_catalog_xmin = xmin;
slot->candidate_xmin_lsn = current_lsn;
+ elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+ LSN_FORMAT_ARGS(current_lsn));
}
SpinLockRelease(&slot->mutex);

Today, again looking at this patch, I don't think doing elog inside
spinlock is a good idea. We can either release spinlock before it or
use some variable to remember that we need to write such an elog and
do it after releasing the lock. What do you think?

The elog will be effective only under DEBUG1, otherwise it will be almost a NOOP. I am wondering whether it's worth adding a bool assignment and move the elog out only for DEBUG1.

If you don't like adding another variable then probably we can release
spinlock in each of if .. else loop. As mentioned previously, it
doesn't seem a good idea to use elog inside spinlock, so we either
need to find some way to avoid that or probably will drop this patch.
Do let me know what you or others prefer here?

--
With Regards,
Amit Kapila.

#13Andres Freund
andres@anarazel.de
In reply to: Ashutosh Bapat (#9)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

Hi,

On 2021-07-12 17:28:15 +0530, Ashutosh Bapat wrote:

On Mon, Jul 12, 2021 at 8:39 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Mon, Jul 5, 2021 at 12:54 PM Masahiko Sawada <sawada.mshk@gmail.com>
Today, again looking at this patch, I don't think doing elog inside
spinlock is a good idea. We can either release spinlock before it or
use some variable to remember that we need to write such an elog and
do it after releasing the lock. What do you think?

The elog will be effective only under DEBUG1, otherwise it will be almost a
NOOP. I am wondering whether it's worth adding a bool assignment and move
the elog out only for DEBUG1. Anyway, will defer it to you.

It's *definitely* not ok to do an elog() while holding a spinlock. Consider
what happens if the elog tries to format the message and runs out of
memory. Or if elog detects the stack depth is too deep. An ERROR would be
thrown, and we'd loose track of the held spinlock.

Greetings,

Andres Freund

#14Ashutosh Bapat
ashutosh.bapat@enterprisedb.com
In reply to: Andres Freund (#13)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Sat, Aug 7, 2021 at 11:40 AM Andres Freund <andres@anarazel.de> wrote:

Hi,

On 2021-07-12 17:28:15 +0530, Ashutosh Bapat wrote:

On Mon, Jul 12, 2021 at 8:39 AM Amit Kapila <amit.kapila16@gmail.com>

wrote:

On Mon, Jul 5, 2021 at 12:54 PM Masahiko Sawada <sawada.mshk@gmail.com

Today, again looking at this patch, I don't think doing elog inside
spinlock is a good idea. We can either release spinlock before it or
use some variable to remember that we need to write such an elog and
do it after releasing the lock. What do you think?

The elog will be effective only under DEBUG1, otherwise it will be

almost a

NOOP. I am wondering whether it's worth adding a bool assignment and move
the elog out only for DEBUG1. Anyway, will defer it to you.

It's *definitely* not ok to do an elog() while holding a spinlock. Consider
what happens if the elog tries to format the message and runs out of
memory. Or if elog detects the stack depth is too deep. An ERROR would be
thrown, and we'd loose track of the held spinlock.

Thanks for the clarification.

Amit,
I will provide the patch changed accordingly.

--
Best Wishes,
Ashutosh

#15Ashutosh Bapat
ashutosh.bapat@enterprisedb.com
In reply to: Ashutosh Bapat (#14)
1 attachment(s)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

Hi Amit and Andres,
Here's updated patch

On Mon, Aug 9, 2021 at 11:14 AM Ashutosh Bapat <
ashutosh.bapat@enterprisedb.com> wrote:

On Sat, Aug 7, 2021 at 11:40 AM Andres Freund <andres@anarazel.de> wrote:

Hi,

On 2021-07-12 17:28:15 +0530, Ashutosh Bapat wrote:

On Mon, Jul 12, 2021 at 8:39 AM Amit Kapila <amit.kapila16@gmail.com>

wrote:

On Mon, Jul 5, 2021 at 12:54 PM Masahiko Sawada <

sawada.mshk@gmail.com>

Today, again looking at this patch, I don't think doing elog inside
spinlock is a good idea. We can either release spinlock before it or
use some variable to remember that we need to write such an elog and
do it after releasing the lock. What do you think?

The elog will be effective only under DEBUG1, otherwise it will be

almost a

NOOP. I am wondering whether it's worth adding a bool assignment and

move

the elog out only for DEBUG1. Anyway, will defer it to you.

It's *definitely* not ok to do an elog() while holding a spinlock.
Consider
what happens if the elog tries to format the message and runs out of
memory. Or if elog detects the stack depth is too deep. An ERROR would be
thrown, and we'd loose track of the held spinlock.

Thanks for the clarification.

Amit,
I will provide the patch changed accordingly.

--
Best Wishes,
Ashutosh

--
--
Best Wishes,
Ashutosh

Attachments:

0001-Report-new-catalog_xmin-candidate-in-LogicalIncrease.patchtext/x-patch; charset=US-ASCII; name=0001-Report-new-catalog_xmin-candidate-in-LogicalIncrease.patchDownload
From 0a2f2c1f530d72219d9db7bd1ff77c1ae8c4ffe4 Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <ashutosh.bapat@2ndquadrant.com>
Date: Thu, 13 May 2021 13:40:33 +0530
Subject: [PATCH] Report new catalog_xmin candidate in
 LogicalIncreaseXminForSlot()

Similar to LogicalIncreaseRestartDecodingForSlot() add a debug message
to LogicalIncreaseXminForSlot() reporting a new catalog_xmin candidate.
---
 src/backend/replication/logical/logical.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/src/backend/replication/logical/logical.c b/src/backend/replication/logical/logical.c
index 64b8280c13..6c8c387e73 100644
--- a/src/backend/replication/logical/logical.c
+++ b/src/backend/replication/logical/logical.c
@@ -1565,6 +1565,7 @@ LogicalIncreaseXminForSlot(XLogRecPtr current_lsn, TransactionId xmin)
 {
 	bool		updated_xmin = false;
 	ReplicationSlot *slot;
+	bool		got_new_xmin = false;
 
 	slot = MyReplicationSlot;
 
@@ -1602,12 +1603,22 @@ LogicalIncreaseXminForSlot(XLogRecPtr current_lsn, TransactionId xmin)
 	{
 		slot->candidate_catalog_xmin = xmin;
 		slot->candidate_xmin_lsn = current_lsn;
+
+		/*
+		 * Add a line about new xmin in server logs at an appropriate log level
+		 * after releasing the spinlock.
+		 */
+		got_new_xmin = true;
 	}
 	SpinLockRelease(&slot->mutex);
 
 	/* candidate already valid with the current flush position, apply */
 	if (updated_xmin)
 		LogicalConfirmReceivedLocation(slot->data.confirmed_flush);
+
+	if (got_new_xmin)
+		elog(DEBUG1, "got new catalog_xmin %u at %X/%X", xmin,
+			 LSN_FORMAT_ARGS(current_lsn));
 }
 
 /*
-- 
2.25.1

#16Amit Kapila
amit.kapila16@gmail.com
In reply to: Ashutosh Bapat (#15)
1 attachment(s)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Tue, Aug 17, 2021 at 11:58 AM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

Hi Amit and Andres,
Here's updated patch

I think we can log the required information immediately after
releasing spinlock, otherwise, the other logs from
LogicalConfirmReceivedLocation() might interleave. I have made that
change and slightly edit the comment and commit message. I am planning
to push this tomorrow unless you or others have any comments.

--
With Regards,
Amit Kapila.

Attachments:

0001-Log-new-catalog-xmin-candidate-in-LogicalIncreaseXmi.patchapplication/octet-stream; name=0001-Log-new-catalog-xmin-candidate-in-LogicalIncreaseXmi.patchDownload
From 2adc21ef82e96e336cb160e059d85586b09e50f7 Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <ashutosh.bapat@2ndquadrant.com>
Date: Thu, 13 May 2021 13:40:33 +0530
Subject: [PATCH] Log new catalog xmin candidate in
 LogicalIncreaseXminForSlot().

Similar to LogicalIncreaseRestartDecodingForSlot() add a debug message to
LogicalIncreaseXminForSlot() reporting a new catalog_xmin candidate.

This just adds additional diagnostic information during logical decoding that
can aid debugging.

Author: Ashutosh Bapat
Reviewed-by: Masahiko Sawada, Amit Kapila
Discussion: https://postgr.es/m/CAExHW5usQWbiUz0hHOCu5twS1O9DvpcPojf6sor=8q--VUuMbA@mail.gmail.com
---
 src/backend/replication/logical/logical.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/src/backend/replication/logical/logical.c b/src/backend/replication/logical/logical.c
index 64b8280c13..aae0ae5b8a 100644
--- a/src/backend/replication/logical/logical.c
+++ b/src/backend/replication/logical/logical.c
@@ -1565,6 +1565,7 @@ LogicalIncreaseXminForSlot(XLogRecPtr current_lsn, TransactionId xmin)
 {
 	bool		updated_xmin = false;
 	ReplicationSlot *slot;
+	bool		got_new_xmin = false;
 
 	slot = MyReplicationSlot;
 
@@ -1602,9 +1603,19 @@ LogicalIncreaseXminForSlot(XLogRecPtr current_lsn, TransactionId xmin)
 	{
 		slot->candidate_catalog_xmin = xmin;
 		slot->candidate_xmin_lsn = current_lsn;
+
+		/*
+		 * Log new xmin at an appropriate log level after releasing the
+		 * spinlock.
+		 */
+		got_new_xmin = true;
 	}
 	SpinLockRelease(&slot->mutex);
 
+	if (got_new_xmin)
+		elog(DEBUG1, "got new catalog xmin %u at %X/%X", xmin,
+			 LSN_FORMAT_ARGS(current_lsn));
+
 	/* candidate already valid with the current flush position, apply */
 	if (updated_xmin)
 		LogicalConfirmReceivedLocation(slot->data.confirmed_flush);
-- 
2.28.0.windows.1

#17Ashutosh Bapat
ashutosh.bapat@enterprisedb.com
In reply to: Amit Kapila (#16)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

Yeah, I agree. Sorry for missing that.

The updated patch looks good to me.

On Mon, Sep 6, 2021 at 3:25 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Tue, Aug 17, 2021 at 11:58 AM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

Hi Amit and Andres,
Here's updated patch

I think we can log the required information immediately after
releasing spinlock, otherwise, the other logs from
LogicalConfirmReceivedLocation() might interleave. I have made that
change and slightly edit the comment and commit message. I am planning
to push this tomorrow unless you or others have any comments.

--
With Regards,
Amit Kapila.

--
--
Best Wishes,
Ashutosh

#18Amit Kapila
amit.kapila16@gmail.com
In reply to: Ashutosh Bapat (#17)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Mon, Sep 6, 2021 at 5:29 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

Yeah, I agree. Sorry for missing that.

The updated patch looks good to me.

Pushed!

--
With Regards,
Amit Kapila.

#19Ashutosh Bapat
ashutosh.bapat.oss@gmail.com
In reply to: Amit Kapila (#18)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

Thanks Amit.

On Tue, Sep 7, 2021 at 11:14 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Mon, Sep 6, 2021 at 5:29 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

Yeah, I agree. Sorry for missing that.

The updated patch looks good to me.

Pushed!

--
With Regards,
Amit Kapila.

--
Best Wishes,
Ashutosh Bapat

#20Jaime Casanova
jcasanov@systemguards.com.ec
In reply to: Amit Kapila (#18)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Tue, Sep 07, 2021 at 11:14:23AM +0530, Amit Kapila wrote:

On Mon, Sep 6, 2021 at 5:29 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

Yeah, I agree. Sorry for missing that.

The updated patch looks good to me.

Pushed!

This patch is still on "Needs review"!
Should we change it to Committed or is expected something else
about it?

--
Jaime Casanova
Director de Servicios Profesionales
SystemGuards - Consultores de PostgreSQL

#21Masahiko Sawada
sawada.mshk@gmail.com
In reply to: Jaime Casanova (#20)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Fri, Oct 1, 2021 at 1:45 AM Jaime Casanova
<jcasanov@systemguards.com.ec> wrote:

On Tue, Sep 07, 2021 at 11:14:23AM +0530, Amit Kapila wrote:

On Mon, Sep 6, 2021 at 5:29 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

Yeah, I agree. Sorry for missing that.

The updated patch looks good to me.

Pushed!

This patch is still on "Needs review"!
Should we change it to Committed or is expected something else
about it?

Yes, the patch already gets committed (4c347885). So I also think we
should mark it as Committed.

Regards,

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

#22Amit Kapila
amit.kapila16@gmail.com
In reply to: Masahiko Sawada (#21)
Re: Diagnostic comment in LogicalIncreaseXminForSlot

On Fri, Oct 1, 2021 at 6:36 AM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

On Fri, Oct 1, 2021 at 1:45 AM Jaime Casanova
<jcasanov@systemguards.com.ec> wrote:

On Tue, Sep 07, 2021 at 11:14:23AM +0530, Amit Kapila wrote:

On Mon, Sep 6, 2021 at 5:29 PM Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:

Yeah, I agree. Sorry for missing that.

The updated patch looks good to me.

Pushed!

This patch is still on "Needs review"!
Should we change it to Committed or is expected something else
about it?

Yes, the patch already gets committed (4c347885). So I also think we
should mark it as Committed.

Right, I have changed the status to Committed.

--
With Regards,
Amit Kapila.