Hi All, Hi Andres,
First, customer told us the backup repository snapshot we were working on was
lost. We only have the WAL files and the VM files left…
He has been able to keep the repo snapshot from June 10th, holding data and
archives down to May 31st. But we might not be able to keep it for a long time…
1. Why the error appeared June 4th
As I wrote upthread, the error about missing "pg_xact/0D44" appeared during
the nightly vacuum of June 4th 2AM. The pg_control files allows to explain
what happened:
20260531-210002F: Latest checkpoint's oldestXID: 3498165236
20260531-210002F_20260601-210002I: Latest checkpoint's oldestXID: 3498165236
20260531-210002F_20260602-210001I: Latest checkpoint's oldestXID: 3498165236
20260531-210002F_20260603-210001I: Latest checkpoint's oldestXID: 3596946949
20260531-210002F_20260604-210002I: Latest checkpoint's oldestXID: 3596946949
20260531-210002F_20260605-210001I: Latest checkpoint's oldestXID: 3596946949
20260531-210002F_20260606-210002I: Latest checkpoint's oldestXID: 3596946949
The horizon jump from 3,498,165,236 to 3,596,946,949 between June 2nd and
3rd, removing all segments from 0D08 à 0D65, including 0D44. An old rows
might have been frozen somewhere in the cluster, this doesn't seem
unexpected. The corruption probably occurred way before this time. We could
check the WAL between 2nd and 3rd of June, as long as the snapshot is kept,
if someone think of something fishy about this oldestXID jump.
2. WAL analysis between May 13th to May 15th
I've been able to collect more WALs covering the INSERTs/ABORT in these
blocks and what happened after.
The nightly vacuum of May 14th 2AM is interesting. I checked what happened to
500 consecutive blocks before and 500 consecutive blocks after the corruption
zone (3,691,936 -> 3,694,482). Blocks outside of the corruption zone has been
vacuumed and visibility bits sets, eg for one of them:
LSN Num Record type Archiving date
D171/7E94D590 1 INSERT+INIT May 13th 19h02
D171/7E94EBC0 to D171/7E954568 26 INSERT May 13th 19h02
D171/7E94EB68 to D171/7E9546F0 27 ABORT May 13th 19h02
D1A5/14E22C58 1 CLEAN remxid 0 May 14th 02h11
D1A6/6421D380 1 CLEAN remxid 0 FPW May 14th 02h14
D1A6/6421D440 1 VISIBLE cutoff xid 0 May 14th 02h14
Looking at bad blocks they all have been skipped by the vacuum. There is ONLY
the INSERT+INIT/INSERT/ABORT records for them.
Here's the sum up of the xlog records including the insert batch + nightly
vacuum, for the 500 consecutive blocks before and after the corruption zone:
# 500 before (3,691,436 to 3,691,935):
kind │ count
--------------+-------
INSERT+INIT │ 500
INSERT │ 12983
ABORT │ 13483
FPI_FOR_HINT │ 504
CLEAN │ 1000
VISIBLE │ 500
# 500 after (3,694,483 to 3,694,982):
kind │ count
--------------+-------
INSERT │ 12981
FPI_FOR_HINT │ 515
ABORT │ 13481
CLEAN │ 1000
VISIBLE │ 500
INSERT+INIT │ 500
For each block, there's one INSERT+INIT, about 27 INSERT and as many ABORT
rollbacking all of them. Each block has two CLEAN record and one VISIBLE.
Sum up of the same period for the 2547 consecutive corrupted blocks:
kind │ count
--------------+-------
INSERT | 65905
INSERT+INIT │ 2547
ABORT │ 68452
FPI_FOR_HINT │ 50
Well, no CLEAN, no VISIBLE there. I don't understand what would keep the
vacuum away specifically for these blocks and not the other surrounding ones…
So considering your question:
> - Are there any vacuum related WAL records for the affected heap blocks? If
> e.g. the relevant rows were removed as part of a VACUUM, this would likely
> be evidence of the write somehow having gotten lost.
It doesn't seems a vacuum record has been lost. We don't have the vacuum
activity from May 15th though.
Considering:
> One interesting thing to look at is whether there are WAL records for the
> affected page with a later LSN than what you saw when the first vacuum
> failed.
No activity past the May 13th ~19h02 batch on these blocks. Note that I only
checked between May 13th 18h22 and May 15th 02h05.
> I'd check a few of the base backups for
> a) the size of the heap relation
Unfortunately, this will not be possible.
> b) the contents of one of the affected blocks
Not possible either. Note that I still have the xlog records writting these
blocks and they are similar to what we observed and extracted from the table
mid-june.
3. Tail of the heap?
As written in intro, unfortunately we don't have the heap files anymore.
However, I've been able to find six blocks located after the corruption zone
with only INSERT records and no INSERT+INIT. One of them (3,787,952) is in
the same heap segment. So I suppose the corruption zone was not the tail of
the heap, neither the tail of a segment, despite the large amount of
INSERT+INIT found.
4. Write activity during maintenance
It seems the INSERT batch was still running during the vacuum of the table
(May 14th, between 02h00 and 02h15), with 167778 records inserted during this
maintenance (according to LSN).
I didn't dig this yet.
5. Storage setup & versions
The server is a VM managed by VMWare. Each ESX access 4TB datastores in a SAN
using Hitachi hardware as storage layer, using multipath (eight paths per
LUN). VMs are using 1TB VMDKs created in these datastores. LVM is used inside
the VMs.
OS: RHEL8, May 12th kernel version was kernel-4.18.0-553.111.1.el8_10.x86_64.
No known failures on the SAN or ESXs around May 12th.
6. pg_reorg or pg_repack
Using such tools is prohibited in production without asking internal DBA team
first. The DBA team confirmed with developers they never used them, neither
in scripts or manualy, but some are still on holidays.
However, it seems highly improbable these tools were used in production.
7. Other
There's still no TRUNCATE on this relation and none of the corrupted blocks
has more than one +INIT xlog record during the batch and VACUUM maintenance.
I keep digging 4.
Regards,
