MIME-Version: 1.0
References: <CALj2ACXDHGfhKkwzi81BRqWft4n85AO1zmkeqf6xEg+0xTCH9g@mail.gmail.com>
 <a1de2fd3-4a88-0325-c698-580c044f38b2@oss.nttdata.com> <CALj2ACU9ynpCwfuL0a4Bx0SDbHcjRDk49pwjDwfOzoQ1-kx1pw@mail.gmail.com>
 <20220201.152756.1157327790387186473.horikyota.ntt@gmail.com>
 <CALj2ACUtZhTb=2ENkF3BQ3wi137uaGi__qzvXC-qFYC0XwjALw@mail.gmail.com> <be548399-4c5e-77a7-2a95-fad224f1d24d@oss.nttdata.com>
In-Reply-To: <be548399-4c5e-77a7-2a95-fad224f1d24d@oss.nttdata.com>
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Wed, 2 Feb 2022 20:16:35 +0530
Message-ID: <CALj2ACVVMAGDvourutDvtDUOhTqS_yTtfrdCjtP75-RrQU0dFA@mail.gmail.com>
Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message
To: Fujii Masao <masao.fujii@oss.nttdata.com>
Cc: Kyotaro Horiguchi <horikyota.ntt@gmail.com>, Nathan Bossart <nathandbossart@gmail.com>, 
	Stephen Frost <sfrost@snowman.net>, "Bossart, Nathan" <bossartn@amazon.com>, 
	Julien Rouhaud <rjuju123@gmail.com>, Michael Paquier <michael@paquier.xyz>, 
	PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: <https://www.postgresql.org/message-id/CALj2ACVVMAGDvourutDvtDUOhTqS_yTtfrdCjtP75-RrQU0dFA%40mail.gmail.com>
Precedence: bulk

On Tue, Feb 1, 2022 at 9:39 PM Fujii Masao <masao.fujii@oss.nttdata.com> wr=
ote:
> I found that CreateRestartPoint() already reported the redo lsn as follow=
s 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.re=
do)),
>                          xtime ? errdetail("Last completed transaction wa=
s 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 di=
fferent, for example, when the current DB state is not DB_IN_ARCHIVE_RECOVE=
RY. In this case, which lsn should we report as redo lsn?

Do we ever reach CreateRestartPoint when ControlFile->stat !=3D
DB_IN_ARCHIVE_RECOVERY? Assert(ControlFile->state =3D=3D
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 =3D=3D 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 !=3D 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 =3D=3D
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 !=3D 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 !=3D
DB_IN_ARCHIVE_RECOVERY) cases or when control file isn't updated but
restart point happened.

Thoughts?

Regards,
Bharath Rupireddy.