From: Fujii Masao <masao.fujii@oss.nttdata.com>
To: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Cc: bdrouvot@amazon.com
Cc: sawada.mshk@gmail.com
Cc: alvherre@alvh.no-ip.org
Cc: masahiko.sawada@2ndquadrant.com
Cc: pgsql-hackers@postgresql.org
Subject: Re: Add Information during standby recovery conflicts
Date: Fri, 8 Jan 2021 13:19:18 +0900
Message-ID: <665ebdf3-d517-18c6-6b32-06fcdd9d6f83@oss.nttdata.com> (raw)
In-Reply-To: <20210108.111712.1465719681094712823.horikyota.ntt@gmail.com>
References: <8c1fca5b-6c5c-df6f-0b6d-4702eeb11c5c@amazon.com>
<02295c62-e90f-9bf7-63ba-1ccda204aa71@oss.nttdata.com>
<fd057da9-5616-e10e-fae6-75a85b89be68@oss.nttdata.com>
<20210108.111712.1465719681094712823.horikyota.ntt@gmail.com>
On 2021/01/08 11:17, Kyotaro Horiguchi wrote:
> At Fri, 8 Jan 2021 01:32:11 +0900, Fujii Masao <masao.fujii@oss.nttdata.com> wrote in
>>
>> Attached is the updated version of the patch. This can be applied to
>> current master.
>>
>> With the patch, for example, if the startup process waited longer than
>> deadlock_timeout for the recovery conflict on the lock, the latter log
>> message in the followings would be additionally output.
>>
>> LOG: recovery still waiting after 1001.223 ms: recovery conflict on
>> lock
>> LOG: recovery finished waiting after 19004.694 ms: recovery conflict
>> on lock
>
> + /*
> + * Emit the log message if recovery conflict on buffer pin was resolved but
> + * the startup process waited longer than deadlock_timeout for it.
>
> The first line is beyond the 80th column.
Thanks for pointing out this! This happened because I forgot to run pgindent
for bufmgr.c. Attached is the updated version of the patch.
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Attachments:log_recovery_conflict_waits_after_resolve_v3.patch (text/plain, 6.7K) downloaddiff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgmlindex 7c0a673a8d..82864bbb24 100644--- a/doc/src/sgml/config.sgml+++ b/doc/src/sgml/config.sgml@@ -6961,7 +6961,7 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
<listitem>
<para>
Controls whether a log message is produced when the startup process
- is waiting longer than <varname>deadlock_timeout</varname>+ waits longer than <varname>deadlock_timeout</varname>
for recovery conflicts. This is useful in determining if recovery
conflicts prevent the recovery from applying WAL.
</para>
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.cindex 71b5852224..c116e75ca1 100644--- a/src/backend/storage/buffer/bufmgr.c+++ b/src/backend/storage/buffer/bufmgr.c@@ -3846,6 +3846,16 @@ LockBufferForCleanup(Buffer buffer)
/* Successfully acquired exclusive lock with pincount 1 */
UnlockBufHdr(bufHdr, buf_state);
+ /*+ * Emit the log message if recovery conflict on buffer pin was+ * resolved but the startup process waited longer than+ * deadlock_timeout for it.+ */+ if (logged_recovery_conflict)+ LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN,+ waitStart, GetCurrentTimestamp(),+ NULL, false);+
/* Report change to non-waiting status */
if (new_status)
{
@@ -3900,7 +3910,7 @@ LockBufferForCleanup(Buffer buffer)
DeadlockTimeout))
{
LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN,
- waitStart, now, NULL);+ waitStart, now, NULL, true);
logged_recovery_conflict = true;
}
}
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.cindex d4b0f65ba2..39a30c00f7 100644--- a/src/backend/storage/ipc/standby.c+++ b/src/backend/storage/ipc/standby.c@@ -226,11 +226,14 @@ WaitExceedsMaxStandbyDelay(uint32 wait_event_info)
* wait_start is the timestamp when the caller started to wait.
* now is the timestamp when this function has been called.
* wait_list is the list of virtual transaction ids assigned to
- * conflicting processes.+ * conflicting processes. still_waiting indicates whether+ * the startup process is still waiting for the recovery conflict+ * to be resolved or not.
*/
void
LogRecoveryConflict(ProcSignalReason reason, TimestampTz wait_start,
- TimestampTz now, VirtualTransactionId *wait_list)+ TimestampTz now, VirtualTransactionId *wait_list,+ bool still_waiting)
{
long secs;
int usecs;
@@ -238,6 +241,12 @@ LogRecoveryConflict(ProcSignalReason reason, TimestampTz wait_start,
StringInfoData buf;
int nprocs = 0;
+ /*+ * There must be no conflicting processes when the recovery conflict has+ * already been resolved.+ */+ Assert(still_waiting || wait_list == NULL);+
TimestampDifference(wait_start, now, &secs, &usecs);
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
@@ -275,12 +284,21 @@ LogRecoveryConflict(ProcSignalReason reason, TimestampTz wait_start,
* conflicting backends in a detail message. Note that if all the backends
* in the list are not active, no detail message is logged.
*/
- ereport(LOG,- errmsg("recovery still waiting after %ld.%03d ms: %s",- msecs, usecs, _(get_recovery_conflict_desc(reason))),- nprocs > 0 ? errdetail_log_plural("Conflicting process: %s.",- "Conflicting processes: %s.",- nprocs, buf.data) : 0);+ if (still_waiting)+ {+ ereport(LOG,+ errmsg("recovery still waiting after %ld.%03d ms: %s",+ msecs, usecs, _(get_recovery_conflict_desc(reason))),+ nprocs > 0 ? errdetail_log_plural("Conflicting process: %s.",+ "Conflicting processes: %s.",+ nprocs, buf.data) : 0);+ }+ else+ {+ ereport(LOG,+ errmsg("recovery finished waiting after %ld.%03d ms: %s",+ msecs, usecs, _(get_recovery_conflict_desc(reason))));+ }
if (nprocs > 0)
pfree(buf.data);
@@ -375,13 +393,12 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
/*
* Emit the log message if the startup process is waiting
- * longer than deadlock_timeout for recovery conflict on- * buffer pin.+ * longer than deadlock_timeout for recovery conflict.
*/
if (maybe_log_conflict &&
TimestampDifferenceExceeds(waitStart, now, DeadlockTimeout))
{
- LogRecoveryConflict(reason, waitStart, now, waitlist);+ LogRecoveryConflict(reason, waitStart, now, waitlist, true);
logged_recovery_conflict = true;
}
}
@@ -391,6 +408,14 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
waitlist++;
}
+ /*+ * Emit the log message if recovery conflict was resolved but the startup+ * process waited longer than deadlock_timeout for it.+ */+ if (logged_recovery_conflict)+ LogRecoveryConflict(reason, waitStart, GetCurrentTimestamp(),+ NULL, false);+
/* Reset ps display if we changed it */
if (new_status)
{
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.cindex db0cfaa360..c87ffc6549 100644--- a/src/backend/storage/lmgr/proc.c+++ b/src/backend/storage/lmgr/proc.c@@ -1322,7 +1322,8 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
* longer than deadlock_timeout.
*/
LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_LOCK,
- standbyWaitStart, now, cnt > 0 ? vxids : NULL);+ standbyWaitStart, now,+ cnt > 0 ? vxids : NULL, true);
logged_recovery_conflict = true;
}
}
@@ -1607,6 +1608,15 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
disable_timeout(DEADLOCK_TIMEOUT, false);
}
+ /*+ * Emit the log message if recovery conflict on lock was resolved but the+ * startup process waited longer than deadlock_timeout for it.+ */+ if (InHotStandby && logged_recovery_conflict)+ LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_LOCK,+ standbyWaitStart, GetCurrentTimestamp(),+ NULL, false);+
/*
* Re-acquire the lock table's partition lock. We have to do this to hold
* off cancel/die interrupts before we can mess with lockAwaited (else we
diff --git a/src/include/storage/standby.h b/src/include/storage/standby.hindex a0f3e0bdf0..2b1f340b82 100644--- a/src/include/storage/standby.h+++ b/src/include/storage/standby.h@@ -40,7 +40,8 @@ extern void StandbyDeadLockHandler(void);
extern void StandbyTimeoutHandler(void);
extern void StandbyLockTimeoutHandler(void);
extern void LogRecoveryConflict(ProcSignalReason reason, TimestampTz wait_start,
- TimestampTz cur_ts, VirtualTransactionId *wait_list);+ TimestampTz cur_ts, VirtualTransactionId *wait_list,+ bool still_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: masao.fujii@oss.nttdata.com, horikyota.ntt@gmail.com, bdrouvot@amazon.com, sawada.mshk@gmail.com, alvherre@alvh.no-ip.org, masahiko.sawada@2ndquadrant.com
Subject: Re: Add Information during standby recovery conflicts
In-Reply-To: <665ebdf3-d517-18c6-6b32-06fcdd9d6f83@oss.nttdata.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