Re: Add Information during standby recovery conflicts

On 7/7/20 9:43 AM, Masahiko Sawada wrote:
> 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
> How about adding the subject? that is, "recovery is waiting for
> recovery conflict on %s" or "recovery process <pid> is waiting for
> conflict on %s".

The subject is now added in the new attached patch (I did not include
the pid as it is part of the log prefix).

It now looks like:

2020-07-11 12:00:41.092 UTC [23217] LOG:  recovery is waiting for
recovery conflict on snapshot
2020-07-11 12:00:41.092 UTC [23217] DETAIL:  There is 1 blocking
connection(s).
2020-07-11 12:00:41.092 UTC [23217] CONTEXT:  WAL redo at 0/4A0A6BF0 for
Heap2/CLEAN: remxid 1128
        WAL record received at 2020-07-11 12:00:41.092231+00
        tbs 1663 db 13586 rel 16805, fork main, blkno 0
>
>> 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).
> To follow the existing log message, perhaps this can be something like
> "WAL record received at %s, rel %u/%u/%u, fork %s, blkno %u. %d
> processes". But I'm not sure the errdetail is the best place to
> display the WAL information as I mentioned in the latter part of this
> email.

moved to the context and formatted the same way as the current
Standby/LOCK context.

> Ok. Let's keep this thread for the new attached patch that focus on the
>> recovery process waiting.
> Thank you for updating the patch!
>
> I've tested the latest patch.

Thank you for testing and reviewing!

> On recovery conflict on lock and on
> bufferpin, if max_standby_streaming_delay is disabled (set to -1), the
> logs don't appear even if log_recovery_conflicts is true.

Nice catch! it is fixed in the new attached patch (the log reporting has
been moved out of StandbyTimeoutHandler()).

>
> Here is random comments on the code:
>
> + recovery_conflict_main_message = psprintf("waiting for
> recovery conflict on %s",
> +
> get_procsignal_reason_desc(reason));
> :
> + ereport(LOG,
> + (errmsg("%s", recovery_conflict_main_message),
> + errdetail("%s\n" "There is %d blocking
> connection(s).", wal_record_detail_str, num_waitlist_entries)));
>
> It's not translation-support-friendly. I think the message "waiting
> for recovery conflict on %s" should be surrounded by _(). Or we can
> just put it to ereport as follows:
>
> ereport(LOG,
> (errmsg("waiting for recovery conflicts on %s",
> get_procsignal_reason_desc(reason))
> ...

changed in the new attached patch.

>
> ---
> + oldcontext = MemoryContextSwitchTo(ErrorContext);
> + econtext = error_context_stack;
> +
> + if (XLogRecGetBlockTag(econtext->arg, 0, &rnode, &forknum, &blknum))
>
> I don't think it's a good idea to rely on error_context_stack because
> other codes might set another error context before reaching here in
> the future.

right, changed in the new attached patch: this is now done in
rm_redo_error_callback() and using the XLogReaderState passed as argument.

>
> ---
> + if (XLogRecGetBlockTag(econtext->arg, 0, &rnode, &forknum, &blknum))
> + wal_record_detail_str = psprintf("WAL record received
> at %s.\nTablespace/database/relation are %u/%u/%u, fork is %s and
> block is %u.",
> + receipt_time_str,
> rnode.spcNode, rnode.dbNode, rnode.relNode,
> + forkNames[forknum],
> + blknum);
>
> There might be a block tag in block ids other than 0.

right, fixed in the new attached patch.

> I'm not sure the
> errdetail is the best place where we display WAL information.

moved to context in the new attached patch.

> For
> instance, we display both the relation oid and block number depending
> on RM as follows:
>
> 2020-07-07 15:50:30.733 JST [13344] LOG: waiting for recovery conflict on lock
> 2020-07-07 15:50:30.733 JST [13344] DETAIL: WAL record received at
> 2020-07-07 15:50:27.73378+09.
> There is 1 blocking connection(s).
> 2020-07-07 15:50:30.733 JST [13344] CONTEXT: WAL redo at 0/3000028
> for Standby/LOCK: xid 506 db 13586 rel 16384
>
> I wonder if we can display the details of redo WAL information by
> improving xlog_outdesc() or rm_redo_error_callback() so that it
> displays relfilenode, forknum, and block number. What do you think?

I think that fully make sense to move this to rm_redo_error_callback().

This is where the information is now been displayed in the new attached
patch.

>
> ---
> + /* display wal record information */
> + if (log_recovery_conflicts)
> + LogBlockedWalRecordInfo(num_waitlist_entries, reason);
>
> I'm concerned that we should log the recovery conflict information
> every time when a recovery conflict happens from the perspective of
> overheads and the amount of the logs. Can we logs that information
> after waiting for deadlock_timeouts secs like log_lock_waits or
> waiting for the fixed duration?

The new attached patch is now waiting for deadlock_timeout duration.

>
> ---
> @@ -609,6 +682,10 @@ StandbyTimeoutHandler(void)
> /* forget any pending STANDBY_DEADLOCK_TIMEOUT request */
> disable_timeout(STANDBY_DEADLOCK_TIMEOUT, false);
>
> + /* display wal record information */
> + if (log_recovery_conflicts)
> + LogBlockedWalRecordInfo(-1,
> PROCSIG_RECOVERY_CONFLICT_BUFFERPIN);
> +
> SendRecoveryConflictWithBufferPin(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN);
> }
>
> ResolveRecoveryConflictWithBufferPin() which sets a timer to call
> StandbyTimeoutHandler() can be called multiple times even if the
> recovery is waiting for one buffer pin. I think we should avoid
> logging the same contents multiple times.

I do agree, only the first pass is now been logged.

>
> ---
> -
> + {
> + {"log_recovery_conflicts", PGC_SUSET, LOGGING_WHAT,
> + gettext_noop("Logs standby recovery conflicts."),
> + NULL
> + },
> + &log_recovery_conflicts,
> + true,
> + NULL, NULL, NULL
> + },
>
> Other logging parameters such as log_lock_waits is false by default. I
> think this parameter can also be false by default but is there any
> reason to enable it by default?

now set to false by default.

>
> Since this parameter applies only to the startup process, I think it
> should be PGC_SIGHUP.

changed that way.

>
> ---
> + /* display wal record information */
> + if (log_recovery_conflicts)
> + LogBlockedWalRecordInfo(CountDBBackends(dbid),
> PROCSIG_RECOVERY_CONFLICT_DATABASE);
>
> We log the recovery conflict into the server log but we don't update
> the process title to append "waiting". While discussing the process
> title update on recovery conflict, I got the review comment[1] that we
> don't need to update the process title because no wait occurs when
> recovery conflict with database happens. As the comment says, recovery
> is canceling the existing processes on the database being removed, but
> not waiting for something.

Ok, I keep reporting the conflict but changed the wording for this
particular case.

Thanks

Bertrand