Re: pg16: invalid page/page verification failed
On Fri, Oct 06, 2023 at 08:47:39AM -0700, Andres Freund wrote: > Hi, > > On 2023-10-06 09:20:05 +0900, Michael Paquier wrote: > > On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote: > > > This table is what it sounds like: a partition into which CSV logs are > > > COPY'ed. It would've been created around 8am. There's no special > > > params set for the table nor for autovacuum. > > > > This may be an important bit of information. 31966b151e6a is new as > > of Postgres 16, has changed the way relations are extended and COPY > > was one area touched. I am adding Andres in CC. > > Hm, is there any chance the COPY targets more than one partition? If so, this > sounds like it might be the issue described here > https://postgr.es/m/20230925213746.fwqauhhifjgefyzk%40alap3.anarazel.de The first error was from: log_time | 2023-10-05 09:57:01.939-05 left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095200.csv' WITH csv Unfortunately, I no longer have the CSV files which caused errors. After I moved the broken table out of the way and created a new partition, they would've been imported successfully, and then removed. Also, it's sad, but the original 2023_10_05_0900 partition I created was itself rotated out of existence a few hours ago (I still have the most interesting lines, though). I've seen that it's possible for a CSV to include some data that ideally would've gone into the "next" CSV: 2023-01-01_18.csv might include a line of data after 6pm. For example, with log_rotation_age=2min, postgresql-2023-10-06_120800.csv had a row after 12:10: 2023-10-06 12:10:00.101 CDT,"pryzbyj","pryzbyj",5581,"[local]",65203f66.15cd,2,... But I'm not sure how that can explain this issue, because this was 095600.csv, and not 095800.csv. My script knows to create the "next" partition, to handle the case that the file includes some data that should've gone to the next logfile. I'm handling that case with the anticipation that there might be a few tenths of a second or even a few seconds of logs in the wrong file - typically 0 lines and sometimes 1 line. I don't know if it's even possible to have multiple lines in the "wrong" file. In any case, I'm not not expecting log rotation to be 2 minutes behind. Also, not only was the data in the CSV earlier than 10am, but the error *itself* was also earlier. The error importing the CSV was at 9:57, so the CSV couldn't have had data after 10:00. Not that it matters, but my script doesn't import the most recent logfile, and also avoids importing files written within the last minute. I don't see how a CSV with a 2 minute interval of data beginning at 9:56 could straddle hourly partitions. log_time | 2023-10-05 09:57:01.939-05 left | invalid page in block 119 of relation base/16409/801594131 left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095200.csv' WITH csv log_time | 2023-10-05 09:57:01.939-05 left | page verification failed, calculated checksum 5074 but expected 50 left | COPY postgres_log FROM '/var/log/postgresql/postgresql-2023-10-05_095200.csv' WITH csv -- Justin
Re: pg16: invalid page/page verification failed
Hi, On 2023-10-06 09:20:05 +0900, Michael Paquier wrote: > On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote: > > This table is what it sounds like: a partition into which CSV logs are > > COPY'ed. It would've been created around 8am. There's no special > > params set for the table nor for autovacuum. > > This may be an important bit of information. 31966b151e6a is new as > of Postgres 16, has changed the way relations are extended and COPY > was one area touched. I am adding Andres in CC. Hm, is there any chance the COPY targets more than one partition? If so, this sounds like it might be the issue described here https://postgr.es/m/20230925213746.fwqauhhifjgefyzk%40alap3.anarazel.de I think at this stage the easiest fix might be just to copy the approach of calling ReleaseBulkInsertStatePin(), even though I think that's architecturally wrong. Greetings, Andres Freund
Re: pg16: invalid page/page verification failed
On Fri, Oct 06, 2023 at 09:20:05AM +0900, Michael Paquier wrote:
> On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote:
> > This table is what it sounds like: a partition into which CSV logs are
> > COPY'ed. It would've been created around 8am. There's no special
> > params set for the table nor for autovacuum.
>
> This may be an important bit of information. 31966b151e6a is new as
> of Postgres 16, has changed the way relations are extended and COPY
> was one area touched. I am adding Andres in CC.
Also, I realized that someone kicked off a process just after 9am which
would've done a lot of INSERT ON CONFLICT DO UPDATE, VACUUM FULL, and
VACUUM. Which consumed and dirtied buffers about 100x faster than normal.
log_time | 2023-10-05 10:00:55.794-05
pid | 31754
left | duration: 51281.001 ms statement: VACUUM (FULL,FREEZE)
othertable...
log_time | 2023-10-05 10:01:01.784-05
backend_type | checkpointer
left | checkpoint starting: time
log_time | 2023-10-05 10:01:02.935-05
pid | 10023
left | page verification failed, calculated checksum 5074 but
expected 5050
context | COPY postgres_log, line 947
left | COPY postgres_log FROM
'/var/log/postgresql/postgresql-2023-10-05_095600.csv' WITH csv
log_time | 2023-10-05 10:01:02.935-05
pid | 10023
left | invalid page in block 119 of relation base/16409/801594131
context | COPY postgres_log, line 947
left | COPY postgres_log FROM
'/var/log/postgresql/postgresql-2023-10-05_095600.csv' WITH csv
log_time | 2023-10-05 10:01:11.636-05
pid | 31754
left | duration: 15838.374 ms statement: VACUUM (FREEZE)
othertable...
I meant to point out that the issue is on the last block.
postgres=# SELECT
pg_relation_size('"BROKEN_postgres_log_2023_10_05_0900"')/8192;
?column? | 120
It sounds like there may be an issue locking (pinning?) a page, or
rather not locking it, or releasing the lock too early.
--
Justin
Re: pg16: invalid page/page verification failed
On Thu, Oct 05, 2023 at 11:45:18AM -0500, Justin Pryzby wrote: > This table is what it sounds like: a partition into which CSV logs are > COPY'ed. It would've been created around 8am. There's no special > params set for the table nor for autovacuum. This may be an important bit of information. 31966b151e6a is new as of Postgres 16, has changed the way relations are extended and COPY was one area touched. I am adding Andres in CC. -- Michael signature.asc Description: PGP signature
Re: pg16: invalid page/page verification failed
On Thu, Oct 05, 2023 at 07:16:31PM +0200, Matthias van de Meent wrote: > On Thu, 5 Oct 2023 at 18:48, Justin Pryzby wrote: > > > > On an instance running pg16.0: > > > > log_time | 2023-10-05 10:03:00.014-05 > > backend_type | autovacuum worker > > left | page verification failed, calculated checksum 5074 but > > expected 5050 > > context | while scanning block 119 of relation > > "public.postgres_log_2023_10_05_0900" > > > > This is the only error I've seen so far, and for all I know there's a > > issue on the storage behind the VM, or a cosmic ray hit. But I moved > > the table out of the way and saved a copy of get_raw_page() in case > > someone wants to ask about it. > > > > postgres=# SELECT * FROM > > heap_page_item_attrs(get_raw_page(801594131::regclass::text, 119), > > 801594131); > > lp | lp_off | lp_flags | lp_len | t_xmin | t_xmax | t_field3 | t_ctid | > > t_infomask2 | t_infomask | t_hoff | t_bits | t_oid | t_attrs > >1 | 2304 |1 | 16 ||| || > > |||| | > >2 | 8160 |1 | 16 ||| || > > |||| | > >3 | 8144 |1 | 16 ||| || > > |||| | > > ...all the same except for lp_off... > > 365 | 2352 |1 | 16 ||| || > > |||| | > > 366 | 2336 |1 | 16 ||| || > > |||| | > > 367 | 2320 |1 | 16 ||| || > > |||| | > > That's not a HEAP page; it looks more like a btree page: lp_len is too > short for heap (which starts at lp_len = 24), and there are too many > line pointers for an 8KiB heap page. btree often has lp_len of 16: 8 > bytes indextuple header, one maxalign of data (e.g. int or bigint). > > So, assuming it's a block of a different relation kind, then it's also > likely it was originally located elsewhere in that other relation, > indeed causing the checksum failure. You can further validate this by > looking at the page header's pd_special value - if it is 8176, that'd > be another indicator for it being a btree. Nice point. postgres=# SET ignore_checksum_failure=on; SELECT * FROM generate_series(115,119) AS a, page_header(get_raw_page(801594131::regclass::text, a)) AS b; WARNING: page verification failed, calculated checksum 5074 but expected 5050 a | lsn | checksum | flags | lower | upper | special | pagesize | version | prune_xid -+--+--+---+---+---+-+--+-+--- 115 | B61/A9436C8 | -23759 | 4 |92 | 336 |8192 | 8192 | 4 | 0 116 | B61/A944FA0 | 3907 | 4 | 104 | 224 |8192 | 8192 | 4 | 0 117 | B61/A946828 | -24448 | 4 |76 | 264 |8192 | 8192 | 4 | 0 118 | B61/A94CCE0 |26915 | 4 |28 | 6256 |8192 | 8192 | 4 | 0 119 | B5C/9F30D1C8 | 5050 | 0 | 1492 | 2304 |8176 | 8192 | 4 | 0 The table itself has a few btree indexes on text columns and a brin index on log_timestamp, but not on the integers. It sounds like it's what's expected at this point, but after I "SET ignore_checksum_failure=on", and read the page in, vacuum kicked off and then crashed (in heap_page_prune() if that half of the stack trace can be trusted). *** stack smashing detected ***: postgres: autovacuum worker postgres terminated < 2023-10-05 12:35:30.764 CDT >LOG: server process (PID 30692) was terminated by signal 11: Segmentation fault < 2023-10-05 12:35:30.764 CDT >DETAIL: Failed process was running: autovacuum: VACUUM ANALYZE public.BROKEN_postgres_log_2023_10_05_0900 I took the opportunity to fsck the FS, which showed no errors. I was curious if the relfilenodes had gotten confused/corrupted/?? But this seems to indicate not; the problem is only one block. postgres=# SELECT oid, relfilenode, oid=relfilenode, relname FROM pg_class WHERE oid BETWEEN 80155 AND 801594199 ORDER BY 1; oid| relfilenode | ?column? | relname ---+-+--+- 801564542 | 801564542 | t| postgres_log_2023_10_05_0800 801564545 | 801564545 | t| pg_toast_801564542 801564546 | 801564546 | t| pg_toast_801564542_index 801564547 | 801564547 | t| postgres_log_2023_10_05_0800_log_time_idx 801564548 | 801564548 | t| postgres_log_2023_10_05_0800_error_severity_idx 801564549 | 801564549 | t|
Re: pg16: invalid page/page verification failed
On Thu, 5 Oct 2023 at 18:48, Justin Pryzby wrote: > > On an instance running pg16.0: > > log_time | 2023-10-05 10:03:00.014-05 > backend_type | autovacuum worker > left | page verification failed, calculated checksum 5074 but > expected 5050 > context | while scanning block 119 of relation > "public.postgres_log_2023_10_05_0900" > > This is the only error I've seen so far, and for all I know there's a > issue on the storage behind the VM, or a cosmic ray hit. But I moved > the table out of the way and saved a copy of get_raw_page() in case > someone wants to ask about it. > > postgres=# SELECT * FROM > heap_page_item_attrs(get_raw_page(801594131::regclass::text, 119), 801594131); > lp | lp_off | lp_flags | lp_len | t_xmin | t_xmax | t_field3 | t_ctid | > t_infomask2 | t_infomask | t_hoff | t_bits | t_oid | t_attrs >1 | 2304 |1 | 16 ||| || > |||| | >2 | 8160 |1 | 16 ||| || > |||| | >3 | 8144 |1 | 16 ||| || > |||| | > ...all the same except for lp_off... > 365 | 2352 |1 | 16 ||| || > |||| | > 366 | 2336 |1 | 16 ||| || > |||| | > 367 | 2320 |1 | 16 ||| || > |||| | That's not a HEAP page; it looks more like a btree page: lp_len is too short for heap (which starts at lp_len = 24), and there are too many line pointers for an 8KiB heap page. btree often has lp_len of 16: 8 bytes indextuple header, one maxalign of data (e.g. int or bigint). So, assuming it's a block of a different relation kind, then it's also likely it was originally located elsewhere in that other relation, indeed causing the checksum failure. You can further validate this by looking at the page header's pd_special value - if it is 8176, that'd be another indicator for it being a btree. Kind regards, Matthias van de Meent.
