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: Mon, 6 Jul 2020 08:41:49 +0200
Message-ID: <3aededb3-8eb7-bfd6-6fd4-b6487f8f1d74@amazon.com> (raw)
In-Reply-To: <CA+fd4k45sOD63XV-fcpi-ACS12PQa4G19_qf+cCVUcKK2nfKJw@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>
On 7/3/20 4:20 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 Wed, 1 Jul 2020 at 21:52, Drouvot, Bertrand <bdrouvot@amazon.com> wrote:
>> Hey,
>>
>> On 6/29/20 10:55 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, 18 Jun 2020 at 16:28, Drouvot, Bertrand <bdrouvot@amazon.com> wrote:
>>>> Hi hackers,
>>>>
>>>> I've attached a patch to add information during standby recovery conflicts.
>>>> The motive behind is to be able to get some information:
>>>>
>>>> On the apply side
>>>> On the blocker(s) side
>>>>
>>>> Motivation:
>>>>
>>>> When a standby recovery conflict occurs it could be useful to get more information to be able to dive deep on the root cause and find a way to avoid/mitigate new occurrences.
>>> I think this is a good feature. Like log_lock_waits, it will help the
>>> users to investigate recovery conflict issues.
>> exactly, thanks for looking at it.
>>>> Adding this information would make the investigations easier, it could help answering questions like:
>>>>
>>>> On which LSN was the WAL apply blocked?
>>>> What was the purpose of the bocked WAL record?
>>>> On which relation (if any) was the blocked WAL record related to?
>>>> What was the blocker(s) doing?
>>>> When did the blocker(s) started their queries (if any)?
>>>> What was the blocker(s) waiting for? on which wait event?
>>>>
>>>> Technical context and proposal:
>>>>
>>>> There is 2 points in this patch:
>>>>
>>>> Add the information about the blocked WAL record. This is done in standby.c (ResolveRecoveryConflictWithVirtualXIDs, ResolveRecoveryConflictWithDatabase, StandbyTimeoutHandler)
>>> I think we already have the information about the WAL record being
>>> applied in errcontext.
>> right, but it won’t be displayed in case log_error_verbosity is set to
>> terse.
> Yes. I think in this case errcontext or errdetail is more appropriate
> for this information in this case. Otherwise, we will end up emitting
> same WAL record information twice in log_error_verbosity = verbose.
>
> For instance, here is the server logs when I tested a recovery
> conflict on buffer pin but it looks redundant:
>
> 2020-07-03 11:01:15.339 JST [60585] LOG: wal record apply is blocked
> by 1 connection(s), reason: User query might have needed to see row
> versions that must be removed.
> 2020-07-03 11:01:15.339 JST [60585] CONTEXT: WAL redo at 0/30025E0
> for Heap2/CLEAN: remxid 505
> 2020-07-03 11:01:15.339 JST [60585] LOG: blocked wal record rmgr:
> Heap2, lsn: 0/030025E0, received at: 2020-07-03 11:01:15.338997+09,
> desc: CLEAN, relation: rel 1663/12930/16384 fork main blk 0
> 2020-07-03 11:01:15.339 JST [60585] CONTEXT: WAL redo at 0/30025E0
> for Heap2/CLEAN: remxid 505
> 2020-07-03 11:01:15.347 JST [60604] LOG: about to be interrupted:
> backend_type: client backend, state: active, wait_event: PgSleep,
> query_start: 2020-07-03 11:01:14.337708+09
> 2020-07-03 11:01:15.347 JST [60604] STATEMENT: select pg_sleep(30);
> 2020-07-03 11:01:15.347 JST [60604] ERROR: canceling statement due to
> conflict with recovery
> 2020-07-03 11:01:15.347 JST [60604] DETAIL: User query might have
> needed to see row versions that must be removed.
> 2020-07-03 11:01:15.347 JST [60604] STATEMENT: select pg_sleep(30);
>
> There are the information WAL record three times and the reason for
> interruption twice.
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
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).
2020-07-06 06:10:36.022 UTC [14035] CONTEXT: WAL redo at 0/3A05708 for
Heap2/CLEAN: remxid 972
It does not provide the pid(s) of the blocking processes as they'll
appear during the interruption(s).
>> Or did you had in mind to try to avoid using the new
>> “current_replayed_xlog” in xlog.c?
> Regarding LogBlockedWalRecordInfo(), it seems to me that the main
> message of this logging is to let users know both that the process got
> stuck due to recovery conflict and its reason (lock, database,
> bufferpin etc). Other information such as the details of blocked WAL,
> how many processes are blocking seems like additional information. So
> I think this information would be better to be shown errcontext or
> errdetails and we don’t need to create a similar feature as we already
> show the WAL record being replayed in errcontext.
I got rid of current_replayed_xlog in the new patch attached and make
use of the errcontext argument instead.
>
> Also, this function emits two LOG messages related to each other but
> I'm concerned that it can be hard for users to associate these
> separate log lines especially when server logs are written at a high
> rate. And I think these two log lines don't follow our error message
> style[1].
>
>>> I wonder if we can show the recovery conflict information in the main
>>> LOG message, the blocker information in errdetail, and use errcontext
>>> with regard to WAL record information. For example:
>>>
>>> LOG: process 500 waiting for recovery conflict on snapshot
>>> DETAIL: conflicting transition id: 100, 200, 300
>>> CONTEXT: WAL redo at 0/3001970 for Heap2/CLEAN: remxid 506
>> Not sure at all if it would be possible to put all the information at
>> the same time.
>> For example in case of shared buffer pin conflict, the blocker is
>> currently known “only” during the RecoveryConflictInterrupt call (so
>> still not known yet when we can “already” report the blocked LSN
>> information).
>> It might also happen that the blocker(s) will never get interrupted (was
>> not blocking anymore before max_standby_streaming_delay has been
>> reached): then it would not be possible to display all the information
>> here (aka when it is interrupted) while we still want to be warned that
>> the WAL replay has been blocked.
> I think it's okay with showing different information for different
> types of recovery conflict. In buffer pin conflict case, I think we
> can let the user know the process is waiting for recovery conflict on
> buffer pin in the main message and the WAL record being replayed in
> errdetails.
>
>>>> Outcome Example:
>>>>
>>>> 2020-06-15 06:48:23.774 UTC [6971] LOG: wal record apply is blocked by 2 connection(s), reason: User query might have needed to see row versions that must be removed.
>>>> 2020-06-15 06:48:23.774 UTC [6971] LOG: blocked wal record rmgr: Heap2, lsn: 0/038E2678, received at: 2020-06-15 06:48:23.774098+00, desc: CLEAN, relation: rel 1663/13586/16652 fork main blk 0
>>>> 2020-06-15 06:48:54.773 UTC [7088] LOG: about to interrupt pid: 7088, backend_type: client backend, state: active, wait_event_type: Timeout, wait_event: PgSleep, query_start: 2020-06-15 06:48:14.87672+00
>>> I'm concerned that the above information on the process who is about
>>> to be interrupted is very detailed but I'm not sure it will be helpful
>>> for the users. If the blocker is waiting on something lock, the
>>> information should be logged by log_lock_waits.
>> The blocker could also be in “idle in transaction”, say for example, on
>> the standby (with hot_standby_feedback set to off):
>>
>> standby> begin;
>> standby> SET TRANSACTION ISOLATION LEVEL REPEATABLE READ;
>> standby> select * from bdt;
>>
>> on the master:
>>
>> master> update bdt set generate_series = 15;
>> master> vacuum verbose bdt;
>>
>> would produce:
>>
>> 2020-07-01 09:18:55.256 UTC [32751] LOG: about to interrupt pid: 32751,
>> backend_type: client backend, state: idle in transaction,
>> wait_event_type: Client, wait_event: ClientRead, query_start: 2020-07-01
>> 09:18:17.390572+00
>> 2020-07-01 09:18:55.256 UTC [32751] DETAIL: statement: select * from bdt;
>>
>> I think those information are useful to have (might get rid of
>> wait_event_type though: done in the new attached patch).
> Since the backend cancels query at a convenient time
> (CHECK_FOR_INTERRUPT()), I'm concerned that the wait event information
> displayed in that log might not be helpful. For example, even if the
> blocker is getting stuck on disk I/O (WAIT_EVENT_BUFFILE_READ etc)
> while holding a lock that the recovery process is waiting for, when
> the blocker is able to cancel the query it's no longer waiting for
> disk I/O. Also, regarding displaying the backend type, we already show
> the backend type by setting %d in log_line_prefix.
>
> I still think we should show this additional information (wait event,
> query start etc) in errdetails even if we want to show this
> information in the server logs. Perhaps we can improve
> errdetail_recovery_conflict()?
>
> Aside from the above comments from the perspective of high-level
> design, I think we can split this patch into two patches: logging the
> recovery process is waiting (adding log_recovery_conficts) and logging
> the details of blockers who is about to be interrupted. I think it'll
> make review easy.
Ok. Let's keep this thread for the new attached patch that focus on the
recovery process waiting.
I'll create a new one with a dedicated thread for the blockers
information once done.
Thanks
Bertrand
> Regards,
>
> [1] https://www.postgresql.org/docs/devel/error-style-guide.html
>
> --
> Masahiko Sawada http://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Attachments:v1-0001-Add-Standby-Recovery-Conflicts-BlockedOnly-Info.patch (text/plain, 8.8K) download
doc/src/sgml/config.sgml | 15 ++++++
src/backend/storage/ipc/procsignal.c | 36 +++++++++++++
src/backend/storage/ipc/standby.c | 77 +++++++++++++++++++++++++++
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 | 1 +
7 files changed, 140 insertions(+), 1 deletion(-)
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/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..126858a363 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_conflicts = true;
static HTAB *RecoveryLockLists;
@@ -215,6 +216,59 @@ 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)+{+ RelFileNode rnode;+ ForkNumber forknum;+ BlockNumber blknum;+ TimestampTz rtime;+ bool fromStream;+ char *receipt_time_str;+ char *wal_record_detail_str;+ char *recovery_conflict_main_message;+ ErrorContextCallback *econtext;+ MemoryContext oldcontext;++ recovery_conflict_main_message = psprintf("waiting for recovery conflict on %s",+ get_procsignal_reason_desc(reason));++ GetXLogReceiptTime(&rtime, &fromStream);+ receipt_time_str = pstrdup(timestamptz_to_str(rtime));+++ oldcontext = MemoryContextSwitchTo(ErrorContext);+ econtext = error_context_stack;++ 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);+ else+ wal_record_detail_str = psprintf("WAL record received at %s.", receipt_time_str);++ MemoryContextSwitchTo(oldcontext);++ if (num_waitlist_entries > 0)+ ereport(LOG,+ (errmsg("%s", recovery_conflict_main_message),+ errdetail("%s\n" "There is %d blocking connection(s).", wal_record_detail_str, num_waitlist_entries)));+ else+ ereport(LOG,+ (errmsg("%s", recovery_conflict_main_message),+ errdetail("%s", wal_record_detail_str)));+++ pfree(recovery_conflict_main_message);+ pfree(wal_record_detail_str);+ pfree(receipt_time_str);+}+
/*
* This is the main executioner for any query backend that conflicts with
* recovery processing. Judgement has already been passed on it within
@@ -232,6 +286,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 +297,18 @@ 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)+ LogBlockedWalRecordInfo(num_waitlist_entries, reason);+
while (VirtualTransactionIdIsValid(*waitlist))
{
/* reset standbyWait_us for each xact we wait for */
@@ -370,6 +438,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);
@@ -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);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.cindex 2f3e0a70e0..7aa55db5af 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_SUSET, LOGGING_WHAT,+ gettext_noop("Logs standby recovery conflicts."),+ NULL+ },+ &log_recovery_conflicts,+ true,+ 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..1009506eff 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 = on # 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..0a99ad3f40 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);
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: <3aededb3-8eb7-bfd6-6fd4-b6487f8f1d74@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