Re: Add Information during standby recovery conflicts

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