Re: Possible Visibility Map corruption in supported branches?

Hi all,

Operations are quite slow because of summer time. Our next steps are currently
on hold waiting for everyone to be available (including me). Below a quick
follow up on this subject.

Based on the mtime of the WAL archives, the customer provided us the 256
segments of the WAL 0000019E0000D171 where the "bad batch" occurred. The
content has been parsed by pg_waldump and loaded in a table. I can provide a
200MB dump of the table if needed or the raw waldump output.

I found that the 2547 blocks having a corrupted VM were all initialized during
an INSERT+INIT xlogrecord before having between 3 to 26 follow up INSERTs
records, all in their own xact being aborted.

-- sum-up of number record kind per blocks
=# WITH b AS (
SELECT blk, kind, count(*) AS num_in_block
FROM waldump
WHERE rel = 25667392
AND blk BETWEEN 3691936 AND 3694482
GROUP BY blk, kind
)
SELECT kind, num_in_block,
count(*),
sum(num_in_block*count(*)) OVER () AS total_evt
FROM b
GROUP BY kind, num_in_block;

kind num_in_block count total_evt
----------- ------------ ----- ---------
INSERT 3 1 68452
INSERT 5 1 68452
INSERT 6 2 68452
INSERT 9 1 68452
INSERT 10 2 68452
INSERT 13 1 68452
INSERT 15 2 68452
INSERT 18 1 68452
INSERT 19 1 68452
INSERT 25 108 68452
INSERT 26 2426 68452
INSERT+INIT 1 2547 68452
(12 rows)

-- number of xact related to these blocks and their status
=# WITH b AS (
SELECT kind, txn
FROM waldump
WHERE rel = 25667392
AND blk BETWEEN 3691936 AND 3694482
)
SELECT kind, count(*)
FROM waldump w
WHERE EXISTS (SELECT 1 FROM b WHERE b.txn = w.txn)
AND w.rmgr = 'Transaction'
GROUP BY kind;

kind count
----- -----
ABORT 68452

I asked for the 25667392_vm files for the 12, 13 and 14th of May to compare how
the visibility bits for these blocks evolved. You'll find them in attachment
with the script I use to parse them, should you want to check how results below
were produced.

$ stat -c "%n %s" 20260510-210002F_202605*/pg_data/base/235301/25667392_vm
20260510-210002F_20260512-210001I/pg_data/base/235301/25667392_vm 933888
20260510-210002F_20260513-210002I/pg_data/base/235301/25667392_vm 933888
20260510-210002F_20260514-210002I/pg_data/base/235301/25667392_vm 991232

VM files have 114 blocks but the last one who grows to 121. The heap blocks we
study are all referenced in the 113th block of the VM, the last one for the
12th and 13th of May (0 indexed).

The 12th and 13th have the exact same output:

$ ./pg_vm_parse.pl \
20260510-210002F_20260512-210001I/pg_data/base/235301/25667392_vm \
{3691936..3694482} | sha1sum
909beb7d8613be2cdf6d120cdbd686ee224111f5 -

$ ./pg_vm_parse.pl \
20260510-210002F_20260513-210002I/pg_data/base/235301/25667392_vm \
{3691936..3694482} | sha1sum
909beb7d8613be2cdf6d120cdbd686ee224111f5 -

$ ./pg_vm_parse.pl \
20260510-210002F_20260513-210002I/pg_data/base/235301/25667392_vm \
{3691936..3694482} | cut -d, -f 5-6 | sort | uniq -c
72 VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 0
13 VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 1
5 VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 0
2457 VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 1

I'm not sure how the VM references them the 12th if the xlogrecord shows they
were actually initiated the 13th around 19h. This tables receive **a lot** of
aborted xact, more than 99% in 0000019E0000D171* segments. So maybe it
frequently shrinks thanks to some autovacuum truncating the VM? This is
something we plan to analyze when we'll be able to gather all the pg_waldump
data between these two backups.

More surprisingly, these VM are exactly the same for these two days wheras the
"bad batch" filled these blocks with aborted INSERTs in the meantime. Maybe the
waldump of archives between 13th 19h and 13th 21h will shed some light on this,
as soon as we have them.

The 14th have a slight difference as visibility and/or frozen bits for 17
blocks changed to all possible bits combinations.

$ diff vm-20260513-210002.log vm-20260514-210002.log | grep '^>'
> HEAP blk: 3691937, … VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 0
> HEAP blk: 3691938, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 1
> HEAP blk: 3691939, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 1
> HEAP blk: 3691940, … VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 0
> HEAP blk: 3691941, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 0
> HEAP blk: 3691942, … VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 0
> HEAP blk: 3691953, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 0
> HEAP blk: 3691954, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 1
> HEAP blk: 3691955, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 0
> HEAP blk: 3691956, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 0
> HEAP blk: 3691957, … VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 1
> HEAP blk: 3691958, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 1
> HEAP blk: 3691960, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 1
> HEAP blk: 3691961, … VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 1
> HEAP blk: 3691962, … VM_ALL_VISIBLE: 1, VM_ALL_FROZEN: 0
> HEAP blk: 3691964, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 0
> HEAP blk: 3691966, … VM_ALL_VISIBLE: 0, VM_ALL_FROZEN: 1

I'm not sure when/how some visibility bits could flips for some of these blocks
considering in june the HEAP blocks were still having the aborted lines
inserted by the bad batch the 13th of May around 19h.

I really hope we'll be able to find what happen to these blocks in other
pg_waldump extractions between these backups. The snapshot of the backup
repository we restored covers archived WAL between May 03rd 21:30 and May 16th
23:00. Two full backups on sundays and daily incrementals in between.

Stay tuned, but again, any ideas, scenario, information to gather are welcome!

Thank you for reading me down to here!