Thread: wal_consistency_checking reports an inconsistency on master branch

Running "make installcheck" with wal_consistency_checking='all' on the
master branch shows the follow failure on a streaming replica:

19696/2018-04-12 11:35:29 PDT FATAL:  inconsistent page found, rel
1663/50192/66636, forknum 0, blkno 0
19696/2018-04-12 11:35:29 PDT CONTEXT:  WAL redo at 2/6D8411F8 for
Heap/DELETE: off 4 KEYS_UPDATED
19695/2018-04-12 11:35:29 PDT LOG:  startup process (PID 19696) exited
with exit code 1
19695/2018-04-12 11:35:29 PDT LOG:  terminating any other active
server processes
19695/2018-04-12 11:35:29 PDT LOG:  database system is shut down

I can correlate it with this wal_debug output on the primary:

18713/2018-04-12 11:20:40 PDT ERROR:  new row violates check option
for view "upview"
18713/2018-04-12 11:20:40 PDT DETAIL:  Failing row contains (a, 4, 120, 1, 1).
18713/2018-04-12 11:20:40 PDT STATEMENT:  UPDATE upview set c = 120 WHERE b = 4;
18713/2018-04-12 11:20:40 PDT LOG:  INSERT @ 2/6D8411F8:  -
Transaction/ABORT: 2018-04-12 11:20:40.085145-07
18073/2018-04-12 11:20:40 PDT LOG:  xlog bg flush request write
2/6D840000; flush: 0/0, current is write 2/6D840000; flush 2/6D7B40B0
18713/2018-04-12 11:20:40 PDT LOG:  INSERT @ 2/6D841378:  -
Heap/DELETE: off 4 KEYS_UPDATED
18713/2018-04-12 11:20:40 PDT STATEMENT:  UPDATE upview set a = 'b', b
= 15, c = 120 WHERE b = 4;
18713/2018-04-12 11:20:40 PDT LOG:  INSERT @ 2/6D8415F0:  - Heap/INSERT: off 10
18713/2018-04-12 11:20:40 PDT STATEMENT:  UPDATE upview set a = 'b', b
= 15, c = 120 WHERE b = 4;
18713/2018-04-12 11:20:40 PDT ERROR:  new row violates check option
for view "upview"
18713/2018-04-12 11:20:40 PDT DETAIL:  Failing row contains (b, 15, 120, 1, 1).
18713/2018-04-12 11:20:40 PDT STATEMENT:  UPDATE upview set a = 'b', b
= 15, c = 120 WHERE b = 4;

In short, it looks like the tests added to update.sql by commit
2f178441 ("Allow UPDATE to move rows between partitions") lead to this
failure, since I always hit a problem when update.sql is reached. I
haven't gone to the trouble of digging any deeper than that just yet.

-- 
Peter Geoghegan

On Thu, Apr 12, 2018 at 11:47 AM, Peter Geoghegan <pg@bowt.ie> wrote:
> In short, it looks like the tests added to update.sql by commit
> 2f178441 ("Allow UPDATE to move rows between partitions") lead to this
> failure, since I always hit a problem when update.sql is reached. I
> haven't gone to the trouble of digging any deeper than that just yet.

Without having looked at it in much detail, this seems rather more
likely to be the fault of 2f178441. That was recent enough that it's
easy to believe that I'd be the first to notice it, and actually has
on-disk changes, in the form of ItemPointerSetMovedPartitions().

-- 
Peter Geoghegan

On Thu, Apr 12, 2018 at 03:36:12PM -0700, Peter Geoghegan wrote:
> Without having looked at it in much detail, this seems rather more
> likely to be the fault of 2f178441. That was recent enough that it's
> easy to believe that I'd be the first to notice it, and actually has
> on-disk changes, in the form of ItemPointerSetMovedPartitions().

Since f16241be the following comment has been added to heap_mask():
/*
 * NB: Not ignoring ctid changes due to the tuple having moved
 * (i.e. HeapTupleHeaderIndicatesMovedPartitions), because that's
 * important information that needs to be in-sync between primary
 * and standby, and thus is WAL logged.
 */

And actually, if you remove this query from update.sql, then the
consistency checks are able to finish:
UPDATE upview set c = 120 WHERE b = 4;

This triggers in the test suite a CHECK violation but this should not
result in a row being moved as even c is updated it would remain on the
same child partition so no rows are moved across partitions here.

Could this be pointing to an older issue?
--
Michael

On 2018/04/13 7:36, Peter Geoghegan wrote:
> On Thu, Apr 12, 2018 at 11:47 AM, Peter Geoghegan <pg@bowt.ie> wrote:
>> In short, it looks like the tests added to update.sql by commit
>> 2f178441 ("Allow UPDATE to move rows between partitions") lead to this
>> failure, since I always hit a problem when update.sql is reached. I
>> haven't gone to the trouble of digging any deeper than that just yet.
> 
> Without having looked at it in much detail, this seems rather more
> likely to be the fault of 2f178441. That was recent enough that it's
> easy to believe that I'd be the first to notice it, and actually has
> on-disk changes, in the form of ItemPointerSetMovedPartitions().

I think you meant f16241bef7cc2 (Raise error when affecting tuple moved
into different partition), because it's the one that adds
ItemPointerSetMovedPartitions.  Commit 2f178441 you quoted added the test
that triggered the failure.

Thanks,
Amit

On 2018-04-13 12:29:21 +0900, Amit Langote wrote:
> On 2018/04/13 7:36, Peter Geoghegan wrote:
> > On Thu, Apr 12, 2018 at 11:47 AM, Peter Geoghegan <pg@bowt.ie> wrote:
> >> In short, it looks like the tests added to update.sql by commit
> >> 2f178441 ("Allow UPDATE to move rows between partitions") lead to this
> >> failure, since I always hit a problem when update.sql is reached. I
> >> haven't gone to the trouble of digging any deeper than that just yet.
> > 
> > Without having looked at it in much detail, this seems rather more
> > likely to be the fault of 2f178441. That was recent enough that it's
> > easy to believe that I'd be the first to notice it, and actually has
> > on-disk changes, in the form of ItemPointerSetMovedPartitions().
> 
> I think you meant f16241bef7cc2 (Raise error when affecting tuple moved
> into different partition), because it's the one that adds
> ItemPointerSetMovedPartitions.  Commit 2f178441 you quoted added the test
> that triggered the failure.

Right. Amul, have you looked at this?

Greetings,

Andres Freund

On Fri, Apr 13, 2018 at 9:06 AM, Andres Freund <andres@anarazel.de> wrote:
> On 2018-04-13 12:29:21 +0900, Amit Langote wrote:
>> On 2018/04/13 7:36, Peter Geoghegan wrote:
>> > On Thu, Apr 12, 2018 at 11:47 AM, Peter Geoghegan <pg@bowt.ie> wrote:
>> >> In short, it looks like the tests added to update.sql by commit
>> >> 2f178441 ("Allow UPDATE to move rows between partitions") lead to this
>> >> failure, since I always hit a problem when update.sql is reached. I
>> >> haven't gone to the trouble of digging any deeper than that just yet.
>> >
>> > Without having looked at it in much detail, this seems rather more
>> > likely to be the fault of 2f178441. That was recent enough that it's
>> > easy to believe that I'd be the first to notice it, and actually has
>> > on-disk changes, in the form of ItemPointerSetMovedPartitions().
>>
>> I think you meant f16241bef7cc2 (Raise error when affecting tuple moved
>> into different partition), because it's the one that adds
>> ItemPointerSetMovedPartitions.  Commit 2f178441 you quoted added the test
>> that triggered the failure.
>
> Right. Amul, have you looked at this?
>

I have looked into this and found that the issue is in heap_xlog_delete -- we
have missed to set the correct offset number from the target_tid when
XLH_DELETE_IS_PARTITION_MOVE flag is set.

Please find the attached patch does the correction and a big thanks to
Peter for the bug report.

Regards,
Amul

On Fri, Apr 13, 2018 at 02:15:35PM +0530, amul sul wrote:
> I have looked into this and found that the issue is in heap_xlog_delete -- we
> have missed to set the correct offset number from the target_tid when
> XLH_DELETE_IS_PARTITION_MOVE flag is set.

Oh, this looks good to me.  So when a row was moved across partitions
this could have caused incorrect tuple references on a standby, which
could have caused corruptions.

wal_consistency_checking is proving to be worth its cost here...
--
Michael

On 2018/04/13 19:08, Michael Paquier wrote:
> On Fri, Apr 13, 2018 at 02:15:35PM +0530, amul sul wrote:
>> I have looked into this and found that the issue is in heap_xlog_delete -- we
>> have missed to set the correct offset number from the target_tid when
>> XLH_DELETE_IS_PARTITION_MOVE flag is set.
> 
> Oh, this looks good to me.  So when a row was moved across partitions
> this could have caused incorrect tuple references on a standby, which
> could have caused corruptions.
> 
> wal_consistency_checking is proving to be worth its cost here...

+1

Thanks,
Amit

On 13/04/18 13:08, Michael Paquier wrote:
> On Fri, Apr 13, 2018 at 02:15:35PM +0530, amul sul wrote:
>> I have looked into this and found that the issue is in heap_xlog_delete -- we
>> have missed to set the correct offset number from the target_tid when
>> XLH_DELETE_IS_PARTITION_MOVE flag is set.
> 
> Oh, this looks good to me.  So when a row was moved across partitions
> this could have caused incorrect tuple references on a standby, which
> could have caused corruptions.

Hmm. So, the problem was that HeapTupleHeaderSetMovedPartitions() only 
sets the block number to InvalidBlockNumber, and leaves the offset 
number unchanged. WAL replay didn't preserve the offset number, so the 
master and the standby had a different offset number in the ctid.

Why does HeapTupleHeaderSetMovedPartitions() leave the offset number 
unchanged? The old offset number is meaningless without the block 
number. Also, bits and magic values in the tuple header are scarce. 
We're squandering a whole range of values in the ctid, everything with 
ip_blkid==InvalidBlockNumber, to mean "moved to different partition", 
when a single value would suffice.

Let's tighten that up. In the attached (untested) patch, I changed the 
macros so that "moved to different partition" is indicated by the magic 
TID (InvalidBlockNumber, 0xfffd). Offset number 0xfffe was already used 
for speculative insertion tokens, so this follows that precedent.

I kept using InvalidBlockNumber there, so ItemPointerIsValid() still 
considers those item pointers as invalid. But my gut feeling is actually 
that it would be better to use e.g. 0 as the block number, so that these 
item pointers would appear valid. Again, to follow the precedent of 
speculative insertion tokens. But I'm not sure if there was some 
well-thought-out reason to make them appear invalid. A comment on that 
would be nice, at least.

(Amit hinted at this in 
https://www.postgresql.org/message-id/CAA4eK1KtsTqsGDggDCrz2O9Jgo7ma-Co-B8%2Bv3L2zWMA2NHm6A%40mail.gmail.com. 
He was OK with the current approach, but I feel pretty strongly that we 
should also set the offset number.)

- Heikki

On 2018-04-23 13:22:21 +0300, Heikki Linnakangas wrote:
> On 13/04/18 13:08, Michael Paquier wrote:
> > On Fri, Apr 13, 2018 at 02:15:35PM +0530, amul sul wrote:
> > > I have looked into this and found that the issue is in heap_xlog_delete -- we
> > > have missed to set the correct offset number from the target_tid when
> > > XLH_DELETE_IS_PARTITION_MOVE flag is set.
> > 
> > Oh, this looks good to me.  So when a row was moved across partitions
> > this could have caused incorrect tuple references on a standby, which
> > could have caused corruptions.
> 
> Hmm. So, the problem was that HeapTupleHeaderSetMovedPartitions() only sets
> the block number to InvalidBlockNumber, and leaves the offset number
> unchanged. WAL replay didn't preserve the offset number, so the master and
> the standby had a different offset number in the ctid.

Right.

> Why does HeapTupleHeaderSetMovedPartitions() leave the offset number
> unchanged? The old offset number is meaningless without the block number.
> Also, bits and magic values in the tuple header are scarce. We're
> squandering a whole range of values in the ctid, everything with
> ip_blkid==InvalidBlockNumber, to mean "moved to different partition", when a
> single value would suffice.

Yes, I agree on that.


> I kept using InvalidBlockNumber there, so ItemPointerIsValid() still
> considers those item pointers as invalid. But my gut feeling is actually
> that it would be better to use e.g. 0 as the block number, so that these
> item pointers would appear valid. Again, to follow the precedent of
> speculative insertion tokens. But I'm not sure if there was some
> well-thought-out reason to make them appear invalid. A comment on that would
> be nice, at least.

That seems risky to me. We want something that stops EPQ style chasing
without running into asserts for invalid offsets...

Greetings,

Andres Freund

On Mon, Apr 23, 2018 at 07:58:30AM -0700, Andres Freund wrote:
> On 2018-04-23 13:22:21 +0300, Heikki Linnakangas wrote:
>> Why does HeapTupleHeaderSetMovedPartitions() leave the offset number
>> unchanged? The old offset number is meaningless without the block number.
>> Also, bits and magic values in the tuple header are scarce. We're
>> squandering a whole range of values in the ctid, everything with
>> ip_blkid==InvalidBlockNumber, to mean "moved to different partition", when a
>> single value would suffice.
>
> Yes, I agree on that.

True that the spculative inserts and the partition move are handled in
inconsistent ways now.

>> I kept using InvalidBlockNumber there, so ItemPointerIsValid() still
>> considers those item pointers as invalid. But my gut feeling is actually
>> that it would be better to use e.g. 0 as the block number, so that these
>> item pointers would appear valid. Again, to follow the precedent of
>> speculative insertion tokens. But I'm not sure if there was some
>> well-thought-out reason to make them appear invalid. A comment on that would
>> be nice, at least.
>
> That seems risky to me. We want something that stops EPQ style chasing
> without running into asserts for invalid offsets...

-/*
- * Special value used in t_ctid.ip_posid, to indicate that it holds a
- * speculative insertion token rather than a real TID.  This must be
-higher
- * than MaxOffsetNumber, so that it can be distinguished from a valid
- * offset number in a regular item pointer.
- */
-#define SpecTokenOffsetNumber      0xfff
Moving those definitions from htup_details.h to itemptr.h seems
confusing for me.  As those are heap-related operations, I would
recommend to keep them where they are, and also move those two ones
to htup_details.h, renaming them on the way so as they are more
-consistent:
- ItemPointerIndicatesMovedPartitions
- ItemPointerSetMovedPartitions
--
Michael

As a general note on this thread, we should try to get this cleared up
as soon as possible, since it involves an on-disk format change.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2018-04-23 07:58:30 -0700, Andres Freund wrote:
> On 2018-04-23 13:22:21 +0300, Heikki Linnakangas wrote:
> > On 13/04/18 13:08, Michael Paquier wrote:
> > > On Fri, Apr 13, 2018 at 02:15:35PM +0530, amul sul wrote:
> > > > I have looked into this and found that the issue is in heap_xlog_delete -- we
> > > > have missed to set the correct offset number from the target_tid when
> > > > XLH_DELETE_IS_PARTITION_MOVE flag is set.
> > > 
> > > Oh, this looks good to me.  So when a row was moved across partitions
> > > this could have caused incorrect tuple references on a standby, which
> > > could have caused corruptions.
> > 
> > Hmm. So, the problem was that HeapTupleHeaderSetMovedPartitions() only sets
> > the block number to InvalidBlockNumber, and leaves the offset number
> > unchanged. WAL replay didn't preserve the offset number, so the master and
> > the standby had a different offset number in the ctid.
> 
> Right.
> 
> > Why does HeapTupleHeaderSetMovedPartitions() leave the offset number
> > unchanged? The old offset number is meaningless without the block number.
> > Also, bits and magic values in the tuple header are scarce. We're
> > squandering a whole range of values in the ctid, everything with
> > ip_blkid==InvalidBlockNumber, to mean "moved to different partition", when a
> > single value would suffice.
> 
> Yes, I agree on that.
> 
> 
> > I kept using InvalidBlockNumber there, so ItemPointerIsValid() still
> > considers those item pointers as invalid. But my gut feeling is actually
> > that it would be better to use e.g. 0 as the block number, so that these
> > item pointers would appear valid. Again, to follow the precedent of
> > speculative insertion tokens. But I'm not sure if there was some
> > well-thought-out reason to make them appear invalid. A comment on that would
> > be nice, at least.
> 
> That seems risky to me. We want something that stops EPQ style chasing
> without running into asserts for invalid offsets...

Heikki, would you rather apply this yourself or have me do it?

Greetings,

Andres Freund

On 2018-04-30 22:08:46 -0700, Andres Freund wrote:
> On 2018-04-23 07:58:30 -0700, Andres Freund wrote:
> > On 2018-04-23 13:22:21 +0300, Heikki Linnakangas wrote:
> > > On 13/04/18 13:08, Michael Paquier wrote:
> > > > On Fri, Apr 13, 2018 at 02:15:35PM +0530, amul sul wrote:
> > > > > I have looked into this and found that the issue is in heap_xlog_delete -- we
> > > > > have missed to set the correct offset number from the target_tid when
> > > > > XLH_DELETE_IS_PARTITION_MOVE flag is set.
> > > > 
> > > > Oh, this looks good to me.  So when a row was moved across partitions
> > > > this could have caused incorrect tuple references on a standby, which
> > > > could have caused corruptions.
> > > 
> > > Hmm. So, the problem was that HeapTupleHeaderSetMovedPartitions() only sets
> > > the block number to InvalidBlockNumber, and leaves the offset number
> > > unchanged. WAL replay didn't preserve the offset number, so the master and
> > > the standby had a different offset number in the ctid.
> > 
> > Right.
> > 
> > > Why does HeapTupleHeaderSetMovedPartitions() leave the offset number
> > > unchanged? The old offset number is meaningless without the block number.
> > > Also, bits and magic values in the tuple header are scarce. We're
> > > squandering a whole range of values in the ctid, everything with
> > > ip_blkid==InvalidBlockNumber, to mean "moved to different partition", when a
> > > single value would suffice.
> > 
> > Yes, I agree on that.
> > 
> > 
> > > I kept using InvalidBlockNumber there, so ItemPointerIsValid() still
> > > considers those item pointers as invalid. But my gut feeling is actually
> > > that it would be better to use e.g. 0 as the block number, so that these
> > > item pointers would appear valid. Again, to follow the precedent of
> > > speculative insertion tokens. But I'm not sure if there was some
> > > well-thought-out reason to make them appear invalid. A comment on that would
> > > be nice, at least.
> > 
> > That seems risky to me. We want something that stops EPQ style chasing
> > without running into asserts for invalid offsets...
> 
> Heikki, would you rather apply this yourself or have me do it?

I pushed that now.

Greetings,

Andres Freund