PostgreSQL Bugs

Collected from the PG bugs email list.

Bug ID16159
PG Version11.6
OSCentOS 7.6.1810 (3.10.0-957.el7.x86_64)
Opened2019-12-11 12:39:20+00
Reported byPavel Suderevsky
StatusNew

Body of first available message related to this bug follows.

The following bug has been logged on the website:

Bug reference:      16159
Logged by:          Pavel Suderevsky
Email address:      (redacted)
PostgreSQL version: 11.6
Operating system:   CentOS 7.6.1810 (3.10.0-957.el7.x86_64)
Description:        

Reproduced 11.2,11.6.

If PostgreSQL starts recovery and finds a history file for a timeline that
is higher than current one, it will request file with the segment for the
future timeline (that most likely doesn't exist yet) and only then it will
request file with the segment for current timeline. 
If archive is located on remote storage it can take huge time to find that
segments for the future timelines are not exist yet and therefore recovery
can take too long.

Example:

recovery.conf:
>restore_command = 'echo -e "Searching WAL: %f, location: %p";
/usr/bin/pgbackrest --stanza=platform archive-get %f "%p"'
>recovery_target_timeline = 'latest'
>standby_mode = 'on'

Postgres log during startup:
>
> 2019-12-06 07:11:16 CST  LOG:  database system was shut down in recovery
> at 2019-12-06 07:11:08 CST
> Searching WAL: 00000022.history, location: pg_wal/RECOVERYHISTORY
> 2019-12-06 07:11:16 CST  LOG:  restored log file "00000022.history" from
> archive
> Searching WAL: 00000023.history, location: pg_wal/RECOVERYHISTORY
> 2019-12-06 07:11:16 CST  LOG:  entering standby mode
> Searching WAL: 00000022.history, location: pg_wal/RECOVERYHISTORY
> 2019-12-06 07:11:16 CST  LOG:  restored log file "00000022.history" from
> archive
> Searching WAL: 00000022000018C60000003F, location: pg_wal/RECOVERYXLOG
> Searching WAL: 00000021000018C60000003F, location: pg_wal/RECOVERYXLOG
> 2019-12-06 07:11:20 CST  LOG:  restored log file
> "00000021000018C60000003F" from archive
> Searching WAL: 00000021.history, location: pg_wal/RECOVERYHISTORY
> 2019-12-06 07:11:20 CST  LOG:  restored log file "00000021.history" from
> archive
> Searching WAL: 00000022000018BF0000001B, location: pg_wal/RECOVERYXLOG
> Searching WAL: 00000021000018BF0000001B, location: pg_wal/RECOVERYXLOG
> 2019-12-06 07:11:27 CST  LOG:  restored log file
> "00000021000018BF0000001B" from archive
> 2019-12-06 07:11:27 CST  LOG:  redo starts at 18BF/1B311260
> Searching WAL: 00000022000018BF0000001C, location: pg_wal/RECOVERYXLOG
> Searching WAL: 00000021000018BF0000001C, location: pg_wal/RECOVERYXLOG
> 2019-12-06 07:11:34 CST  LOG:  restored log file
> "00000021000018BF0000001C" from archive
> Searching WAL: 00000022000018BF0000001D, location: pg_wal/RECOVERYXLOG
> Searching WAL: 00000021000018BF0000001D, location: pg_wal/RECOVERYXLOG
> 2019-12-06 07:11:40 CST  LOG:  restored log file
> "00000021000018BF0000001D" from archive
> Searching WAL: 00000022000018BF0000001E, location: pg_wal/RECOVERYXLOG
> Searching WAL: 00000021000018BF0000001E, location: pg_wal/RECOVERYXLOG
> 2019-12-06 07:11:46 CST  LOG:  restored log file
> "00000021000018BF0000001E" from archive
> Searching WAL: 00000022000018BF0000001F, location: pg_wal/RECOVERYXLOG
> Searching WAL: 00000021000018BF0000001F, location: pg_wal/RECOVERYXLOG
> 2019-12-06 07:11:53 CST  LOG:  restored log file
> "00000021000018BF0000001F" from archive

As you can see Postgres tries to restore  00000022* WALs before timeline
switch LSN has been reached while restoring 00000021*.

Messages

DateAuthorSubject
2019-12-11 12:39:20+00PG Bug reporting formBUG #16159: recovery requests WALs for the next timelines before timeline switch LSN has been reached
2019-12-12 03:48:56+00Kyotaro HoriguchiRe: BUG #16159: recovery requests WALs for the next timelines before timeline switch LSN has been reached
2020-01-28 16:13:32+00Pavel SuderevskyRe: BUG #16159: recovery requests WALs for the next timelines before timeline switch LSN has been reached