Re: standby apply lag on inactive servers

On 2020-Jan-28, Kyotaro Horiguchi wrote:

> At Mon, 27 Jan 2020 18:06:27 -0300, Alvaro Herrera <alvherre(at)2ndquadrant(dot)com> wrote in
> > Actually looking again, getRecordTimestamp is looking pretty strange.
> > It looks much more natural by using nested switch/case blocks, as with
> > this diff. I think the compiler does a better job this way too.
>
> Agreed. Anyway I looked the latest version.
>
> The aim of the patch seem reasonable. XLOG_END_OF_RECOVERY and
> XLOG_XACT_PREPARE also have a timestamp but it doesn't help much. (But
> could be included for consistency.)

Hello, thanks for looking.

> The timestamp of a checkpoint record is the start time of a checkpoint
> (and doesn't have subseconds part, but it's not a problem.). That
> means that the timestamp is usually far behind the time at the record
> has been inserted. As the result the stored timestamp can go back by a
> significant internval. I don't think that causes an actual problem but
> the movement looks wierd as the result of
> pg_last_xact_replay_timestamp().

Ouch ... yeah, it should be set only if it doesn't go backwards.

> xlog.c:7329: (similar code exists at line 9332)
> > ereport(LOG,
> > (errmsg("redo done at %X/%X",
> > (uint32) (ReadRecPtr >> 32), (uint32) ReadRecPtr)));
> > xtime = GetLatestXTime();
> > if (xtime)
> > ereport(LOG,
> > (errmsg("last completed transaction was at log time %s",
> > timestamptz_to_str(xtime))));
>
> This code assumes (and the name GetLatestXTime() suggests, I first
> noticed that here..) that the timestamp comes from commit/abort logs,
> so otherwise it shows a wrong timestamp. We shouldn't update the
> variable by other than that kind of records.

Hmm, that's terrible. GetLatestXTime() being displayed user-visibly for
"last transaction completion" but having it include unrelated things
such as restore points is terrible. One idea is to should split it in
two: one exclusively for transaction commit/abort, and another for all
WAL activity. That way, the former can be used for that message, and
the latter for standby replay reports. However, that might be
overengineering, if the only thing that the former is that one LOG
message; instead changing the log message to state that the time is for
other activity, as you suggest, is simpler and has no downside that I
can see.

--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services