Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message

From: Bharath Rupireddy <[email-masked]>
Date: Tue, 1 Feb 2022 18:33:24 +0530

On Tue, Feb 1, 2022 at 11:58 AM Kyotaro Horiguchi
<[email-masked]> wrote:
> > Modified in v8.
> 0001 looks good to me.
> I tend to agree to 0002.

Thanks.

> FWIW, I collected other user-facing usage of "location" as LSN.
>
> xlog.c:11298, 11300:  (in backup-label)
>   appendStringInfo(labelfile, "START WAL LOCATION: %X/%X (file %s)\n",
>   appendStringInfo(labelfile, "CHECKPOINT LOCATION: %X/%X\n",
>   (and corresponding reader-code)
>
> xlog,c:11791, 11793:  (in backup history file)
>   fprintf(fp, "START WAL LOCATION: %X/%X (file %s)\n",
>   fprintf(fp, "STOP WAL LOCATION: %X/%X (file %s)\n",
>   (and corresponding reader-code)

I tried to change the "location" to "lsn" in most of the user-facing
messages/text. I refrained from changing the bakup_label file content
(above) as it might break many applications/service layer code and
it's not good for backward compatibility.

Attaching the above changes 0003 (0001 and 0002 remain the same). If
the committer doesn't agree on the text or wording in 0003, I would
like the 0001 and 0002 to be taken here and I can start a new thread
for discussing 0003 separately.

Regards,
Bharath Rupireddy.

---

From: Fujii Masao <[email-masked]>
Date: Wed, 2 Feb 2022 01:09:43 +0900

> <[email-masked]> wrote:

I found that CreateRestartPoint() already reported the redo lsn as follows after emitting the restartpoint log message. To avoid duplicated logging of the same information, we should update this code?

	ereport((log_checkpoints ? LOG : DEBUG2),
			(errmsg("recovery restart point at %X/%X",
					LSN_FORMAT_ARGS(lastCheckPoint.redo)),
			 xtime ? errdetail("Last completed transaction was at log time %s.",
							   timestamptz_to_str(xtime)) : 0));

This code reports lastCheckPoint.redo as redo lsn. OTOH, with the patch, LogCheckpointEnd() reports ControlFile->checkPointCopy.redo. They may be different, for example, when the current DB state is not DB_IN_ARCHIVE_RECOVERY. In this case, which lsn should we report as redo lsn?

+						"lsn=%X/%X, redo lsn=%X/%X",

Originally you proposed to use upper cases for "lsn". But the latest patch uses the lower cases. Why? It seems better to use upper cases, i.e., LSN and REDO LSN because LSN is basically used in other errmsg().

> for discussing 0003 separately.

Personally I'm ok with 001, but regarding 0002 and 0003 patches, I'm not sure if it's really worth replacing "location" with "lsn" there. BTW, the similar idea was proposed at [1] before, but seems "location" was left as it was.

[1]
https://postgr.es/m/[email-masked]

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

---

From: Stephen Frost <[email-masked]>
Date: Tue, 1 Feb 2022 16:05:38 -0500

Greetings,

> Originally you proposed to use upper cases for "lsn". But the latest patch uses the lower cases. Why? It seems better to use upper cases, i.e., LSN and REDO LSN because LSN is basically used in oth…

We do use 'lsn=' quite a bit in verify_nbtree.c already and lowercase is
also what's in the various functions and views in the catalog in the
database, of course.  I don't see even one usage of "LSN=" in the tree
today.  We also use 'lsn %X/%X' in replorigindesc.c, xactdesc.c,
xactdesc.c, tablesync.c, standby.c, parsexlog.c, then 'redo %X/%X' in
xactdesc.c.

xlog.c does have a number of "WAL location (LSN)", along with a bunch of
other usages.  logical.c uses both "LSN" and "lsn".  worker.c uses
"LSN".  slot.c uses "restart_lsn". pg_rewind.c uses "WAL location" while
pg_waldump.c uses, "lsn:", "WAL location", and "WAL record".

Overall, we don't seem to be super consistent, but I'd say that 'lsn='
looks the best, to my eyes anyway, and isn't out of place in the code
base.  Lowercase seems to generally be more common overall. 

> https://postgr.es/m/[email-masked]

This discussion strikes me as sufficient reason to make the change, with
the prior comment not really having all that much weight.  When we're
actually pretty consistent with one term, having random places where we
are inconsistent leads people to be unsure about which way to go and
then we end up having to have this discussion.  Would be great to avoid
having to have it again in the future.

Thanks,

Stephen

---

From: Bharath Rupireddy <[email-masked]>
Date: Wed, 2 Feb 2022 20:16:35 +0530

> This code reports lastCheckPoint.redo as redo lsn. OTOH, with the patch, LogCheckpointEnd() reports ControlFile->checkPointCopy.redo. They may be different, for example, when the current DB state i…

Do we ever reach CreateRestartPoint when ControlFile->stat !=
DB_IN_ARCHIVE_RECOVERY? Assert(ControlFile->state ==
DB_IN_ARCHIVE_RECOVERY); in CreateRestartPoint doesn't fail any
regression tests.

Here's what can happen:
lastCheckPoint.redo is 100 and ControlFile->checkPointCopy.redo is
105, so, "skipping restartpoint, already performed at %X/%X"
LogCheckpointEnd isn't reached
lastCheckPoint.redo is 105 and ControlFile->checkPointCopy.redo is 100
and ControlFile->state == DB_IN_ARCHIVE_RECOVERY, then the control
file gets updated and LogCheckpointEnd prints the right redo lsn.
lastCheckPoint.redo is 105 and ControlFile->checkPointCopy.redo is 100
and ControlFile->state != DB_IN_ARCHIVE_RECOVERY, the the control file
doesn't get updated and LogCheckpointEnd just prints the control redo
lsn. Looks like this case is rare given Assert(ControlFile->state ==
DB_IN_ARCHIVE_RECOVERY); doesn't fail any tests.

I think we should just let LogCheckpointEnd print the redo lsn from
the control file. We can just remove the above errmsg("recovery
restart point at %X/%X" message altogether or just print it only in
the rare scenario, something like below:

if (ControlFile->state != DB_IN_ARCHIVE_RECOVERY)
{
    ereport((log_checkpoints ? LOG : DEBUG2),
            (errmsg("performed recovery restart point at %X/%X while
the database state is %s",
                    LSN_FORMAT_ARGS(lastCheckPoint.redo)),
getDBState(ControlFile->state)));
}

And the last commit/abort records's timestamp will always get logged
even before we reach here in the main redo loop (errmsg("last
completed transaction was at log time %s").

Or another way is to just pass the redo lsn to LogCheckpointEnd and
pass the lastCheckPoint.redo in if (ControlFile->state !=
DB_IN_ARCHIVE_RECOVERY) cases or when control file isn't updated but
restart point happened.

Thoughts?

Regards,
Bharath Rupireddy.

---

From: Fujii Masao <[email-masked]>
Date: Thu, 3 Feb 2022 13:59:03 +0900

> DB_IN_ARCHIVE_RECOVERY); in CreateRestartPoint doesn't fail any

ISTM that CreateRestartPoint() can reach the condition ControlFile->state != DB_IN_ARCHIVE_RECOVERY. Please imagine the case where CreateRestartPoint() has already started and calls CheckPointGuts(). If the standby server is promoted while CreateRestartPoint() is flushing the data to disk at CheckPointGuts(), the state would be updated to DB_IN_PRODUCTION and CreateRestartPoint() can see the state != DB_IN_ARCHIVE_RECOVERY later.

As far as I read the code, this case seems to be able to make the server unrecoverable. If this case happens, since pg_control is not updated, pg_control still indicates the REDO LSN of last valid restartpoint. But CreateRestartPoint() seems to delete old WAL files based on its "current" REDO LSN not pg_control's REDO LSN. That is, WAL files required for the crash recovery starting from pg_control's REDO LSN would be removed.

If this understanding is right, to address this issue, probably we need to make CreateRestartPoint() do nothing (return immediately) when the state != DB_IN_ARCHIVE_RECOVERY?

Regards,