archive recovery fetching wrong segments
Hello, hackers!
I`m investigating a complains from our clients about archive recovery
speed been very slow, and I`ve noticed a really strange and, I think, a
very dangerous recovery behavior.
When running multi-timeline archive recovery, for every requested segno
startup process iterates through every timeline in restore target
timeline history, starting from highest timeline and ending in current,
and tries to fetch the segno in question from this timeline.
Consider the following example.
Timelines:
ARCHIVE INSTANCE 'node'
================================================================================================================================
TLI Parent TLI Switchpoint Min Segno Max
Segno N segments Size Zratio N backups Status
================================================================================================================================
3 2 0/AEFFEDE0 0000000300000000000000AE
0000000300000000000000D5 40 41MB 15.47 0 OK
2 1 0/A08768D0 0000000200000000000000A0
0000000200000000000000AE 15 14MB 17.24 0 OK
1 0 0/0 000000010000000000000001
0000000100000000000000BB 187 159MB 18.77 1 OK
Backup:
================================================================================================================================
Instance Version ID Recovery Time Mode WAL Mode
TLI Time Data WAL Zratio Start LSN Stop LSN Status
================================================================================================================================
node 11 Q8C8IH 2020-04-06 02:13:31+03 FULL ARCHIVE 1/0
3s 23MB 16MB 1.00 0/2000028 0/30000B8 OK
So when we are trying to restore this backup, located on Timeline 1, to
the restore target on Timeline 3, we are getting this in the PostgreSQL
log:
....
2020-04-05 23:24:36 GMT [28508]: [5-1] LOG: restored log file
"00000003.history" from archive
INFO: PID [28511]: pg_probackup archive-get WAL file:
000000030000000000000002, remote: none, threads: 1/1, batch: 20
ERROR: PID [28511]: pg_probackup archive-get failed to deliver WAL file
000000030000000000000002, prefetched: 0/20, time elapsed: 0ms
INFO: PID [28512]: pg_probackup archive-get WAL file:
000000020000000000000002, remote: none, threads: 1/1, batch: 20
ERROR: PID [28512]: pg_probackup archive-get failed to deliver WAL file
000000020000000000000002, prefetched: 0/20, time elapsed: 0ms
INFO: PID [28513]: pg_probackup archive-get WAL file:
000000010000000000000002, remote: none, threads: 1/1, batch: 20
INFO: PID [28513]: pg_probackup archive-get copied WAL file
000000010000000000000002
2020-04-05 23:24:36 GMT [28508]: [6-1] LOG: restored log file
"000000010000000000000002" from archive
...
Before requesting 000000010000000000000002 recovery tries to fetch
000000030000000000000002 and 000000020000000000000002 and that goes for
every segment, restored from the archive.
This tremendously slows down recovery speed, especially if archive is
located on remote machine with high latency network.
And it also may lead to feeding recovery with wrong WAL segment, located
on the next timeline.
Is there a reason behind this behavior?
Also I`ve attached a patch, which fixed this issue for me, but I`m not
sure, that chosen approach is sound and didn`t break something.
--
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
Attachments:
blind_recovery_fix.patchtext/x-patch; name=blind_recovery_fix.patchDownload
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index f6cd4fde2b..b4ddb246c2 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -3714,12 +3714,30 @@ XLogFileReadAnyTLI(XLogSegNo segno, int emode, int source)
foreach(cell, tles)
{
TimeLineID tli = ((TimeLineHistoryEntry *) lfirst(cell))->tli;
+ XLogRecPtr switchpoint = ((TimeLineHistoryEntry *) lfirst(cell))->begin;
if (tli < curFileTLI)
break; /* don't bother looking at too-old TLIs */
if (source == XLOG_FROM_ANY || source == XLOG_FROM_ARCHIVE)
{
+ /* If current timeline is from the future ... */
+ if (tli > curFileTLI && switchpoint != InvalidXLogRecPtr)
+ {
+ XLogSegNo switchSegno;
+
+ XLByteToSeg(switchpoint, switchSegno, wal_segment_size);
+
+ /* ... and requested segno is not the segment with switchpoint, then
+ * skip current timeline */
+ if (segno < switchSegno)
+ {
+ elog(WARNING, "Skipping timeline: %u, switch segno: %u, current segno: %u", tli, switchSegno, segno);
+ continue;
+ }
+ }
+
+
fd = XLogFileRead(segno, emode, tli,
XLOG_FROM_ARCHIVE, true);
if (fd != -1)
Hi Grigory,
On 4/5/20 8:02 PM, Grigory Smolkin wrote:
Hello, hackers!
I`m investigating a complains from our clients about archive recovery
speed been very slow, and I`ve noticed a really strange and, I think, a
very dangerous recovery behavior.When running multi-timeline archive recovery, for every requested segno
startup process iterates through every timeline in restore target
timeline history, starting from highest timeline and ending in current,
and tries to fetch the segno in question from this timeline.
<snip>
Is there a reason behind this behavior?
Also I`ve attached a patch, which fixed this issue for me, but I`m not
sure, that chosen approach is sound and didn`t break something.
This sure looks like [1]/messages/by-id/792ea085-95c4-bca0-ae82-47fdc80e146d@oss.nttdata.com which has a completed patch nearly ready to
commit. Can you confirm and see if the proposed patch looks good?
--
-David
david@pgmasters.net
[1]: /messages/by-id/792ea085-95c4-bca0-ae82-47fdc80e146d@oss.nttdata.com
/messages/by-id/792ea085-95c4-bca0-ae82-47fdc80e146d@oss.nttdata.com
On 4/6/20 9:17 PM, David Steele wrote:
Hi Grigory,
Hello!
On 4/5/20 8:02 PM, Grigory Smolkin wrote:
Hello, hackers!
I`m investigating a complains from our clients about archive recovery
speed been very slow, and I`ve noticed a really strange and, I think,
a very dangerous recovery behavior.When running multi-timeline archive recovery, for every requested
segno startup process iterates through every timeline in restore
target timeline history, starting from highest timeline and ending in
current, and tries to fetch the segno in question from this timeline.<snip>
Is there a reason behind this behavior?
Also I`ve attached a patch, which fixed this issue for me, but I`m
not sure, that chosen approach is sound and didn`t break something.This sure looks like [1] which has a completed patch nearly ready to
commit. Can you confirm and see if the proposed patch looks good?
Well I`ve been testing it all day and so far nothing is broken.
But this foreach(xlog.c:3777) loop looks very strange to me, it is not
robust, we are blindly going over timelines and feeding recovery some
files, hoping they are the right ones. I think we can do better, because:
1. we know whether or not we are running multi-timeline recovery
2. we know next timeline ID and can calculate switchpoint segment
3. make an informed decision about from what timeline we must requesting
files now.
I will work on it.
--
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
On 4/6/20 3:23 PM, Grigory Smolkin wrote:
On 4/6/20 9:17 PM, David Steele wrote:
Hi Grigory,
Hello!
On 4/5/20 8:02 PM, Grigory Smolkin wrote:
Hello, hackers!
I`m investigating a complains from our clients about archive recovery
speed been very slow, and I`ve noticed a really strange and, I think,
a very dangerous recovery behavior.When running multi-timeline archive recovery, for every requested
segno startup process iterates through every timeline in restore
target timeline history, starting from highest timeline and ending in
current, and tries to fetch the segno in question from this timeline.<snip>
Is there a reason behind this behavior?
Also I`ve attached a patch, which fixed this issue for me, but I`m
not sure, that chosen approach is sound and didn`t break something.This sure looks like [1] which has a completed patch nearly ready to
commit. Can you confirm and see if the proposed patch looks good?Well I`ve been testing it all day and so far nothing is broken.
Perhaps I wasn't clear. There is a patch in this thread:
/messages/by-id/792ea085-95c4-bca0-ae82-47fdc80e146d@oss.nttdata.com
which seems to address the same issue and is ready to be committed.
I'd suggest you have a look at that patch and see if it fixes your issue.
Regards,
--
-David
david@pgmasters.net
On 4/6/20 10:51 PM, David Steele wrote:
On 4/6/20 3:23 PM, Grigory Smolkin wrote:
On 4/6/20 9:17 PM, David Steele wrote:
Hi Grigory,
Hello!
On 4/5/20 8:02 PM, Grigory Smolkin wrote:
Hello, hackers!
I`m investigating a complains from our clients about archive
recovery speed been very slow, and I`ve noticed a really strange
and, I think, a very dangerous recovery behavior.When running multi-timeline archive recovery, for every requested
segno startup process iterates through every timeline in restore
target timeline history, starting from highest timeline and ending
in current, and tries to fetch the segno in question from this
timeline.<snip>
Is there a reason behind this behavior?
Also I`ve attached a patch, which fixed this issue for me, but I`m
not sure, that chosen approach is sound and didn`t break something.This sure looks like [1] which has a completed patch nearly ready to
commit. Can you confirm and see if the proposed patch looks good?Well I`ve been testing it all day and so far nothing is broken.
Perhaps I wasn't clear. There is a patch in this thread:
/messages/by-id/792ea085-95c4-bca0-ae82-47fdc80e146d@oss.nttdata.com
which seems to address the same issue and is ready to be committed.
I'd suggest you have a look at that patch and see if it fixes your issue.
Ops, I`ve missed it.
Thank you, I will look into it.
Regards,
--
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company