Обсуждение: BUG #11032: Prepared transactions do not update pg_last_xact_replay_timestamp() anymore

The following bug has been logged on the website:

Bug reference:      11032
Logged by:          Sergiy Zuban
Email address:      s.zuban@gmail.com
PostgreSQL version: 9.3.5
Operating system:   Linux
Description:

After upgrade from 9.3.4 to 9.3.5 pg_last_xact_replay_timestamp() returns
outdated timestamp.

It stopped working properly after commit
d19bd29f07aef9e508ff047d128a4046cc8bc1e2

COMMIT PREPARED should update transaction timestamp, but it doesn't seem to
happen.

s.zuban@gmail.com writes:
> After upgrade from 9.3.4 to 9.3.5 pg_last_xact_replay_timestamp() returns
> outdated timestamp.

> It stopped working properly after commit
> d19bd29f07aef9e508ff047d128a4046cc8bc1e2

Really?

It looks to me like this never worked: the code around recoveryStopsHere
has never paid any attention to COMMIT_PREPARED (or ABORT_PREPARED).
Certainly that patch had zip to do with the replay-timestamp behavior.

If you think it worked before, I'd like to see what your test case was.

            regards, tom lane

On 2014-07-24 17:46:13 -0400, Tom Lane wrote:
> s.zuban@gmail.com writes:
> > After upgrade from 9.3.4 to 9.3.5 pg_last_xact_replay_timestamp() returns
> > outdated timestamp.
>
> > It stopped working properly after commit
> > d19bd29f07aef9e508ff047d128a4046cc8bc1e2
>
> Really?
>
> It looks to me like this never worked: the code around recoveryStopsHere
> has never paid any attention to COMMIT_PREPARED (or ABORT_PREPARED).
> Certainly that patch had zip to do with the replay-timestamp behavior.
>
> If you think it worked before, I'd like to see what your test case was.

I wonder if this is possibly influenced by
bb38fb0d43c8d7ff54072bfd8bd63154e536b384. IIRC before it committing a
prepared xact caused a plain commit record for the xid doing the COMMIT
PREPARED.

Greetings,

Andres Freund

--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

Andres Freund <andres@2ndquadrant.com> writes:
> On 2014-07-24 17:46:13 -0400, Tom Lane wrote:
>> It looks to me like this never worked: the code around recoveryStopsHere
>> has never paid any attention to COMMIT_PREPARED (or ABORT_PREPARED).

> I wonder if this is possibly influenced by
> bb38fb0d43c8d7ff54072bfd8bd63154e536b384. IIRC before it committing a
> prepared xact caused a plain commit record for the xid doing the COMMIT
> PREPARED.

Hm, I see nothing in that commit that looks like it would've changed
what gets written to WAL (and if it did, we have a serious minor version
compatibility issue).  OTOH, if it did, that would explain the
complaint of a behavioral change since the last minor releases.

            regards, tom lane

On 2014-07-24 18:32:09 -0400, Tom Lane wrote:
> Andres Freund <andres@2ndquadrant.com> writes:
> > On 2014-07-24 17:46:13 -0400, Tom Lane wrote:
> >> It looks to me like this never worked: the code around recoveryStopsHere
> >> has never paid any attention to COMMIT_PREPARED (or ABORT_PREPARED).
>
> > I wonder if this is possibly influenced by
> > bb38fb0d43c8d7ff54072bfd8bd63154e536b384. IIRC before it committing a
> > prepared xact caused a plain commit record for the xid doing the COMMIT
> > PREPARED.
>
> Hm, I see nothing in that commit that looks like it would've changed
> what gets written to WAL (and if it did, we have a serious minor version
> compatibility issue).  OTOH, if it did, that would explain the
> complaint of a behavioral change since the last minor releases.

Afaics before the commit a LockGXact() did a GetTopTransactionId(),
afterwards it doesn't anymore. That'd fit, right?

Greetings,

Andres Freund

--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

Andres Freund <andres@2ndquadrant.com> writes:
> Afaics before the commit a LockGXact() did a GetTopTransactionId(),
> afterwards it doesn't anymore. That'd fit, right?

Ah, I think you've got it.  Now I'm worried.  I have a very vague
recollection that that behavior (forcing our own COMMIT to be written
after a COMMIT PREPARED) was intentional.  I don't recall exactly
why though.

xact.h points out

/*
 * COMMIT_PREPARED and ABORT_PREPARED are identical to COMMIT/ABORT records
 * except that we have to store the XID of the prepared transaction explicitly
 * --- the XID in the record header will be for the transaction doing the
 * COMMIT PREPARED or ABORT PREPARED command.
 */

and what this change means is that there isn't actually any valid XID in
the record header, which at least means that comment needs an update.
But I'm concerned about the knock-on aspects of that.  In particular
I wonder if we were expecting commit of the surrounding transaction to
result in a WAL flush or anything like that.  The proposal you made
recently to not sync non-XID-assigning WAL records would affect this.

As far as the timestamp aspects go, I wonder if we were thinking that
commit/abort prepared might contain stale timestamps by design.  They
don't --- in the current coding, the timestamp is the time of creating the
WAL record, not of the prepare --- but it's not that hard to imagine that
time-of-prepare might have been the original intent.

            regards, tom lane

Prior to this change probably it was working not properly in 100% of cases
(timestamp was updated even if prepared transaction wasn't committed yet?),
but still it was a good way to check replication delay and it worked. Now
pg_last_xact_replay_timestamp() is useless for such purpose and I hope you
can fix this in next minor release.

--
Sergiy Zuban


On Thu, Jul 24, 2014 at 4:46 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

> s.zuban@gmail.com writes:
> > After upgrade from 9.3.4 to 9.3.5 pg_last_xact_replay_timestamp() returns
> > outdated timestamp.
>
> > It stopped working properly after commit
> > d19bd29f07aef9e508ff047d128a4046cc8bc1e2
>
> Really?
>
> It looks to me like this never worked: the code around recoveryStopsHere
> has never paid any attention to COMMIT_PREPARED (or ABORT_PREPARED).
> Certainly that patch had zip to do with the replay-timestamp behavior.
>
> If you think it worked before, I'd like to see what your test case was.
>
>                         regards, tom lane
>

On 07/25/2014 01:50 AM, Tom Lane wrote:
> Andres Freund <andres@2ndquadrant.com> writes:
>> Afaics before the commit a LockGXact() did a GetTopTransactionId(),
>> afterwards it doesn't anymore. That'd fit, right?
>
> Ah, I think you've got it.

Yep. The extra commit record masked the issue that getRecordTimestamp()
ignores commit/abort prepared records.

>  Now I'm worried.  I have a very vague
> recollection that that behavior (forcing our own COMMIT to be written
> after a COMMIT PREPARED) was intentional.  I don't recall exactly
> why though.

Hmm. I've always considered it just a quirk that we didn't bother to fix
when two-phase commit was implemented, because it would've required more
invasive code changes. But the code has since moved on - not all
transactions are assigned an XID anymore - and now it was
straightforward to fix that quirk.

It wouldn't surprise me much though, if we find more little things like
this that were previously masked by the extra commit record:

At a quick glance, the recovery_min_apply_delay code in xlog.c seems to
be oblivious of prepared transactions. Now that we no longer write the
normal COMMIT record after a COMMIT_PREPARED record, that's become
worse, but it was always wrong. The COMMIT_PREPARED record would always
be applied immediately, regardless of recovery_min_apply_delay, although
we would then pause at the commit record that follows. The
recovery_target_xid handling also ignores prepared transactions.

> xact.h points out
>
> /*
>   * COMMIT_PREPARED and ABORT_PREPARED are identical to COMMIT/ABORT records
>   * except that we have to store the XID of the prepared transaction explicitly
>   * --- the XID in the record header will be for the transaction doing the
>   * COMMIT PREPARED or ABORT PREPARED command.
>   */
>
> and what this change means is that there isn't actually any valid XID in
> the record header, which at least means that comment needs an update.
> But I'm concerned about the knock-on aspects of that.  In particular
> I wonder if we were expecting commit of the surrounding transaction to
> result in a WAL flush or anything like that.  The proposal you made
> recently to not sync non-XID-assigning WAL records would affect this.

RecordTransactionCommitPrepared calls XLogFlush() and
SyncRepWaitForLSN(), so those particular things are covered.

We probably should set XLogRecord->xl_xid in COMMIT_/ABORT_PREPARED
records though. It seems weird not to, and it would simplify code that
interprets those records. But I don't think we should back-patch that.

> As far as the timestamp aspects go, I wonder if we were thinking that
> commit/abort prepared might contain stale timestamps by design.  They
> don't --- in the current coding, the timestamp is the time of creating the
> WAL record, not of the prepare --- but it's not that hard to imagine that
> time-of-prepare might have been the original intent.

Time-of-commit makes much more sense to me. The transaction doesn't
appear as committed to other transactions until it's committed,
regardless of when it prepared.

It surprises me that there is no timestamp at all in the prepare-record
though. That could be very useful information, if you wanted to monitor
the delay between prepare and commit, for example. But that's another issue.

I propose the attached (untested) patch that fixes the issues mentioned
this far. I'll set up streaming replication and test
recovery_target_xid, recovery_min_apply_delay, and
pg_last_xact_replay_timestamp() with the patch, and barring
objections/bugs, commit and backpatch. For master branch, I'll
investigate how hacky it would be to set XLogRecord->xl_xid to the XID
of the prepared transaction.

- Heikki

On 2014-07-28 13:05:13 +0300, Heikki Linnakangas wrote:
> We probably should set XLogRecord->xl_xid in COMMIT_/ABORT_PREPARED records
> though. It seems weird not to, and it would simplify code that interprets
> those records. But I don't think we should back-patch that.

I doubt that'd be a net improvement - wouldn't that just make the life
of anything tracking xid liveliness a bit more complicated?

Greetings,

Andres Freund

--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On 07/28/2014 05:17 PM, Andres Freund wrote:
> On 2014-07-28 13:05:13 +0300, Heikki Linnakangas wrote:
>> We probably should set XLogRecord->xl_xid in COMMIT_/ABORT_PREPARED records
>> though. It seems weird not to, and it would simplify code that interprets
>> those records. But I don't think we should back-patch that.
>
> I doubt that'd be a net improvement - wouldn't that just make the life
> of anything tracking xid liveliness a bit more complicated?

How so?

- Heikki

On 2014-07-28 20:58:25 +0300, Heikki Linnakangas wrote:
> On 07/28/2014 05:17 PM, Andres Freund wrote:
> >On 2014-07-28 13:05:13 +0300, Heikki Linnakangas wrote:
> >>We probably should set XLogRecord->xl_xid in COMMIT_/ABORT_PREPARED records
> >>though. It seems weird not to, and it would simplify code that interprets
> >>those records. But I don't think we should back-patch that.
> >
> >I doubt that'd be a net improvement - wouldn't that just make the life
> >of anything tracking xid liveliness a bit more complicated?
>
> How so?

Nothing super concrete. Doesn't feel entirely right ;): It's imo
confusing if records for the same xid are possibly created by two
different backends and that there suddenly can be an additional WAL
record referring to the xid after it's been prepared.

Greetings,

Andres Freund

--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On 07/28/2014 01:05 PM, Heikki Linnakangas wrote:
> I propose the attached (untested) patch that fixes the issues mentioned
> this far.

Committed and backpatched.

- Heikki