Re: Wrong LSN in WAL decoding error messages - Mailing list pgsql-hackers
| From | surya poondla |
|---|---|
| Subject | Re: Wrong LSN in WAL decoding error messages |
| Date | |
| Msg-id | CAOVWO5rGVkiB-MUxKJVtUv3L=H3taWx7Rsg5_zea-nmQknU-MQ@mail.gmail.com Whole thread |
| In response to | Wrong LSN in WAL decoding error messages (rahul@rhyadav.dev) |
| List | pgsql-hackers |
Hi Rahul,
Thanks for the patches. I reviewed both, and tested 0001 on REL_19_STABLE (3f5bfbce4c4) and 0001+0002 on master.
0001 looks right to me. The other checks in XLogDecodeNextRecord() already report RecPtr; DecodeXLogRecord() is the only place that uses
ReadRecPtr, and that pointer has been unreliable there since 3f1ce97346.
You also correctly left RestoreBlockImage() alone, it only runs on a record that has already been returned (redo, pg_waldump
--save-fullpage, pg_walinspect), so ReadRecPtr really is that record.
Thanks to the reproducing steps, I reproduced it the same way you did. hole_offset set to 0 in an uncompressed FPI, CRC recomputed. I crashed a cluster with kill -9
partway through a transaction after a checkpoint, then corrupted an FPI from that transaction, at 0/01821288.
Crash recovery reported these LSNs (in all cases "redo done at 0/01821248"):
recovery_prefetch=try recovery_prefetch=off
unpatched 0/0180F608 0/01821248
patched 0/01821288 0/01821288
With prefetching on, the unpatched message named the redo start point, 45 records (about 71kB) before the bad record.
The prefetcher had decoded that whole span in one go before redo got its second record,
so ReadRecPtr was still at the redo point. So "several records back" in the commit message undersells it a bit.
Thanks for the patches. I reviewed both, and tested 0001 on REL_19_STABLE (3f5bfbce4c4) and 0001+0002 on master.
0001 looks right to me. The other checks in XLogDecodeNextRecord() already report RecPtr; DecodeXLogRecord() is the only place that uses
ReadRecPtr, and that pointer has been unreliable there since 3f1ce97346.
You also correctly left RestoreBlockImage() alone, it only runs on a record that has already been returned (redo, pg_waldump
--save-fullpage, pg_walinspect), so ReadRecPtr really is that record.
Thanks to the reproducing steps, I reproduced it the same way you did. hole_offset set to 0 in an uncompressed FPI, CRC recomputed. I crashed a cluster with kill -9
partway through a transaction after a checkpoint, then corrupted an FPI from that transaction, at 0/01821288.
Crash recovery reported these LSNs (in all cases "redo done at 0/01821248"):
recovery_prefetch=try recovery_prefetch=off
unpatched 0/0180F608 0/01821248
patched 0/01821288 0/01821288
With prefetching on, the unpatched message named the redo start point, 45 records (about 71kB) before the bad record.
The prefetcher had decoded that whole span in one go before redo got its second record,
so ReadRecPtr was still at the redo point. So "several records back" in the commit message undersells it a bit.
With recovery_prefetch on, the LSN can be anywhere in the read-ahead window, and here it was the redo point. It might be worth saying that.
The patched and unpatched clusters ended up the same, i.e same stop point, same rows, and byte-identical relation files (pg_control differed only
in timestamps). So 0001 changes only the message, which makes it an easy backpatch.
One more case for pg_waldump, from a separate WAL segment (an initdb template, not the cluster above) with the same corruption applied to
the FPI at 0/010165F8. When pg_waldump is started at the bad record (-s 0/010165F8), the unpatched build reports
"could not find a valid record after 0/010165F8: ... at 0/01016568"
which is an LSN before the requested start. With 0001 it names 0/010165F8.
A few comments:
1. The WAL_DEBUG caller in XLogInsertRecord() passes EndPos, so after the patch those messages show the end of the record rather than its
start. As you say, that matches what that code logs. It's still an improvement, because debug_reader is never positioned, so the
messages printed 0/00000000 before. A line in the commit message would make the difference from the other caller clear.
2. Could we have a test? pg_waldump's 001_basic.pl checks the "error in WAL record at" message only for falling off the end of WAL, and
only matches the prefix. Patching two bytes of an FPI and fixing the CRC is easy enough in Perl, and a check that the reported LSN equals
the record's LSN would cover both 0001 and 0002. I'm happy to share the script I used if that helps.
3. pg_walinspect passes the same message through, so users of pg_get_wal_records_info() will benefit from 0001 too.
Reaging the 0002:
+1. It does what pg_rewind's extractPageMap() and pg_walinspect's ReadNextXLogRecord() already do when XLogReadRecord() fails, and with
the prefix and the message agree at the normal end of WAL. I agree about keeping it to master.
Regards,
Surya Poondla
The patched and unpatched clusters ended up the same, i.e same stop point, same rows, and byte-identical relation files (pg_control differed only
in timestamps). So 0001 changes only the message, which makes it an easy backpatch.
One more case for pg_waldump, from a separate WAL segment (an initdb template, not the cluster above) with the same corruption applied to
the FPI at 0/010165F8. When pg_waldump is started at the bad record (-s 0/010165F8), the unpatched build reports
"could not find a valid record after 0/010165F8: ... at 0/01016568"
which is an LSN before the requested start. With 0001 it names 0/010165F8.
A few comments:
1. The WAL_DEBUG caller in XLogInsertRecord() passes EndPos, so after the patch those messages show the end of the record rather than its
start. As you say, that matches what that code logs. It's still an improvement, because debug_reader is never positioned, so the
messages printed 0/00000000 before. A line in the commit message would make the difference from the other caller clear.
2. Could we have a test? pg_waldump's 001_basic.pl checks the "error in WAL record at" message only for falling off the end of WAL, and
only matches the prefix. Patching two bytes of an FPI and fixing the CRC is easy enough in Perl, and a check that the reported LSN equals
the record's LSN would cover both 0001 and 0002. I'm happy to share the script I used if that helps.
3. pg_walinspect passes the same message through, so users of pg_get_wal_records_info() will benefit from 0001 too.
Reaging the 0002:
+1. It does what pg_rewind's extractPageMap() and pg_walinspect's ReadNextXLogRecord() already do when XLogReadRecord() fails, and with
the prefix and the message agree at the normal end of WAL. I agree about keeping it to master.
Regards,
Surya Poondla
pgsql-hackers by date: