From: Drouvot, Bertrand <bdrouvot@amazon.com>
To: Masahiko Sawada <masahiko.sawada@2ndquadrant.com>
Cc: PostgreSQL-development <pgsql-hackers@postgresql.org>
Subject: Re: Add Information during standby recovery conflicts
Date: Sun, 4 Oct 2020 13:48:22 +0200
Message-ID: <29da248a-e21c-a3eb-a051-f1ec79b13d31@amazon.com> (raw)
In-Reply-To: <0fb96369-cc7c-cddb-a474-ca3d29904123@amazon.com>
References: <9a60178c-a853-1440-2cdc-c3af916cff59@amazon.com>
<CA+fd4k6oBCoF+4sAgWqsC5+B5+EWQfT=FyPg9zVo4wh+zTXhUg@mail.gmail.com>
<daeecc9d-567a-cad8-298a-6f12ed7cb665@amazon.com>
<CA+fd4k45sOD63XV-fcpi-ACS12PQa4G19_qf+cCVUcKK2nfKJw@mail.gmail.com>
<3aededb3-8eb7-bfd6-6fd4-b6487f8f1d74@amazon.com>
<CA+fd4k5ftD-OZPA2K0gPJxDv12mxAknAM2LVTjMRFbjZCC2FhQ@mail.gmail.com>
<85c21e8e-4b12-9ff6-92bf-24fac2166632@amazon.com>
<CA+fd4k7Y2H+NT-yNr1NTBKnefyWbnOP5+1cfaACTNL8WXpwhNA@mail.gmail.com>
<45fba139-8415-ae3e-0637-f9c698432f00@amazon.com>
<CA+fd4k6msoKMGBxuOvZ8+iC2LAdzWbGZbkYY9r0+z56FVca-AA@mail.gmail.com>
<05621ec8-6e62-25db-14c4-50079304617d@amazon.com>
<CA+fd4k4kqcSxuWpLOESwGsEnKLvdEpEKbspLCD5uf9SsE8bEAw@mail.gmail.com>
<0fb96369-cc7c-cddb-a474-ca3d29904123@amazon.com>
On 8/28/20 4:14 PM, Drouvot, Bertrand wrote:
>
> On 8/28/20 7:03 AM, Masahiko Sawada wrote:
>> CAUTION: This email originated from outside of the organization. Do
>> not click links or open attachments unless you can confirm the sender
>> and know the content is safe.
>>
>>
>>
>> On Thu, 27 Aug 2020 at 20:58, Drouvot, Bertrand <bdrouvot@amazon.com>
>> wrote:
>>>
>>> On 8/27/20 10:16 AM, Masahiko Sawada wrote
>>>> On Mon, 10 Aug 2020 at 23:43, Drouvot, Bertrand
>>>> <bdrouvot@amazon.com> wrote:
>>>>> Hi,
>>>>>
>>>>> On 7/31/20 7:12 AM, Masahiko Sawada wrote:
>>>>>> + tmpWaitlist = waitlist;
>>>>>> + while (VirtualTransactionIdIsValid(*tmpWaitlist))
>>>>>> + {
>>>>>> + tmpWaitlist++;
>>>>>> + }
>>>>>> +
>>>>>> + num_waitlist_entries = (tmpWaitlist - waitlist);
>>>>>> +
>>>>>> + /* display wal record information */
>>>>>> + if (log_recovery_conflicts &&
>>>>>> (TimestampDifferenceExceeds(recovery_conflicts_log_time,
>>>>>> GetCurrentTimestamp(),
>>>>>> + DeadlockTimeout))) {
>>>>>> + LogBlockedWalRecordInfo(num_waitlist_entries, reason);
>>>>>> + recovery_conflicts_log_time = GetCurrentTimestamp();
>>>>>> + }
>>>>>>
>>>>>> recovery_conflicts_log_time is not initialized. And shouldn't we
>>>>>> compare the current timestamp to the timestamp when the startup
>>>>>> process started waiting?
>>>>>>
>>>>>> I think we should call LogBlockedWalRecordInfo() inside of the inner
>>>>>> while loop rather than at the beginning of
>>>>>> ResolveRecoveryConflictWithVirtualXIDs(). In lock conflict cases,
>>>>>> the
>>>>>> startup process waits until 'ltime', then enters
>>>>>> ResolveRecoveryConflictWithVirtualXIDs() after reaching 'ltime'.
>>>>>> Therefore, it makes sense to call LogBlockedWalRecordInfo() at the
>>>>>> beginning of ResolveRecoveryConflictWithVirtualXIDs(). However, in
>>>>>> snapshot and tablespace conflict cases (i.g.
>>>>>> ResolveRecoveryConflictWithSnapshot() and
>>>>>> ResolveRecoveryConflictWithTablespace()), it enters
>>>>>> ResolveRecoveryConflictWithVirtualXIDs() without waits and waits for
>>>>>> reaching ‘ltime’ inside of the inner while look. So the above
>>>>>> condition could always be false.
>>>>> That would make the information being displayed after
>>>>> max_standby_streaming_delay is reached for the multiple cases you
>>>>> just
>>>>> described.
>>>> Sorry, it should be deadlock_timeout, not max_standby_streaming_delay.
>>>> Otherwise, the recovery conflict log message is printed when
>>>> resolution, which seems not to achieve the original purpose. Am I
>>>> missing something?
>>> Ok, I understand where the confusion is coming from.
>>>
>>> Indeed the new version is now printing the recovery conflict log
>>> message
>>> during the conflict resolution (while the initial intention was to be
>>> warned as soon as the replay had to wait).
>>>
>>> The advantage of the new version is that it would be consistent across
>>> all the conflicts scenarios (if not, we would get messages during the
>>> resolution or when the replay started waiting, depending of the
>>> conflict
>>> scenario).
>>>
>>> On the other hand, the cons of the new version is that we would miss
>>> messages when no resolution is needed (replay wait duration <
>>> max_standby_streaming_delay), but is that really annoying? (As no
>>> cancellation would occur)
>>>
>>> Thinking about it, i like the new version (being warned during the
>>> resolution) as we would get messages only when cancelation will occur
>>> (which is what the user might want to avoid, so the extra info would be
>>> useful).
>>>
>>> What do you think?
>> Hmm, I think we print the reason why backends are canceled even of as
>> now by ProcessInterrupts(). With this patch and related patches you
>> proposed on another thread, the startup process reports virtual xids
>> being interrupted, the reason, and LSN of blocked WAL, then processes
>> will also report its virtual xid and reason. Therefore, the new
>> information added by these patches is only the LSN of blocked WAL.
>
> That's completely right, let's come back to the original intention of
> this patch (means, don't wait for the conflict resolution to log
> messages).
>
> I'll submit a new version once updated.
Please find attached the new patch.
It provides the following outcomes depending on the conflict:
2020-10-04 09:08:51.923 UTC [30788] LOG: recovery is waiting recovery
conflict on buffer pin
OR
2020-10-04 09:52:25.832 UTC [1249] LOG: recovery is waiting recovery
conflict on snapshot
2020-10-04 09:52:25.832 UTC [1249] DETAIL: Conflicting virtual
transaction ids: 3/2, 2/4.
OR
2020-10-04 09:11:51.717 UTC [30788] LOG: recovery is waiting recovery
conflict on lock
2020-10-04 09:11:51.717 UTC [30788] DETAIL: Conflicting virtual
transaction id: 2/5.
OR
2020-10-04 09:13:04.104 UTC [30788] LOG: recovery is resolving recovery
conflict on database
Thanks
Bertrand
Attachments:v1-0004-Add-Standby-Recovery-Conflicts-BlockedOnly-Info.patch (text/plain, 10.9K) download
doc/src/sgml/config.sgml | 22 ++++++++++
src/backend/storage/buffer/bufmgr.c | 13 ++++++
src/backend/storage/ipc/procsignal.c | 36 ++++++++++++++++
src/backend/storage/ipc/standby.c | 61 +++++++++++++++++++++++++++
src/backend/storage/lmgr/proc.c | 9 ++++
src/backend/utils/misc/guc.c | 10 ++++-
src/backend/utils/misc/postgresql.conf.sample | 1 +
src/include/storage/procsignal.h | 1 +
src/include/storage/standby.h | 2 +
9 files changed, 154 insertions(+), 1 deletion(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgmlindex ee914740cc..6023c7d8c0 100644--- a/doc/src/sgml/config.sgml+++ b/doc/src/sgml/config.sgml@@ -6839,6 +6839,28 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-recovery-conflict-waits" xreflabel="log_recovery_conflict_waits">+ <term><varname>log_recovery_conflict_waits</varname> (<type>boolean</type>)+ <indexterm>+ <primary><varname>log_recovery_conflict_waits</varname> configuration parameter</primary>+ </indexterm>+ </term>+ <listitem>+ <para>+ Controls whether detailed information is produced when the + startup process is resolving or waiting for recovery conflicts.+ It logs only when it waits for longer than <varname>deadlock_timeout</varname>.+ For the lock conflict case, it does not wait for <varname>deadlock_timeout</varname> to be reached.+ </para>++ <para>+ This parameter can only be set in the <filename>postgresql.conf</filename>+ file or on the server command line.+ The default is <literal>off</literal>.+ </para>+ </listitem>+ </varlistentry>+
<varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
<term><varname>log_parameter_max_length</varname> (<type>integer</type>)
<indexterm>
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.cindex e549fa1d30..152c2292d8 100644--- a/src/backend/storage/buffer/bufmgr.c+++ b/src/backend/storage/buffer/bufmgr.c@@ -3808,6 +3808,8 @@ LockBufferForCleanup(Buffer buffer)
{
BufferDesc *bufHdr;
char *new_status = NULL;
+ TimestampTz waitStart = 0;+ bool logged;
Assert(BufferIsPinned(buffer));
Assert(PinCountWaitBuf == NULL);
@@ -3828,6 +3830,8 @@ LockBufferForCleanup(Buffer buffer)
GetPrivateRefCount(buffer));
bufHdr = GetBufferDescriptor(buffer - 1);
+ waitStart = GetCurrentTimestamp();+ logged = false;
for (;;)
{
@@ -3881,6 +3885,15 @@ LockBufferForCleanup(Buffer buffer)
new_status[len] = '\0'; /* truncate off " waiting" */
}
+ if (log_recovery_conflict_waits && !logged+ && TimestampDifferenceExceeds(waitStart,+ GetCurrentTimestamp(), DeadlockTimeout))+ {+ LogRecoveryConflict(NULL,+ PROCSIG_RECOVERY_CONFLICT_BUFFERPIN, true);+ logged = true;+ }+
/* Publish the bufid that Startup process waits on */
SetStartupBufferPinWaitBufId(buffer - 1);
/* Set alarm and then wait to be signaled by UnpinBuffer() */
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.cindex ffe67acea1..575ee79687 100644--- a/src/backend/storage/ipc/procsignal.c+++ b/src/backend/storage/ipc/procsignal.c@@ -591,3 +591,39 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
errno = save_errno;
}
++extern const char *get_procsignal_reason_desc(ProcSignalReason reason)+ {+ const char *reasonDesc = "unknown reason";++ switch (reason)+ {+ case PROCSIG_RECOVERY_CONFLICT_BUFFERPIN:+ reasonDesc = "buffer pin";+ break;+ case PROCSIG_RECOVERY_CONFLICT_LOCK:+ reasonDesc = "lock";+ break;+ case PROCSIG_RECOVERY_CONFLICT_TABLESPACE:+ reasonDesc = "tablespace";+ break;+ case PROCSIG_RECOVERY_CONFLICT_SNAPSHOT:+ reasonDesc = "snapshot";+ break;+ case PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK:+ reasonDesc = "deadlock";+ break;+ case PROCSIG_RECOVERY_CONFLICT_DATABASE:+ reasonDesc = "database";+ break;+ case PROCSIG_CATCHUP_INTERRUPT:+ case PROCSIG_NOTIFY_INTERRUPT:+ case PROCSIG_PARALLEL_MESSAGE:+ case PROCSIG_WALSND_INIT_STOPPING:+ case NUM_PROCSIGNALS:+ break;+ default:+ break;+ }+ return reasonDesc;+}diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.cindex 52b2809dac..7d4241a4e1 100644--- a/src/backend/storage/ipc/standby.c+++ b/src/backend/storage/ipc/standby.c@@ -39,6 +39,7 @@
int vacuum_defer_cleanup_age;
int max_standby_archive_delay = 30 * 1000;
int max_standby_streaming_delay = 30 * 1000;
+bool log_recovery_conflict_waits = false;
static HTAB *RecoveryLockLists;
@@ -215,6 +216,52 @@ WaitExceedsMaxStandbyDelay(uint32 wait_event_info)
return false;
}
+/*+ * Log the recovery conflict+ */+void+LogRecoveryConflict(VirtualTransactionId *waitlist, ProcSignalReason reason, bool waiting)+{++ VirtualTransactionId *vxids;+ StringInfoData buf;+ int count;++ if (waitlist && waiting) {+ vxids = waitlist;+ count = 0;+ initStringInfo(&buf);++ while (VirtualTransactionIdIsValid(*vxids))+ {+ count++;+ if (count > 1)+ appendStringInfo(&buf,", ");++ appendStringInfo(&buf,"%d/%u",vxids->backendId,+ vxids->localTransactionId);+ vxids++;+ }+ ereport(LOG,+ (errmsg("recovery is waiting recovery conflict on %s",+ get_procsignal_reason_desc(reason)),+ (errdetail_log_plural("Conflicting virtual transaction id: %s.",+ "Conflicting virtual transaction ids: %s.",+ count, buf.data))));+ pfree(buf.data);+ }+ else if (!waitlist) {+ if (!waiting)+ ereport(LOG,+ (errmsg("recovery is resolving recovery conflict on %s",+ get_procsignal_reason_desc(reason))));+ else+ ereport(LOG,+ (errmsg("recovery is waiting recovery conflict on %s",+ get_procsignal_reason_desc(reason))));+ }+}+
/*
* This is the main executioner for any query backend that conflicts with
* recovery processing. Judgement has already been passed on it within
@@ -232,6 +279,7 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
{
TimestampTz waitStart = 0;
char *new_status;
+ bool logged = false;
/* Fast exit, to avoid a kernel call if there's no work to be done. */
if (!VirtualTransactionIdIsValid(*waitlist))
@@ -249,6 +297,14 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
/* wait until the virtual xid is gone */
while (!VirtualXactLock(*waitlist, false))
{
+ /* Log the recovery conflict */+ if (log_recovery_conflict_waits && !logged+ && TimestampDifferenceExceeds(waitStart,+ GetCurrentTimestamp(), DeadlockTimeout))+ {+ LogRecoveryConflict(waitlist, reason, report_waiting);+ logged = true;+ }
/*
* Report via ps if we have been waiting for more than 500 msec
* (should that be configurable?)
@@ -370,6 +426,11 @@ ResolveRecoveryConflictWithDatabase(Oid dbid)
* block during InitPostgres() and then disconnect when they see the
* database has been removed.
*/
++ /* Log the recovery conflict */+ if (log_recovery_conflict_waits)+ LogRecoveryConflict(NULL, PROCSIG_RECOVERY_CONFLICT_DATABASE, false);+
while (CountDBBackends(dbid) > 0)
{
CancelDBBackends(dbid, PROCSIG_RECOVERY_CONFLICT_DATABASE, true);
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.cindex 88566bd9fa..8cbd3b39a3 100644--- a/src/backend/storage/lmgr/proc.c+++ b/src/backend/storage/lmgr/proc.c@@ -1069,6 +1069,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
PGPROC *proc;
PGPROC *leader = MyProc->lockGroupLeader;
int i;
+ bool logged;
/*
* If group locking is in use, locks held by members of my locking group
@@ -1275,11 +1276,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
* timeout and updating the locallock table, but if we lose control to an
* error, LockErrorCleanup will fix that up.
*/
+ logged = false;
do
{
if (InHotStandby)
{
/* Set a timer and wait for that or for the Lock to be granted */
+ VirtualTransactionId *backends;+ backends = GetLockConflicts(&locallock->tag.lock, AccessExclusiveLock, NULL);+ if (log_recovery_conflict_waits && !logged) {+ LogRecoveryConflict(backends, PROCSIG_RECOVERY_CONFLICT_LOCK, true);+ logged = true;+ }+
ResolveRecoveryConflictWithLock(locallock->tag.lock);
}
else
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.cindex 596bcb7b84..e94aa79418 100644--- a/src/backend/utils/misc/guc.c+++ b/src/backend/utils/misc/guc.c@@ -1570,7 +1570,15 @@ static struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
-+ {+ {"log_recovery_conflict_waits", PGC_SIGHUP, LOGGING_WHAT,+ gettext_noop("Logs standby recovery conflicts resolution."),+ NULL+ },+ &log_recovery_conflict_waits,+ false,+ NULL, NULL, NULL+ },
{
{"log_hostname", PGC_SIGHUP, LOGGING_WHAT,
gettext_noop("Logs the host name in the connection logs."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sampleindex 9cb571f7cc..c2e1af714d 100644--- a/src/backend/utils/misc/postgresql.conf.sample+++ b/src/backend/utils/misc/postgresql.conf.sample@@ -553,6 +553,7 @@
# %% = '%'
# e.g. '<%u%%%d> '
#log_lock_waits = off # log lock waits >= deadlock_timeout
+#log_recovery_conflict_waits = off # log standby recovery conflicts
#log_parameter_max_length = -1 # when logging statements, limit logged
# bind-parameter values to N bytes;
# -1 means print in full, 0 disables
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.hindex 5cb39697f3..7cd988263d 100644--- a/src/include/storage/procsignal.h+++ b/src/include/storage/procsignal.h@@ -71,5 +71,6 @@ extern void WaitForProcSignalBarrier(uint64 generation);
extern void ProcessProcSignalBarrier(void);
extern void procsignal_sigusr1_handler(SIGNAL_ARGS);
+extern const char *get_procsignal_reason_desc(ProcSignalReason reason);
#endif /* PROCSIGNAL_H */
diff --git a/src/include/storage/standby.h b/src/include/storage/standby.hindex faaf1d3817..8e3b02f7be 100644--- a/src/include/storage/standby.h+++ b/src/include/storage/standby.h@@ -23,6 +23,7 @@
extern int vacuum_defer_cleanup_age;
extern int max_standby_archive_delay;
extern int max_standby_streaming_delay;
+extern bool log_recovery_conflict_waits;
extern void InitRecoveryTransactionEnvironment(void);
extern void ShutdownRecoveryTransactionEnvironment(void);
@@ -38,6 +39,7 @@ extern void CheckRecoveryConflictDeadlock(void);
extern void StandbyDeadLockHandler(void);
extern void StandbyTimeoutHandler(void);
extern void StandbyLockTimeoutHandler(void);
+extern void LogRecoveryConflict(VirtualTransactionId *waitlist, ProcSignalReason reason, bool waiting);
/*
* Standby Rmgr (RM_STANDBY_ID)
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: bdrouvot@amazon.com, masahiko.sawada@2ndquadrant.com
Subject: Re: Add Information during standby recovery conflicts
In-Reply-To: <29da248a-e21c-a3eb-a051-f1ec79b13d31@amazon.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