Re: Add Information during standby recovery conflicts

On Sun, 4 Oct 2020 at 20:48, Drouvot, Bertrand <bdrouvot@amazon.com> wrote:
>
>
> 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
>

Sorry I didn't realize I failed to send review comments. Here is my
comments on the previous version (v4) patch (attached to [1]):

---
@ -3828,6 +3830,8 @@ LockBufferForCleanup(Buffer buffer)
                        GetPrivateRefCount(buffer));

       bufHdr = GetBufferDescriptor(buffer - 1);
       waitStart = GetCurrentTimestamp();
       logged = false;

I think it's better to avoid calling GetCurrentTimestamp() when the
timestamp is not used. In the above case, we can call it only when
log_recovery_conflict_waits is true.

---
+void
+LogRecoveryConflict(VirtualTransactionId *waitlist, ProcSignalReason
reason, bool waiting)

It seems to me that having 'reason' at the first argument is natural.

---
+       /* Log the recovery conflict */
+       if (log_recovery_conflict_waits)
+               LogRecoveryConflict(NULL,
PROCSIG_RECOVERY_CONFLICT_DATABASE, false);

There seems no need to log recovery conflicts because no wait occurs
when recovery conflict with database happens.

---
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);
                }

We log the recovery conflicts without checking deadlock timeout here.
I think we should call LogRecoveryConflict() after
ResolveRecoveryConflictWithLock() with the check if we're waiting for
longer than deadlock_time sec. That way, we can also remove the
following description in the doc, which seems more appropriate
behavior:

+        For the lock conflict case, it does not wait for
<varname>deadlock_timeout</varname> to be reached.

Also, in ResolveRecoveryConflictWithVirtualXIDs() called from
ResolveRecoveryConflictWithLock(), we could log the same again here:

+                       /* Log the recovery conflict */
+                       if (log_recovery_conflict_waits && !logged
+                                       && TimestampDifferenceExceeds(waitStart,
+
GetCurrentTimestamp(), DeadlockTimeout))
+                       {
+                               LogRecoveryConflict(waitlist, reason,
report_waiting);
+                               logged = true;
+                       }

Note that since the 'report_waiting' is false in this case, waitStart
is not initialized.

I think we can use 'report_waiting' for this purpose too. The
'report_waiting' is false in the lock conflict cases where we also
want to skip logging a recovery conflict in
ResolveRecoveryConflictWithVirtualXIDs().

---
@@ -1069,6 +1069,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod
lockMethodTable)
       PGPROC     *proc;
        PGPROC     *leader = MyProc->lockGroupLeader;
        int                     i;
+       bool logged;

I guess it's better to rename 'logged' to 'logged_recovery_confclit'
or other to make the purpose clear. This function logs not only
recovery conflicts but also deadlock and waits for lock.

As an alternative idea, possibly we can allow it to report the log
multiple times with how long waiting for. We pass the time when the
wait started to LogRecoveryConflict() and show something like
"recovery is still waiting recovery conflict on buffer pin after 100.0
ms". But we can also leave it as the next improvement.

---
+extern const char *get_procsignal_reason_desc(ProcSignalReason reason)
+   {
+       const char *reasonDesc = "unknown reason";
+

I think we can move this function to standby.c.

---
The patch needs to run pgindent. For instance, the following change
doesn't follow the coding style:

+
+       if (waitlist && waiting) {
+               vxids = waitlist;
+               count = 0;
+               initStringInfo(&buf);

---
Currently, we report the list of the conflicted virtual transaction
ids but perhaps showing process ids instead seems better. What do you
think?

I've attached the patch as an idea of fixing the above comments as
well as the comment from Alvaro. I can be applied on top of v4 patch.

[1] https://www.postgresql.org/message-id/29da248a-e21c-a3eb-a051-f1ec79b13d31%40amazon.com

--
Masahiko Sawada            http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services