On 2020/12/15 2:00, Fujii Masao wrote:
On 2020/12/15 0:49, Drouvot, Bertrand wrote:
Hi,
On 12/14/20 4:20 PM, Fujii Masao 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 2020/12/14 21:31, Fujii Masao wrote:
On 2020/12/05 12:38, Masahiko Sawada wrote:
On Fri, Dec 4, 2020 at 7:22 PM Drouvot, Bertrand <bdrou...@amazon.com> wrote:
Hi,
On 12/4/20 2:21 AM, Fujii Masao wrote:
On 2020/12/04 9:28, Masahiko Sawada wrote:
On Fri, Dec 4, 2020 at 2:54 AM Fujii Masao
<masao.fu...@oss.nttdata.com> wrote:
On 2020/12/01 17:29, Drouvot, Bertrand wrote:
Hi,
On 12/1/20 12:35 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 Tue, Dec 1, 2020 at 3:25 AM Alvaro Herrera
<alvhe...@alvh.no-ip.org> wrote:
On 2020-Dec-01, Fujii Masao wrote:
+ if (proc)
+ {
+ if (nprocs == 0)
+ appendStringInfo(&buf, "%d", proc->pid);
+ else
+ appendStringInfo(&buf, ", %d", proc->pid);
+
+ nprocs++;
What happens if all the backends in wait_list have gone? In
other words,
how should we handle the case where nprocs == 0 (i.e., nprocs
has not been
incrmented at all)? This would very rarely happen, but can happen.
In this case, since buf.data is empty, at least there seems no
need to log
the list of conflicting processes in detail message.
Yes, I noticed this too; this can be simplified by changing the
condition in the ereport() call to be "nprocs > 0" (rather than
wait_list being null), otherwise not print the errdetail. (You
could
test buf.data or buf.len instead, but that seems uglier to me.)
+1
Maybe we can also improve the comment of this function from:
+ * This function also reports the details about the conflicting
+ * process ids if *wait_list is not NULL.
to " This function also reports the details about the conflicting
process ids if exist" or something.
Thank you all for the review/remarks.
They have been addressed in the new attached patch version.
Thanks for updating the patch! I read through the patch again
and applied the following chages to it. Attached is the updated
version of the patch. Could you review this version? If there is
no issue in it, I'm thinking to commit this version.
Thank you for updating the patch! I have one question.
+ timeouts[cnt].id = STANDBY_TIMEOUT;
+ timeouts[cnt].type = TMPARAM_AFTER;
+ timeouts[cnt].delay_ms = DeadlockTimeout;
Maybe STANDBY_TIMEOUT should be STANDBY_DEADLOCK_TIMEOUT here?
I changed the code that way.
As the comment of ResolveRecoveryConflictWithLock() says the
following, a deadlock is detected by the ordinary backend process:
* Deadlocks involving the Startup process and an ordinary backend
proces
* will be detected by the deadlock detector within the ordinary
backend.
If we use STANDBY_DEADLOCK_TIMEOUT,
SendRecoveryConflictWithBufferPin() will be called after
DeadlockTimeout passed, but I think it's not necessary for the startup
process in this case.
Thanks for pointing this! You are right.
If we want to just wake up the startup process
maybe we can use STANDBY_TIMEOUT here?
Thanks for the patch updates! Except what we are still discussing below,
it looks good to me.
When STANDBY_TIMEOUT happens, a request to release conflicting buffer
pins is sent. Right? If so, we should not also use STANDBY_TIMEOUT there?
Agree
Or, first of all, we don't need to enable the deadlock timer at all?
Since what we'd like to do is to wake up after deadlock_timeout
passes, we can do that by changing ProcWaitForSignal() so that it can
accept the timeout and giving the deadlock_timeout to it. If we do
this, maybe we can get rid of STANDBY_LOCK_TIMEOUT from
ResolveRecoveryConflictWithLock(). Thought?
Where do we enable deadlock timeout in hot standby case? You meant to
enable it in ProcWaitForSignal() or where we set a timer for not hot
standby case, in ProcSleep()?
No, what I tried to say is to change ResolveRecoveryConflictWithLock() so that
it does
1. calculate the "minimum" timeout from deadlock_timeout and
max_standby_xxx_delay
2. give the calculated timeout value to ProcWaitForSignal()
3. wait for signal and timeout on ProcWaitForSignal()
Since ProcWaitForSignal() calls WaitLatch(), seems it's not so difficult to
make ProcWaitForSignal() handle the timeout. If we do this, I was thinking that
we can get rid of enable_timeouts() from ResolveRecoveryConflictWithLock().
Why not simply use (again) the STANDBY_LOCK_TIMEOUT one? (as it triggers
a call to StandbyLockTimeoutHandler() which does nothing, except waking
up. That's what we want, right?)
Right, what I wanted to mean is STANDBY_LOCK_TIMEOUT. The startup
process can wake up and do nothing. Thank you for pointing out.
Okay, understood! Firstly I was thinking that enabling the same type (i.e.,
STANDBY_LOCK_TIMEOUT) of lock twice doesn't work properly, but as far as I read
the code, it works. In that case, only the shorter timeout would be activated
in enable_timeouts(). So I agree to use STANDBY_LOCK_TIMEOUT.
So I renamed the argument "deadlock_timer" in ResolveRecoveryConflictWithLock()
because it's not the timer for deadlock and is confusing. Attached is the
updated version of the patch. Barring any objection, I will commit this version.
Thanks for the update!
Indeed the naming is more appropriate and less confusing that way, this version
looks all good to me.
Thanks for the review! I'm thinking to wait half a day before commiting
the patch just in the case someone may object the patch.
BTW, attached is the POC patch that implements the idea discussed upthread;
if log_recovery_conflict_waits is enabled, the startup process reports
the log also after the recovery conflict was resolved and the startup process
finished waiting for it. This patch needs to be applied after
v11-0002-Log-the-standby-recovery-conflict-waits.patch is applied.
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
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 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.c
index 71b5852224..ee16e30d86 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -3846,6 +3846,15 @@ 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 +3909,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.c
index 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.c
index db0cfaa360..3860855d1f 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.h
index 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)
