Re: Add Information during standby recovery conflicts

On Wed, 1 Jul 2020 at 21:52, Drouvot, Bertrand <bdrouvot(at)amazon(dot)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(at)amazon(dot)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.

> 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.

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.

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