Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-04-10 Thread Adam Sjøgren 
Pavan writes:

>> FWIW one of our support customers reported a very similar TOAST table
>> corruption issue last week which nearly caused an outage. After a lot of
>> analysis, I think I've now fully understood the reasons behind the
>> corruption, the underlying bug(s) and possible remedy. I am currently
>> working on writing a reproducible test case to demonstrate the problem and
>> writing the fix. More details on that soon.
>
> I've posted a reproducer and a proposed fix to -hackers [1]
>
> In the particular case that I investigated, a database crash/recovery was
> involved. But I think we should be able to create a scenario where OID
> wrap-around or a standby promotion triggers the problem.  I don't know if
> any of that was involved in the cases reported on this thread, but I've a
> strong suspicion that the underlying bug is probably the same.

In our case there was no crash+recovery, but we do have a high write
load (and the problem occurring quite seldom), so it sounds like it
fits.

> [1] 
> https://www.postgresql.org/message-id/CABOikdOgWT2hHkYG3Wwo2cyZJq2zfs1FH0FgX-%3Dh4OLosXHf9w%40mail.gmail.com

Impressive investigation!

Just a couple of data points: your script to reproduce the problem does
so for all three versions of PostgreSQL we have in use: 9.3.22, 9.6.8
and 10.3.

And I specifically tested on our production machine which exhibits the
problem, running 9.3.22, and your script reproduced the problem there as
well.

I.e. ending with:

  ERROR:  unexpected chunk number 0 (expected 1) for toast value 16396 in 
pg_toast_16384
  REINDEX
  ERROR:  unexpected chunk number 0 (expected 1) for toast value 16396 in 
pg_toast_16384
  VACUUM
  ERROR:  unexpected chunk number 0 (expected 1) for toast value 16396 in 
pg_toast_16384


  Best regards,

Adam

-- 
 "No more than that, but very powerful all theAdam Sjøgren
  same; simple things are good."a...@novozymes.com

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-04-10 Thread Pavan Deolasee 
On Fri, Apr 6, 2018 at 8:55 AM, Pavan Deolasee 
wrote:

>
>
> On Fri, Apr 6, 2018 at 2:34 AM, Tom Lane  wrote:
>
>> a...@novozymes.com (Adam =?utf-8?Q?Sj=C3=B8gren?=) writes:
>> >> [... still waiting for the result, I will return with what it said
>> >> when the server does ...]
>>
>> > It did eventually finish, with the same result:
>>
>> Huh.  So what we have here, apparently, is that regular MVCC snapshots
>> think there is exactly one copy of the 1698936148/0 row, but TOAST fetches
>> think there is more than one.  This is darn odd, not least because we
>> never do UPDATEs in toast tables, only inserts and deletes, so there
>> certainly shouldn't be update chains there.
>>
>> It seems like you've got some corner case wherein SnapshotToast sees a row
>> that isn't visible according to MVCC --- probably a row left over from
>> some previous cycle of life.  That is, I'm imagining the OID counter
>> wrapped around and we've reused a toast OID, but for some reason there's
>> still a row in the table with that OID.  I'm not sure offhand how we could
>> get into such a state.  Alvaro, does this ring any bells (remembering that
>> this is 9.3)?
>>
>
> FWIW one of our support customers reported a very similar TOAST table
> corruption issue last week which nearly caused an outage. After a lot of
> analysis, I think I've now fully understood the reasons behind the
> corruption, the underlying bug(s) and possible remedy. I am currently
> working on writing a reproducible test case to demonstrate the problem and
> writing the fix. More details on that soon.
>
>
I've posted a reproducer and a proposed fix to -hackers [1]

In the particular case that I investigated, a database crash/recovery was
involved. But I think we should be able to create a scenario where OID
wrap-around or a standby promotion triggers the problem.  I don't know if
any of that was involved in the cases reported on this thread, but I've a
strong suspicion that the underlying bug is probably the same.

Thanks,
Pavan

[1] https://www.postgresql.org/message-id/CABOikdOgWT2hHkYG3Wwo2cyZJq2zf
s1FH0FgX-%3Dh4OLosXHf9w%40mail.gmail.com

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

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-04-05 Thread Tom Lane 
a...@novozymes.com (Adam =?utf-8?Q?Sj=C3=B8gren?=) writes:
>> [... still waiting for the result, I will return with what it said
>> when the server does ...]

> It did eventually finish, with the same result:

Huh.  So what we have here, apparently, is that regular MVCC snapshots
think there is exactly one copy of the 1698936148/0 row, but TOAST fetches
think there is more than one.  This is darn odd, not least because we
never do UPDATEs in toast tables, only inserts and deletes, so there
certainly shouldn't be update chains there.

It seems like you've got some corner case wherein SnapshotToast sees a row
that isn't visible according to MVCC --- probably a row left over from
some previous cycle of life.  That is, I'm imagining the OID counter
wrapped around and we've reused a toast OID, but for some reason there's
still a row in the table with that OID.  I'm not sure offhand how we could
get into such a state.  Alvaro, does this ring any bells (remembering that
this is 9.3)?

regards, tom lane

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-04-05 Thread Adam Sjøgren 
Tom writes:

>> And when I run the suggested query, I get:
>
>>   efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
>> length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 
>> 1698936148 order by 1,2;
>> chunk_id  | chunk_seq | ctid |xmin| xmax | length 
>>   +---+--++--+
>>1698936148 | 0 | (52888694,2) | 1511390221 |0 |   1996
>>1698936148 | 1 | (52888694,4) | 1511390221 |0 |   1148
>>   (2 rows)

> Hmph.  So if you EXPLAIN that query, does it show it's doing it as an
> indexscan?  I'd expect so, but it's always good to make sure.

It does:

  efamroot@kat efam=# SELECT * FROM efam.sendreference WHERE id = '189909908';
  ERROR:  unexpected chunk number 0 (expected 1) for toast value 1698936148 in 
pg_toast_10919630
  efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698936148 
order by 1,2;
chunk_id  | chunk_seq | ctid |xmin| xmax | length 
  +---+--++--+
   1698936148 | 0 | (52888694,2) | 1511390221 |0 |   1996
   1698936148 | 1 | (52888694,4) | 1511390221 |0 |   1148
  (2 rows)

  efamroot@kat efam=# explain select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698936148 
order by 1,2;
QUERY PLAN  

  
--
   Index Scan using pg_toast_10919630_index on pg_toast_10919630  
(cost=0.57..2627179.25 rows=2135674 width=54)
 Index Cond: (chunk_id = 1698936148::oid)
  (2 rows)

> Assuming it does say that, then the other test I had in mind would
> involve "set enable_indexscan = 0", then repeat the EXPLAIN to make
> sure that you now get a seqscan plan (you might need to turn off
> enable_bitmapscan too), then do the query again and see whether the
> results are the same.

Ok (if I don't disable bitmapscan, I get Bitmap Heap Scans in the EXPLAIN, so):

  efamroot@kat efam=# set enable_indexscan = 0;
  SET
  efamroot@kat efam=# set enable_bitmapscan = 0;
  SET
  efamroot@kat efam=# explain select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698936148 
order by 1,2;
   QUERY PLAN   
   
  
-
   Sort  (cost=96465280.57..96470619.75 rows=2135674 width=54)
 Sort Key: chunk_seq
 ->  Seq Scan on pg_toast_10919630  (cost=0.00..96240754.39 rows=2135674 
width=54)
   Filter: (chunk_id = 1698936148::oid)
  (4 rows)

  efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698936148 
order by 1,2;
  [... still waiting for the result, I will return with what it said
   when the server does ...]


  Best regards,

Adam

-- 
 "No more than that, but very powerful all theAdam Sjøgren
  same; simple things are good."a...@novozymes.com

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-04-05 Thread Tom Lane 
a...@novozymes.com (Adam =?utf-8?Q?Sj=C3=B8gren?=) writes:
> Here's a statement which currently gives an unexpected chunk error:

>   efamroot@kat efam=# SELECT * FROM efam.sendreference WHERE id = '189909908';
>   ERROR:  unexpected chunk number 0 (expected 1) for toast value 1698936148 
> in pg_toast_10919630

OK ...

> And when I run the suggested query, I get:

>   efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
> length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 
> 1698936148 order by 1,2;
> chunk_id  | chunk_seq | ctid |xmin| xmax | length 
>   +---+--++--+
>1698936148 | 0 | (52888694,2) | 1511390221 |0 |   1996
>1698936148 | 1 | (52888694,4) | 1511390221 |0 |   1148
>   (2 rows)

Hmph.  So if you EXPLAIN that query, does it show it's doing it as an
indexscan?  I'd expect so, but it's always good to make sure.

Assuming it does say that, then the other test I had in mind would
involve "set enable_indexscan = 0", then repeat the EXPLAIN to make
sure that you now get a seqscan plan (you might need to turn off
enable_bitmapscan too), then do the query again and see whether the
results are the same.

regards, tom lane

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-04-05 Thread Adam Sjøgren 
Adam writes:

> Here's a statement which currently gives an unexpected chunk error:
>
>   efamroot@kat efam=# SELECT * FROM efam.sendreference WHERE id = '189909908';
>   ERROR:  unexpected chunk number 0 (expected 1) for toast value 1698936148 
> in pg_toast_10919630
>
> And when I run the suggested query, I get:
>
>   efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
> length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 
> 1698936148 order by 1,2;
> chunk_id  | chunk_seq | ctid |xmin| xmax | length 
>   +---+--++--+
>1698936148 | 0 | (52888694,2) | 1511390221 |0 |   1996
>1698936148 | 1 | (52888694,4) | 1511390221 |0 |   1148
>   (2 rows)

More examples:

  efamroot@kat efam=# SELECT * FROM efam.sendreference WHERE id = '237764759';
  ERROR:  unexpected chunk number 0 (expected 1) for toast value 1698958350 in 
pg_toast_10919630
  efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698958350 
order by 1,2;
chunk_id  | chunk_seq | ctid |xmin| xmax | length 
  +---+--++--+
   1698958350 | 0 | (54859821,2) | 1511487270 |0 |   1448
  (1 row)

And:

  efamroot@kat efam=# SELECT * FROM efam.sendreference WHERE id = '366275833';
  ERROR:  unexpected chunk number 0 (expected 1) for toast value 1698945095 in 
pg_toast_10919630
  efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698945095 
order by 1,2;
chunk_id  | chunk_seq | ctid |xmin| xmax | length 
  +---+--++--+
   1698945095 | 0 | (53706565,3) | 1511426847 |0 |   1996
   1698945095 | 1 | (53706565,6) | 1511426847 |0 |108
  (2 rows)

One more:

  efamroot@kat efam=# SELECT * FROM efam.sendreference WHERE id = '189909908';
  ERROR:  unexpected chunk number 0 (expected 1) for toast value 1698936148 in 
pg_toast_10919630
  efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698936148 
order by 1,2;
chunk_id  | chunk_seq | ctid |xmin| xmax | length 
  +---+--++--+
   1698936148 | 0 | (52888694,2) | 1511390221 |0 |   1996
   1698936148 | 1 | (52888694,4) | 1511390221 |0 |   1148
  (2 rows)

And here is one from another table:

  efamroot@kat efam=# SELECT * FROM efam.sequence WHERE id = '235887163';
  ERROR:  unexpected chunk number 0 (expected 1) for toast value 1698750544 in 
pg_toast_10919630
  efamroot@kat efam=# select chunk_id, chunk_seq, ctid, xmin, xmax, 
length(chunk_data) from pg_toast.pg_toast_10919630 where chunk_id = 1698750544 
order by 1,2;
chunk_id  | chunk_seq | ctid |xmin| xmax | length 
  +---+--++--+
   1698750544 | 0 | (39575142,3) | 1510704835 |0 |   1996
   1698750544 | 1 | (39575142,4) | 1510704835 |0 |716
  (2 rows)

Let me know what other relevant info I can provide.


  Best regards,

Adam

-- 
 "No more than that, but very powerful all theAdam Sjøgren
  same; simple things are good."a...@novozymes.com

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-01-17 Thread Michael Paquier 
On Wed, Jan 17, 2018 at 12:16:19PM -0500, Tom Lane wrote:
> The basic thrust of these messages is "I'm reading what should be
> sequentially numbered data chunks for this toast OID, and the sequence
> numbers are wrong".  Both of these instances could be explained by
> duplicate toast rows (or duplicate index entries pointing at one row),
> though of course that would just move to the next question of how it
> got that way.

Good point here. This could be a consequence of freeze-the-dead whose
fix will be available in the next round of minor releases.
--
Michael


signature.asc
Description: PGP signature

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-01-17 Thread Tom Lane 
a...@novozymes.com (Adam =?utf-8?Q?Sj=C3=B8gren?=) writes:
> Also, the error we are getting is now: "unexpected chunk number 2
> (expected 3) for toast value 1498303849 in pg_toast_10919630", where
> previously we've only seen "unexpected chunk number 0 (expected 1)".

> We are kind of at a loss, so any suggestions on what we could try are
> welcome.

The basic thrust of these messages is "I'm reading what should be
sequentially numbered data chunks for this toast OID, and the sequence
numbers are wrong".  Both of these instances could be explained by
duplicate toast rows (or duplicate index entries pointing at one row),
though of course that would just move to the next question of how it
got that way.  Anyway, you could move the investigation along with
some manual checking into what's in that toast table.  For instance

select chunk_id, chunk_seq, ctid, xmin, xmax, length(chunk_data)
  from pg_toast.pg_toast_10919630
  where chunk_id = 1498303849
  order by 1,2;

might be informative.  If you do see what seem to be duplicate
chunk_seq values, checking whether they're still there in a
seqscan would be good.

regards, tom lane

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-01-16 Thread Adam Sjøgren 
Michael writes:

> On Tue, Jan 16, 2018 at 07:05:19PM +0100, Adam Sjøgren wrote:

>> This sounds very interesting - we are running PostgreSQL 9.3.20.

> Which means that we may be looking at a new bug, 9.3.20 is the latest in
> the 9.3 set as of today.

Yes; unfortunately we have failed to reproduce it outside production.

The fact that the tsvector field is always involved when we see the
error might be of interest (the tsvector field is the most updated in
our database, however).

Just for completeness, the tsvector field has a GIN index on it:

"sequence_fts_idx" gin (fts) WITH (fastupdate=off)

and it is updated by a BEFORE INSERT OR UPDATE trigger.

A new observation is that when we previously were able to get the
"unexpected chunk number" to go away by simply updating the tsvector
field of the offending record, we now have a record where we get "ERROR:
tuple concurrently updated" when we try overwriting the field.

On another record exhibiting the "unexpected chunk number" error, we
could overwrite the fts field, as can we on rows not affected by the
"unexpected chunk number"-error. So it seems the two errors might
somehow be related.

We tried stopping all activity on the database, and still got the
"ERROR: tuple concurrently updated" on the row with "unexpected chunk
number".

Also, the error we are getting is now: "unexpected chunk number 2
(expected 3) for toast value 1498303849 in pg_toast_10919630", where
previously we've only seen "unexpected chunk number 0 (expected 1)".

We are kind of at a loss, so any suggestions on what we could try are
welcome.

>> Did you ever find out exactly what the change that solved the problem
>> between 9.4.8 and 9.4.11 was?

> In this case, I think that you are looking for this thread:
> https://www.postgresql.org/message-id/20160826072658.15676.7...@wrigleys.postgresql.org

> And this commit:
> commit: a694435641faf26a9a4c210d20576ae836e86c48
> author: Tom Lane 
> date: Sat, 3 Sep 2016 13:28:53 -0400
> Fix corrupt GIN_SEGMENT_ADDITEMS WAL records on big-endian hardware.
>
> Both involved 9.4.8.

We run on x86_64-hardware, so I guess this wouldn't affect us?


  Best regards,

Adam

-- 
 "No more than that, but very powerful all theAdam Sjøgren
  same; simple things are good."a...@novozymes.com

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-01-16 Thread Michael Paquier 
On Tue, Jan 16, 2018 at 07:05:19PM +0100, Adam Sjøgren wrote:
> This sounds very interesting - we are running PostgreSQL 9.3.20.

Which means that we may be looking at a new bug, 9.3.20 is the latest in
the 9.3 set as of today.

> Did you ever find out exactly what the change that solved the problem
> between 9.4.8 and 9.4.11 was?

In this case, I think that you are looking for this thread:
https://www.postgresql.org/message-id/20160826072658.15676.7...@wrigleys.postgresql.org

And this commit:
commit: a694435641faf26a9a4c210d20576ae836e86c48
author: Tom Lane 
date: Sat, 3 Sep 2016 13:28:53 -0400
Fix corrupt GIN_SEGMENT_ADDITEMS WAL records on big-endian hardware.

Both involved 9.4.8.
--
Michael


signature.asc
Description: PGP signature

Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 76753264 in pg_toast_10920100

2018-01-16 Thread Adam Sjøgren 
  Hi Jorge,


This sounds very interesting - we are running PostgreSQL 9.3.20.

Did you ever find out exactly what the change that solved the problem
between 9.4.8 and 9.4.11 was?


  Best regards,

Adam


Jorge writes:

> Hi Adam , I've been seeing this same  kind of Error in my clusters for a 
> while .
>
> Is this running on postgresql 9.4.8? Because mine was fixed upgrading to 
> 9.4.11 , a bug indeed .
>
>
>
> Kind regards
>
>
>
> Jorge Daniel Fernandez
>
>
> 
> From: Adam Sjøgren <a...@novozymes.com>
> Sent: Tuesday, January 16, 2018 7:18 AM
> To: pgsql-gene...@postgresql.org
> Subject: Re: ERROR: unexpected chunk number 0 (expected 1) for toast value 
> 76753264 in pg_toast_10920100
>
> We are seeing these "ERROR:  unexpected chunk number 0 (expected 1) for
> toast value 1498303849 in pg_toast_10919630" in increasing numbers again¹.
>
> An observation is that they seem to only happen for tsvector fields.
>
> Here is an example sequence of queries for a record (we have more than a
> handful of these currently), which exhibits the problem.
>
> First we get two other fields, 'sequence' is large enough to be toast'ed:
>
>   2018-01-16 08:51:17.362 efam=# select id,sequence from efam.sequence where 
> id = 164504550;
>   Time: 1.150 ms
>
> No problem.
>
> Then we also fetch the tsvector field:
>
>   2018-01-16 08:51:27.773 efam=# select id,sequence,fts from efam.sequence 
> where id = 164504550;
>   ERROR:  unexpected chunk number 0 (expected 1) for toast value 1498303849 
> in pg_toast_10919630
>   Time: 0.912 ms
>
> And we get the error.
>
> Getting the id and the tsvector:
>
>   2018-01-16 08:51:34.174 efam=# select id,fts from efam.sequence where id = 
> 164504550;
>   ERROR:  unexpected chunk number 0 (expected 1) for toast value 1498303849 
> in pg_toast_10919630
>   Time: 6.138 ms
>
> gives the error.
>
> Just getting the tsvector:
>
>   2018-01-16 08:51:40.066 efam=# select fts from efam.sequence where id = 
> 164504550;
>   ERROR:  unexpected chunk number 0 (expected 1) for toast value 1498303849 
> in pg_toast_10919630
>   Time: 1.805 ms
>
> Gives the error.
>
> Field definitions:
>
>id| integer |
>sequence  | text|
>fts   | tsvector|
>
> Maybe the observation that this only happens (for us) on tsvector rings
> a bell for someone?
>
>
>   Best regards,
>
> Adam
>
>
> ¹ As reported back in June, 2017, starting here:
>   https://www.postgresql.org/message-id/7pefuv53dl.fsf%40novozymes.com
>   (I have to admit I never got around to trying to revert the commit
>   Alvaro Herrera suggested we try without
>   
> (https://www.postgresql.org/message-id/20170611033840.hruqadsk47qcdrqb%40alvherre.pgsql))
>
> --
>  "No more than that, but very powerful all theAdam Sjøgren
>   same; simple things are good."a...@novozymes.com
>
>

-- 
 "No more than that, but very powerful all theAdam Sjøgren
  same; simple things are good."a...@novozymes.com