Subject: Re: Add Information during standby recovery conflicts
To: Masahiko Sawada <masahiko.sawada@2ndquadrant.com>
CC: PostgreSQL-development <pgsql-hackers@postgresql.org>
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>
 <85c21e8e-4b12-9ff6-92bf-24fac2166632@amazon.com>
 <CA+fd4k7Y2H+NT-yNr1NTBKnefyWbnOP5+1cfaACTNL8WXpwhNA@mail.gmail.com>
 <45fba139-8415-ae3e-0637-f9c698432f00@amazon.com>
 <CA+fd4k6msoKMGBxuOvZ8+iC2LAdzWbGZbkYY9r0+z56FVca-AA@mail.gmail.com>
 <05621ec8-6e62-25db-14c4-50079304617d@amazon.com>
 <CA+fd4k4kqcSxuWpLOESwGsEnKLvdEpEKbspLCD5uf9SsE8bEAw@mail.gmail.com>
From: "Drouvot, Bertrand" <bdrouvot@amazon.com>
Message-ID: <0fb96369-cc7c-cddb-a474-ca3d29904123@amazon.com>
Date: Fri, 28 Aug 2020 16:14:25 +0200
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:68.0)
 Gecko/20100101 Thunderbird/68.12.0
MIME-Version: 1.0
In-Reply-To: 
 <CA+fd4k4kqcSxuWpLOESwGsEnKLvdEpEKbspLCD5uf9SsE8bEAw@mail.gmail.com>
Content-Type: text/plain; charset="utf-8"; format=flowed
Content-Transfer-Encoding: 8bit
Content-Language: en-US
Precedence: bulk


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.

Thanks!

Bertrand