Horton

Thread

Commits

  1. Log the correct ending timestamp in recovery_target_xid mode.

  1. minor bug

    Torsten Förtsch <tfoertsch123@gmail.com> — 2023-01-16T18:59:33Z

    Hi,

not sure if this is known behavior.

Server version is 14.6 (Debian 14.6-1.pgdg110+1).

In a PITR setup I have these settings:

recovery_target_xid = '852381'
recovery_target_inclusive = 'false'

In the log file I see this message:

LOG:  recovery stopping before commit of transaction 852381, time
2000-01-01 00:00:00+00

But:

postgres=# select * from pg_last_committed_xact();
  xid   |           timestamp           | roident
--------+-------------------------------+---------
 852380 | 2023-01-16 18:00:35.054495+00 |       0

So, the timestamp displayed in the log message is certainly wrong.

Thanks,
Torsten

  2. Re: minor bug

    Laurenz Albe <laurenz.albe@cybertec.at> — 2023-01-17T09:42:03Z

    On Mon, 2023-01-16 at 19:59 +0100, Torsten Förtsch wrote:
> not sure if this is known behavior.
> 
> Server version is 14.6 (Debian 14.6-1.pgdg110+1).
> 
> In a PITR setup I have these settings:
> 
> recovery_target_xid = '852381'
> recovery_target_inclusive = 'false'
> 
> In the log file I see this message:
> 
> LOG:  recovery stopping before commit of transaction 852381, time 2000-01-01 00:00:00+00
> 
> But:
> 
> postgres=# select * from pg_last_committed_xact();
>   xid   |           timestamp           | roident 
> --------+-------------------------------+---------
>  852380 | 2023-01-16 18:00:35.054495+00 |       0
> 
> So, the timestamp displayed in the log message is certainly wrong.

Redirected to -hackers.

If recovery stops at a WAL record that has no timestamp, you get this
bogus recovery stop time.  I think we should show the recovery stop time
only if time was the target, as in the attached patch.

Yours,
Laurenz Albe

  3. Re: minor bug

    Michael Paquier <michael@paquier.xyz> — 2023-01-17T10:12:33Z

    On Tue, Jan 17, 2023 at 10:42:03AM +0100, Laurenz Albe wrote:
> If recovery stops at a WAL record that has no timestamp, you get this
> bogus recovery stop time.  I think we should show the recovery stop time
> only if time was the target, as in the attached patch.

Good catch!  I'll try to take a look.
--
Michael

  4. Re: minor bug

    Tom Lane <tgl@sss.pgh.pa.us> — 2023-01-17T15:32:50Z

    Laurenz Albe <laurenz.albe@cybertec.at> writes:
> On Mon, 2023-01-16 at 19:59 +0100, Torsten Förtsch wrote:
>> So, the timestamp displayed in the log message is certainly wrong.

> If recovery stops at a WAL record that has no timestamp, you get this
> bogus recovery stop time.  I think we should show the recovery stop time
> only if time was the target, as in the attached patch.

I don't think that is a tremendously useful definition: the user
already knows what recoveryStopTime is, or can find it out from
their settings easily enough.

I seem to recall that the original idea was to report the timestamp
of the commit/abort record we are stopping at.  Maybe my memory is
faulty, but I think that'd be significantly more useful than the
current behavior, *especially* when the replay stopping point is
defined by something other than time.

(Also, the wording of the log message suggests that that's what
the reported time is supposed to be.  I wonder if somebody messed
this up somewhere along the way.)

			regards, tom lane

  5. Re: minor bug

    Laurenz Albe <laurenz.albe@cybertec.at> — 2023-01-18T08:27:02Z

    On Tue, 2023-01-17 at 10:32 -0500, Tom Lane wrote:
> Laurenz Albe <laurenz.albe@cybertec.at> writes:
> > On Mon, 2023-01-16 at 19:59 +0100, Torsten Förtsch wrote:
> > > So, the timestamp displayed in the log message is certainly wrong.
> 
> > If recovery stops at a WAL record that has no timestamp, you get this
> > bogus recovery stop time.  I think we should show the recovery stop time
> > only if time was the target, as in the attached patch.
> 
> I don't think that is a tremendously useful definition: the user
> already knows what recoveryStopTime is, or can find it out from
> their settings easily enough.
> 
> I seem to recall that the original idea was to report the timestamp
> of the commit/abort record we are stopping at.  Maybe my memory is
> faulty, but I think that'd be significantly more useful than the
> current behavior, *especially* when the replay stopping point is
> defined by something other than time.
> 
> (Also, the wording of the log message suggests that that's what
> the reported time is supposed to be.  I wonder if somebody messed
> this up somewhere along the way.)

recoveryStopTime is set to recordXtime (the time of the xlog record)
a few lines above that patch, so this is useful information if it is
present.

I realized that my original patch might be a problem for translation;
here is an updated version that does not take any shortcuts.

Yours,
Laurenz Albe

  6. Re: minor bug

    Tom Lane <tgl@sss.pgh.pa.us> — 2023-01-18T20:03:38Z

    Laurenz Albe <laurenz.albe@cybertec.at> writes:
> On Tue, 2023-01-17 at 10:32 -0500, Tom Lane wrote:
>> I seem to recall that the original idea was to report the timestamp
>> of the commit/abort record we are stopping at.  Maybe my memory is
>> faulty, but I think that'd be significantly more useful than the
>> current behavior, *especially* when the replay stopping point is
>> defined by something other than time.
>> (Also, the wording of the log message suggests that that's what
>> the reported time is supposed to be.  I wonder if somebody messed
>> this up somewhere along the way.)

> recoveryStopTime is set to recordXtime (the time of the xlog record)
> a few lines above that patch, so this is useful information if it is
> present.

Ah, but that only happens if recoveryTarget == RECOVERY_TARGET_TIME.
Digging in the git history, I see that this did use to work as
I remember: we always extracted the record time before printing it.
That was accidentally broken in refactoring in c945af80c.  I think
the correct fix is more like the attached.

			regards, tom lane

  7. Re: minor bug

    Laurenz Albe <laurenz.albe@cybertec.at> — 2023-01-19T12:57:14Z

    On Wed, 2023-01-18 at 15:03 -0500, Tom Lane wrote:
> Laurenz Albe <laurenz.albe@cybertec.at> writes:
> > On Tue, 2023-01-17 at 10:32 -0500, Tom Lane wrote:
> > > I seem to recall that the original idea was to report the timestamp
> > > of the commit/abort record we are stopping at.  Maybe my memory is
> > > faulty, but I think that'd be significantly more useful than the
> > > current behavior, *especially* when the replay stopping point is
> > > defined by something other than time.
> > > (Also, the wording of the log message suggests that that's what
> > > the reported time is supposed to be.  I wonder if somebody messed
> > > this up somewhere along the way.)
> 
> > recoveryStopTime is set to recordXtime (the time of the xlog record)
> > a few lines above that patch, so this is useful information if it is
> > present.
> 
> Ah, but that only happens if recoveryTarget == RECOVERY_TARGET_TIME.
> Digging in the git history, I see that this did use to work as
> I remember: we always extracted the record time before printing it.
> That was accidentally broken in refactoring in c945af80c.  I think
> the correct fix is more like the attached.

Yes, you are right.  Your patch looks fine to me.

Yours,
Laurenz Albe

  8. Re: minor bug

    Torsten Förtsch <tfoertsch123@gmail.com> — 2023-01-19T17:18:04Z

    If we never expect getRecordTimestamp to fail, then why put it in the
if-condition?

getRecordTimestamp can fail if the record is not a restore point nor a
commit or abort record. A few lines before in the same function there is
this:

 /* Otherwise we only consider stopping before COMMIT or ABORT records. */
if (XLogRecGetRmid(record) != RM_XACT_ID)
    return false;

I guess that make sure getRecordTimestamp can never fail.

The way it is written in your patch invites it to be optimized out again.
The only thing that prevents it is the comment.

Why not

(void)getRecordTimestamp(record, &recordXtime);
if (recoveryTarget == RECOVERY_TARGET_TIME)
...




On Wed, Jan 18, 2023 at 9:03 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

> Laurenz Albe <laurenz.albe@cybertec.at> writes:
> > On Tue, 2023-01-17 at 10:32 -0500, Tom Lane wrote:
> >> I seem to recall that the original idea was to report the timestamp
> >> of the commit/abort record we are stopping at.  Maybe my memory is
> >> faulty, but I think that'd be significantly more useful than the
> >> current behavior, *especially* when the replay stopping point is
> >> defined by something other than time.
> >> (Also, the wording of the log message suggests that that's what
> >> the reported time is supposed to be.  I wonder if somebody messed
> >> this up somewhere along the way.)
>
> > recoveryStopTime is set to recordXtime (the time of the xlog record)
> > a few lines above that patch, so this is useful information if it is
> > present.
>
> Ah, but that only happens if recoveryTarget == RECOVERY_TARGET_TIME.
> Digging in the git history, I see that this did use to work as
> I remember: we always extracted the record time before printing it.
> That was accidentally broken in refactoring in c945af80c.  I think
> the correct fix is more like the attached.
>
>                         regards, tom lane
>
>

  9. Re: minor bug

    Tom Lane <tgl@sss.pgh.pa.us> — 2023-01-19T17:25:18Z

    Laurenz Albe <laurenz.albe@cybertec.at> writes:
> On Wed, 2023-01-18 at 15:03 -0500, Tom Lane wrote:
>> Ah, but that only happens if recoveryTarget == RECOVERY_TARGET_TIME.
>> Digging in the git history, I see that this did use to work as
>> I remember: we always extracted the record time before printing it.
>> That was accidentally broken in refactoring in c945af80c.  I think
>> the correct fix is more like the attached.

> Yes, you are right.  Your patch looks fine to me.

Pushed then.  Thanks for the report!

			regards, tom lane

  10. Re: minor bug

    Tom Lane <tgl@sss.pgh.pa.us> — 2023-01-19T17:29:53Z

    =?UTF-8?Q?Torsten_F=C3=B6rtsch?= <tfoertsch123@gmail.com> writes:
> Why not

> (void)getRecordTimestamp(record, &recordXtime);
> if (recoveryTarget == RECOVERY_TARGET_TIME)
> ...

Could've done it like that, but I already pushed the other
version, and I don't think it's worth the trouble to change.

			regards, tom lane