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: Sat, 11 Jul 2020 14:55:57 +0200
Message-ID: <85c21e8e-4b12-9ff6-92bf-24fac2166632@amazon.com> (raw)
In-Reply-To: <CA+fd4k5ftD-OZPA2K0gPJxDv12mxAknAM2LVTjMRFbjZCC2FhQ@mail.gmail.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>
On 7/7/20 9:43 AM, Masahiko Sawada wrote:
> Fully makes sense, the new patch version attached is now producing:
>> 2020-07-06 06:10:36.022 UTC [14035] LOG: waiting for recovery conflict
>> on snapshot
> How about adding the subject? that is, "recovery is waiting for
> recovery conflict on %s" or "recovery process <pid> is waiting for
> conflict on %s".
The subject is now added in the new attached patch (I did not include
the pid as it is part of the log prefix).
It now looks like:
2020-07-11 12:00:41.092 UTC [23217] LOG: recovery is waiting for
recovery conflict on snapshot
2020-07-11 12:00:41.092 UTC [23217] DETAIL: There is 1 blocking
connection(s).
2020-07-11 12:00:41.092 UTC [23217] CONTEXT: WAL redo at 0/4A0A6BF0 for
Heap2/CLEAN: remxid 1128
WAL record received at 2020-07-11 12:00:41.092231+00
tbs 1663 db 13586 rel 16805, fork main, blkno 0
>
>> 2020-07-06 06:10:36.022 UTC [14035] DETAIL: WAL record received at
>> 2020-07-06 06:10:36.021963+00.
>> Tablespace/database/relation are 1663/13586/16672, fork is main
>> and block is 0.
>> There is 1 blocking connection(s).
> To follow the existing log message, perhaps this can be something like
> "WAL record received at %s, rel %u/%u/%u, fork %s, blkno %u. %d
> processes". But I'm not sure the errdetail is the best place to
> display the WAL information as I mentioned in the latter part of this
> email.
moved to the context and formatted the same way as the current
Standby/LOCK context.
> Ok. Let's keep this thread for the new attached patch that focus on the
>> recovery process waiting.
> Thank you for updating the patch!
>
> I've tested the latest patch.
Thank you for testing and reviewing!
> On recovery conflict on lock and on
> bufferpin, if max_standby_streaming_delay is disabled (set to -1), the
> logs don't appear even if log_recovery_conflicts is true.
Nice catch! it is fixed in the new attached patch (the log reporting has
been moved out of StandbyTimeoutHandler()).
>
> Here is random comments on the code:
>
> + recovery_conflict_main_message = psprintf("waiting for
> recovery conflict on %s",
> +
> get_procsignal_reason_desc(reason));
> :
> + ereport(LOG,
> + (errmsg("%s", recovery_conflict_main_message),
> + errdetail("%s\n" "There is %d blocking
> connection(s).", wal_record_detail_str, num_waitlist_entries)));
>
> It's not translation-support-friendly. I think the message "waiting
> for recovery conflict on %s" should be surrounded by _(). Or we can
> just put it to ereport as follows:
>
> ereport(LOG,
> (errmsg("waiting for recovery conflicts on %s",
> get_procsignal_reason_desc(reason))
> ...
changed in the new attached patch.
>
> ---
> + oldcontext = MemoryContextSwitchTo(ErrorContext);
> + econtext = error_context_stack;
> +
> + if (XLogRecGetBlockTag(econtext->arg, 0, &rnode, &forknum, &blknum))
>
> I don't think it's a good idea to rely on error_context_stack because
> other codes might set another error context before reaching here in
> the future.
right, changed in the new attached patch: this is now done in
rm_redo_error_callback() and using the XLogReaderState passed as argument.
>
> ---
> + if (XLogRecGetBlockTag(econtext->arg, 0, &rnode, &forknum, &blknum))
> + wal_record_detail_str = psprintf("WAL record received
> at %s.\nTablespace/database/relation are %u/%u/%u, fork is %s and
> block is %u.",
> + receipt_time_str,
> rnode.spcNode, rnode.dbNode, rnode.relNode,
> + forkNames[forknum],
> + blknum);
>
> There might be a block tag in block ids other than 0.
right, fixed in the new attached patch.
> I'm not sure the
> errdetail is the best place where we display WAL information.
moved to context in the new attached patch.
> For
> instance, we display both the relation oid and block number depending
> on RM as follows:
>
> 2020-07-07 15:50:30.733 JST [13344] LOG: waiting for recovery conflict on lock
> 2020-07-07 15:50:30.733 JST [13344] DETAIL: WAL record received at
> 2020-07-07 15:50:27.73378+09.
> There is 1 blocking connection(s).
> 2020-07-07 15:50:30.733 JST [13344] CONTEXT: WAL redo at 0/3000028
> for Standby/LOCK: xid 506 db 13586 rel 16384
>
> I wonder if we can display the details of redo WAL information by
> improving xlog_outdesc() or rm_redo_error_callback() so that it
> displays relfilenode, forknum, and block number. What do you think?
I think that fully make sense to move this to rm_redo_error_callback().
This is where the information is now been displayed in the new attached
patch.
>
> ---
> + /* display wal record information */
> + if (log_recovery_conflicts)
> + LogBlockedWalRecordInfo(num_waitlist_entries, reason);
>
> I'm concerned that we should log the recovery conflict information
> every time when a recovery conflict happens from the perspective of
> overheads and the amount of the logs. Can we logs that information
> after waiting for deadlock_timeouts secs like log_lock_waits or
> waiting for the fixed duration?
The new attached patch is now waiting for deadlock_timeout duration.
>
> ---
> @@ -609,6 +682,10 @@ StandbyTimeoutHandler(void)
> /* forget any pending STANDBY_DEADLOCK_TIMEOUT request */
> disable_timeout(STANDBY_DEADLOCK_TIMEOUT, false);
>
> + /* display wal record information */
> + if (log_recovery_conflicts)
> + LogBlockedWalRecordInfo(-1,
> PROCSIG_RECOVERY_CONFLICT_BUFFERPIN);
> +
> SendRecoveryConflictWithBufferPin(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN);
> }
>
> ResolveRecoveryConflictWithBufferPin() which sets a timer to call
> StandbyTimeoutHandler() can be called multiple times even if the
> recovery is waiting for one buffer pin. I think we should avoid
> logging the same contents multiple times.
I do agree, only the first pass is now been logged.
>
> ---
> -
> + {
> + {"log_recovery_conflicts", PGC_SUSET, LOGGING_WHAT,
> + gettext_noop("Logs standby recovery conflicts."),
> + NULL
> + },
> + &log_recovery_conflicts,
> + true,
> + NULL, NULL, NULL
> + },
>
> Other logging parameters such as log_lock_waits is false by default. I
> think this parameter can also be false by default but is there any
> reason to enable it by default?
now set to false by default.
>
> Since this parameter applies only to the startup process, I think it
> should be PGC_SIGHUP.
changed that way.
>
> ---
> + /* display wal record information */
> + if (log_recovery_conflicts)
> + LogBlockedWalRecordInfo(CountDBBackends(dbid),
> PROCSIG_RECOVERY_CONFLICT_DATABASE);
>
> We log the recovery conflict into the server log but we don't update
> the process title to append "waiting". While discussing the process
> title update on recovery conflict, I got the review comment[1] that we
> don't need to update the process title because no wait occurs when
> recovery conflict with database happens. As the comment says, recovery
> is canceling the existing processes on the database being removed, but
> not waiting for something.
Ok, I keep reporting the conflict but changed the wording for this
particular case.
Thanks
Bertrand
Attachments:v1-0002-Add-Standby-Recovery-Conflicts-BlockedOnly-Info.patch (text/plain, 11.5K) download
doc/src/sgml/config.sgml | 15 +++++++
src/backend/access/transam/xlog.c | 29 +++++++++++++-
src/backend/storage/buffer/bufmgr.c | 4 +-
src/backend/storage/ipc/procsignal.c | 36 +++++++++++++++++
src/backend/storage/ipc/standby.c | 57 ++++++++++++++++++++++++++-
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 | 3 +-
9 files changed, 150 insertions(+), 6 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgmlindex aca8f73a50..5580ea6978 100644--- a/doc/src/sgml/config.sgml+++ b/doc/src/sgml/config.sgml@@ -6763,6 +6763,21 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-recovery-conflicts" xreflabel="log_recovery_conflicts">+ <term><varname>log_recovery_conflicts</varname> (<type>boolean</type>)+ <indexterm>+ <primary><varname>log_recovery_conflicts</varname> configuration parameter</primary>+ </indexterm>+ </term>+ <listitem>+ <para>+ Controls whether detailed information is produced when a conflict+ occurs during standby recovery. The default is <literal>on</literal>.+ Only superusers can change this setting.+ </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/access/transam/xlog.c b/src/backend/access/transam/xlog.cindex 55cac186dc..95e5b0457b 100644--- a/src/backend/access/transam/xlog.c+++ b/src/backend/access/transam/xlog.c@@ -11745,10 +11745,37 @@ rm_redo_error_callback(void *arg)
{
XLogReaderState *record = (XLogReaderState *) arg;
StringInfoData buf;
+ int block_id;+ RelFileNode rnode;+ ForkNumber forknum;+ BlockNumber blknum;+ TimestampTz rtime;+ bool fromStream;+ char *receipt_time_str;
initStringInfo(&buf);
xlog_outdesc(&buf, record);
-+ /*+ * Ensure we are in the startup process+ * if we want to log standby recovery conflicts+ */+ if (AmStartupProcess() && log_recovery_conflicts)+ {+ GetXLogReceiptTime(&rtime, &fromStream);+ if (fromStream)+ {+ receipt_time_str = pstrdup(timestamptz_to_str(rtime));+ appendStringInfo(&buf,"\nWAL record received at %s", receipt_time_str);+ for (block_id = 0; block_id <= record->max_block_id; block_id++)+ {+ if (XLogRecGetBlockTag(record, block_id, &rnode, &forknum, &blknum))+ appendStringInfo(&buf,"\ntbs %u db %u rel %u, fork %s, blkno %u",+ rnode.spcNode, rnode.dbNode, rnode.relNode,+ forkNames[forknum],+ blknum);+ }+ }+ }
/* translator: %s is a WAL record description */
errcontext("WAL redo at %X/%X for %s",
(uint32) (record->ReadRecPtr >> 32),
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.cindex 29c920800a..50c607e0e8 100644--- a/src/backend/storage/buffer/bufmgr.c+++ b/src/backend/storage/buffer/bufmgr.c@@ -3780,6 +3780,7 @@ LockBufferForCleanup(Buffer buffer)
{
BufferDesc *bufHdr;
char *new_status = NULL;
+ bool first_pass = true;
Assert(BufferIsValid(buffer));
Assert(PinCountWaitBuf == NULL);
@@ -3856,7 +3857,8 @@ LockBufferForCleanup(Buffer buffer)
/* Publish the bufid that Startup process waits on */
SetStartupBufferPinWaitBufId(buffer - 1);
/* Set alarm and then wait to be signaled by UnpinBuffer() */
- ResolveRecoveryConflictWithBufferPin();+ ResolveRecoveryConflictWithBufferPin(first_pass);+ first_pass = false;
/* Reset the published bufid */
SetStartupBufferPinWaitBufId(-1);
}
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.cindex c809196d06..f83176cfa7 100644--- a/src/backend/storage/ipc/procsignal.c+++ b/src/backend/storage/ipc/procsignal.c@@ -576,3 +576,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 9e0d5ec257..3152402660 100644--- a/src/backend/storage/ipc/standby.c+++ b/src/backend/storage/ipc/standby.c@@ -39,6 +39,9 @@
int vacuum_defer_cleanup_age;
int max_standby_archive_delay = 30 * 1000;
int max_standby_streaming_delay = 30 * 1000;
+bool log_recovery_conflicts = false;++static TimestampTz recovery_conflicts_log_time;
static HTAB *RecoveryLockLists;
@@ -215,6 +218,27 @@ WaitExceedsMaxStandbyDelay(uint32 wait_event_info)
return false;
}
+/*+ * Display information about the wal record+ * apply being blocked+ */+static void+LogBlockedWalRecordInfo(int num_waitlist_entries, ProcSignalReason reason)+{+ if (num_waitlist_entries > 0)+ if (reason == PROCSIG_RECOVERY_CONFLICT_DATABASE)+ ereport(LOG,+ (errmsg("recovery is experiencing recovery conflict on %s", get_procsignal_reason_desc(reason)),+ errdetail("There is %d conflicting connection(s).", num_waitlist_entries)));+ else+ ereport(LOG,+ (errmsg("recovery is waiting for recovery conflict on %s", get_procsignal_reason_desc(reason)),+ errdetail("There is %d blocking connection(s).", num_waitlist_entries)));+ else+ ereport(LOG,+ (errmsg("recovery is waiting for 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 +256,8 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
{
TimestampTz waitStart = 0;
char *new_status;
+ VirtualTransactionId *tmpWaitlist;+ int num_waitlist_entries;
/* Fast exit, to avoid a kernel call if there's no work to be done. */
if (!VirtualTransactionIdIsValid(*waitlist))
@@ -241,6 +267,21 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
waitStart = GetCurrentTimestamp();
new_status = NULL; /* we haven't changed the ps display */
+ 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();+ }+
while (VirtualTransactionIdIsValid(*waitlist))
{
/* reset standbyWait_us for each xact we wait for */
@@ -370,6 +411,11 @@ ResolveRecoveryConflictWithDatabase(Oid dbid)
* block during InitPostgres() and then disconnect when they see the
* database has been removed.
*/
++ /* display wal record information */+ if (log_recovery_conflicts)+ LogBlockedWalRecordInfo(CountDBBackends(dbid), PROCSIG_RECOVERY_CONFLICT_DATABASE);+
while (CountDBBackends(dbid) > 0)
{
CancelDBBackends(dbid, PROCSIG_RECOVERY_CONFLICT_DATABASE, true);
@@ -480,7 +526,7 @@ ResolveRecoveryConflictWithLock(LOCKTAG locktag)
* at least deadlock_timeout.
*/
void
-ResolveRecoveryConflictWithBufferPin(void)+ResolveRecoveryConflictWithBufferPin(bool first_pass)
{
TimestampTz ltime;
@@ -488,6 +534,14 @@ ResolveRecoveryConflictWithBufferPin(void)
ltime = GetStandbyLimitTime();
+ /* display wal record information */+ if (log_recovery_conflicts && first_pass+ && (TimestampDifferenceExceeds(recovery_conflicts_log_time, GetCurrentTimestamp(),+ DeadlockTimeout))) {+ LogBlockedWalRecordInfo(-1, PROCSIG_RECOVERY_CONFLICT_BUFFERPIN);+ recovery_conflicts_log_time = GetCurrentTimestamp();;+ }+
if (ltime == 0)
{
/*
@@ -522,7 +576,6 @@ ResolveRecoveryConflictWithBufferPin(void)
/* Wait to be signaled by UnpinBuffer() */
ProcWaitForSignal(PG_WAIT_BUFFER_PIN);
-
/*
* Clear any timeout requests established above. We assume here that the
* Startup process doesn't have any other timeouts than what this function
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.cindex 2f3e0a70e0..aa3c3c2325 100644--- a/src/backend/utils/misc/guc.c+++ b/src/backend/utils/misc/guc.c@@ -1594,7 +1594,15 @@ static struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
-+ {+ {"log_recovery_conflicts", PGC_SIGHUP, LOGGING_WHAT,+ gettext_noop("Logs standby recovery conflicts."),+ NULL+ },+ &log_recovery_conflicts,+ 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 ac02bd0c00..40da69c07c 100644--- a/src/backend/utils/misc/postgresql.conf.sample+++ b/src/backend/utils/misc/postgresql.conf.sample@@ -548,6 +548,7 @@
# %% = '%'
# e.g. '<%u%%%d> '
#log_lock_waits = off # log lock waits >= deadlock_timeout
+#log_recovery_conflicts = 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 a0c0bc3ce5..c57413b06d 100644--- a/src/include/storage/procsignal.h+++ b/src/include/storage/procsignal.h@@ -70,5 +70,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 cfbe426e5a..cd2c73a2b5 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_conflicts;
extern void InitRecoveryTransactionEnvironment(void);
extern void ShutdownRecoveryTransactionEnvironment(void);
@@ -33,7 +34,7 @@ extern void ResolveRecoveryConflictWithTablespace(Oid tsid);
extern void ResolveRecoveryConflictWithDatabase(Oid dbid);
extern void ResolveRecoveryConflictWithLock(LOCKTAG locktag);
-extern void ResolveRecoveryConflictWithBufferPin(void);+extern void ResolveRecoveryConflictWithBufferPin(bool first_pass);
extern void CheckRecoveryConflictDeadlock(void);
extern void StandbyDeadLockHandler(void);
extern void StandbyTimeoutHandler(void);
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: <85c21e8e-4b12-9ff6-92bf-24fac2166632@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