Re: Why standby restores some WALs many times from archive?

[Sergey Burladyan]

I think I found what happened here.

One WAL record can be split between WAL files.

In XLogReadRecord, if last WAL record is incomplete, it try to get next WAL:
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
   state->readBuf + RecPtr % XLOG_BLCKSZ, len);
buffer = state->readRecordBuf + len;
gotlen = len;

do
{
/* Calculate pointer to beginning of next page */
targetPagePtr += XLOG_BLCKSZ;

/* Wait for the next page to become available */
readOff = ReadPageInternal(state, targetPagePtr,
 Min(total_len 
- gotlen + SizeOfXLogShortPHD,
 
XLOG_BLCKSZ));

if (readOff < 0)
goto err;

but in my case next WAL not yet in archive (archive_timeout=0 in master)
and it clean cache:
err:

/*
 * Invalidate the xlog page we've cached. We might read from a different
 * source after failure.
 */
state->readSegNo = 0;
state->readOff = 0;
state->readLen = 0;

PG switch to streaming and last WAL (0001002B for
example) still not replayed completely. We do not use streaming and it
switch back to archive:
LOG:  restored log file "0001002B" from archive
...
DEBUG:  could not restore file "0001002C" from archive: child 
process exited with exit code 1
DEBUG:  switched WAL source from archive to stream after failure
DEBUG:  switched WAL source from stream to archive after failure

Now it must reread first part of last WAL record from
0001002B, but XLogFileReadAnyTLI is _always_ read
from the archive first, even if this file is already in pg_xlog:
if (source == XLOG_FROM_ANY || source == XLOG_FROM_ARCHIVE)
{
fd = XLogFileRead(segno, emode, tli,
  XLOG_FROM_ARCHIVE, 
true);
if (fd != -1)
{
elog(DEBUG1, "got WAL segment from archive");
if (!expectedTLEs)
expectedTLEs = tles;
return fd;
}
}

if (source == XLOG_FROM_ANY || source == XLOG_FROM_PG_XLOG)
{
fd = XLogFileRead(segno, emode, tli,
  XLOG_FROM_PG_XLOG, 
true);
if (fd != -1)
{
if (!expectedTLEs)
expectedTLEs = tles;
return fd;
}
}

Well, I think we'll be able to cache locally the last WAL file in 
restore_command
if needed :-)

-- 
Sergey Burladyan

Re: Why standby restores some WALs many times from archive?

[Sergey Burladyan]

0002B" from archive
DEBUG:  got WAL segment from archive
DEBUG:  executing restore command "cp 
/var/lib/postgresql/wals/0001002C pg_xlog/RECOVERYXLOG"
cp: cannot stat ‘/var/lib/postgresql/wals/0001002C’: No such 
file or directory
DEBUG:  could not restore file "0001002C" from archive: child 
process exited with exit code 1
DEBUG:  unexpected pageaddr 0/2100 in log segment 0001002C, 
offset 0
DEBUG:  switched WAL source from archive to stream after failure
DEBUG:  switched WAL source from stream to archive after failure
DEBUG:  executing restore command "cp 
/var/lib/postgresql/wals/0001002B pg_xlog/RECOVERYXLOG"
LOG:  restored log file "0001002B" from archive
DEBUG:  got WAL segment from archive
DEBUG:  executing restore command "cp 
/var/lib/postgresql/wals/0001002C pg_xlog/RECOVERYXLOG"
LOG:  restored log file "0001002C" from archive
DEBUG:  got WAL segment from archive


-- 
Sergey Burladyan



standby.log.bz2
Description: BZip2 compressed data


pg-wal-arch-test.tar.bz2
Description: Unix tar archive

Re: Why standby restores some WALs many times from archive?

[Sergey Burladyan]

Michael Paquier  writes:

> On Sat, Dec 30, 2017 at 04:30:07AM +0300, Sergey Burladyan wrote:
> > We use this scripts:
> > https://github.com/avito-tech/dba-utils/tree/master/pg_archive
> > 
> > But I can reproduce problem with simple cp & mv:
> > archive_command:
> >   test ! -f /var/lib/postgresql/wals/%f && \
> >   test ! -f /var/lib/postgresql/wals/%f.tmp && \
> >   cp %p /var/lib/postgresql/wals/%f.tmp && \
> >   mv /var/lib/postgresql/wals/%f.tmp /var/lib/postgresql/wals/%f
>
> This is unsafe. PostgreSQL expects the WAL segment archived to be
> flushed to disk once the archive command has returned its result to the
> backend.

Yes, you are right, thank you for pointing that out! I upload new
version with sync to github.

> Don't be surprised if you get corrupted instances or that you
> are not able to recover up to a consistent point if you need to roll in
> a backup.

But only if archive was reboot unexpectedly, am I right?

-- 
Sergey Burladyan