Re: improve wals replay on secondary

Hello Mariel,

1) Have you tried to run “CHECKPOINT;” on the standby to perform
restartpoint explicitly? It is possible.

2) If we talk about streaming replication, do you use replication slots? If
so, have you checked pg_replication_slots and pg_stat_replication? They can
help to troubleshoot streaming replication delays — see columns
sent_location, write_location, flush_location, and replay_location in
pg_stat_replication and restart_lsn in pg_replication_slots. If you have
delay in replaying, it should be seen there.

On Wed, May 29, 2019 at 11:39 Mariel Cherkassky <mariel(dot)cherkassky(at)gmail(dot)com>
wrote:

> Is there any messages that indicates that the secondary replayed a
> specific wal ? "restored 00000..." means that the restore_command succeeded
> but there isnt any proof that it replayed the wal.
>
> My theory regarding the issue :
> It seems, that my customer stopped the db 20 minutes after the clone have
> finished. During those 20 minutes the secondary didnt get enough wal
> records (6 wal files) so it didnt reach the max_wal_size. My
> checkpoint_timeout is set to 30minutes, therefore there wasnt any
> checkpoint. As a result of that the secondary didnt reach a restart point.
> Does that sounds reasonable ?
>
> So basically, if I clone a small primary db, the secondary would reach a
> restart point only if it reached a checkpoint (checkpoint_timeout or
> max_wal_size). However, I have cloned many small dbs and saw the it takes a
> sec to start the secondary (which means that restartpoint was reached). So
> what am I missing ?
>
> ‫בתאריך יום ד׳, 29 במאי 2019 ב-11:20 מאת ‪Fabio Pardi‬‏ <‪
> f(dot)pardi(at)portavita(dot)eu‬‏>:‬
>
>>
>>
>> On 5/29/19 9:20 AM, Mariel Cherkassky wrote:
>> > First of all thanks Fabio.
>> > I think that I'm missing something :
>> > In the next questionI'm not talking about streaming replication,rather
>> > on recovery :
>> >
>> > 1.When the secondary get the wals from the primary it tries to replay
>> > them correct ?
>>
>>
>> correct
>>
>> >
>> > 2. By replaying it just go over the wal records and run them in the
>> > secondary ?
>> >
>>
>> correct
>>
>> > 3.All those changes are saved in the shared_buffer(secondary) or the
>> > changed are immediately done on the data files blocks ?
>> >
>>
>> the changes are not saved to your datafile yet. That happens at
>> checkpoint time.
>>
>> > 4.The secondary will need a checkpoint in order to flush those changes
>> > to the data files and in order to reach a restart point ?
>> >
>>
>> yes
>>
>> > So, basically If I had a checkpoint during the clone, the secondary
>> > should also have a checkpoint when I recover the secondary right ?
>> >
>>
>> correct. Even after being in sync with master, if you restart Postgres
>> on standby, it will then re-apply the WAL files from the last checkpoint.
>>
>> In the logfile of the standby, you will see as many messages reporting
>> "restored log file" as many WAL files were produced since the last
>> checkpoint
>>
>> Hope it helps to clarify.
>>
>> regards,
>>
>> fabio pardi
>> >
>> > ‫בתאריך יום ג׳, 28 במאי 2019 ב-13:54 מאת ‪Fabio Pardi‬‏
>> > <‪f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>‬‏>:‬
>> >
>> > Hi Mariel,
>> >
>> > please keep the list posted. When you reply, use 'reply all'. That
>> > will maybe help others in the community and you might also get more
>> > help from others.
>> >
>> > answers are in line here below
>> >
>> >
>> >
>> > On 28/05/2019 10:54, Mariel Cherkassky wrote:
>> > > I have pg 9.6, repmgr version 4.3 .
>> > > I see in the logs that wal files are restored :
>> > > 2019-05-22 12:35:12 EEST 60942 LOG: restored log file
>> > "000000010000377B000000DB" from archive
>> > > that means that the restore_command worked right ?
>> > >
>> >
>> > right
>> >
>> > > According to the docs :
>> > > "In standby mode, a restartpoint is also triggered
>> > if checkpoint_segments log segments have been replayed since last
>> > restartpoint and at least one checkpoint record has been replayed.
>> > Restartpoints can't be performed more frequently than checkpoints in
>> > the master because restartpoints can only be performed at checkpoint
>> > records"
>> > > so maybe I should decrease max_wal_size or even checkpoint_timeout
>> > to force a restartpoint ?
>> > > During this gap (standby clone) 6-7 wals were generated on the
>> primary
>> > >
>> >
>> >
>> > From what you posted earlier, you should in any case have hit a
>> > checkpoint every 30 minutes. (That was also the assumption in the
>> > previous messages. If that's not happening, then i would really
>> > investigate.)
>> >
>> > That is, if during your cloning only a few WAL files were generated,
>> > then it is not enough to trigger a checkpoint and you fallback to
>> > the 30 minutes.
>> >
>> > I would not be bothered if i were you, but can always force a
>> > checkpoint on the master issuing:
>> >
>> > CHECKPOINT ;
>> >
>> > at that stage, on the standby logs you will see the messages:
>> >
>> > restartpoint starting: ..
>> >
>> > restartpoint complete: ..
>> >
>> >
>> >
>> > regards,
>> >
>> > fabio pardi
>> >
>> > >
>> > > ‫בתאריך יום ב׳, 27 במאי 2019 ב-14:04 מאת ‪Fabio Pardi‬‏
>> > <‪f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>
>> > <mailto:f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>>‬‏>:‬
>> > >
>> > > If you did not even see this messages on your standby logs:
>> > >
>> > > restartpoint starting: xlog
>> > >
>> > > then it means that the checkpoint was even never started.
>> > >
>> > > In that case, I have no clue.
>> > >
>> > > Try to describe step by step how to reproduce the problem
>> > together with
>> > > your setup and the version number of Postgres and repmgr, and
>> > i might be
>> > > able to help you further.
>> > >
>> > > regards,
>> > >
>> > > fabio pardi
>> > >
>> > > On 5/27/19 12:17 PM, Mariel Cherkassky wrote:
>> > > > standby_mode = 'on'
>> > > > primary_conninfo = 'host=X.X.X.X user=repmgr
>> > connect_timeout=10 '
>> > > > recovery_target_timeline = 'latest'
>> > > > primary_slot_name = repmgr_slot_1
>> > > > restore_command = 'rsync -avzhe ssh
>> > > > postgres(at)x(dot)x(dot)x(dot)x:/var/lib/pgsql/archive/%f
>> > /var/lib/pgsql/archive/%f ;
>> > > > gunzip < /var/lib/pgsql/archive/%f > %p'
>> > > > archive_cleanup_command =
>> '/usr/pgsql-9.6/bin/pg_archivecleanup
>> > > > /var/lib/pgsql/archive %r'
>> > > >
>> > > > ‫בתאריך יום ב׳, 27 במאי 2019 ב-12:29 מאת ‪Fabio Pardi‬‏
>> > > > <‪f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>
>> > <mailto:f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>>
>> > <mailto:f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>
>> > <mailto:f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>>>‬‏>:‬
>> > > >
>> > > > Hi Mariel,
>> > > >
>> > > > let s keep the list in cc...
>> > > >
>> > > > settings look ok.
>> > > >
>> > > > what's in the recovery.conf file then?
>> > > >
>> > > > regards,
>> > > >
>> > > > fabio pardi
>> > > >
>> > > > On 5/27/19 11:23 AM, Mariel Cherkassky wrote:
>> > > > > Hey,
>> > > > > the configuration is the same as in the primary :
>> > > > > max_wal_size = 2GB
>> > > > > min_wal_size = 1GB
>> > > > > wal_buffers = 16MB
>> > > > > checkpoint_completion_target = 0.9
>> > > > > checkpoint_timeout = 30min
>> > > > >
>> > > > > Regarding your question, I didnt see this message
>> > (consistent recovery
>> > > > > state reached at), I guess thats why the secondary
>> > isnt avaialble
>> > > > yet..
>> > > > >
>> > > > > Maybe I'm wrong, but what I understood from the
>> > documentation- restart
>> > > > > point is generated only after the secondary had a
>> > checkpoint wihch
>> > > > means
>> > > > > only after 30 minutes or after max_wal_size is reached
>> > ? But
>> > > > still, why
>> > > > > wont the secondary reach a consisteny recovery state
>> > (does it
>> > > > requires a
>> > > > > restart point to be generated ? )
>> > > > >
>> > > > >
>> > > > > ‫בתאריך יום ב׳, 27 במאי 2019 ב-12:12 מאת ‪Fabio
>> Pardi‬‏
>> > > > > <‪f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>
>> > <mailto:f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>>
>> > <mailto:f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>
>> > <mailto:f(dot)pardi(at)portavita(dot)eu <mailto:f(dot)pardi(at)portavita(dot)eu>>>
>> > > > <mailto:f(dot)pardi(at)portavita(dot)eu
>> > <mailto:f(dot)pardi(at)portavita(dot)eu> <mailto:f(dot)pardi(at)portavita(dot)eu
>> > <mailto:f(dot)pardi(at)portavita(dot)eu>> <mailto:f(dot)pardi(at)portavita(dot)eu
>> > <mailto:f(dot)pardi(at)portavita(dot)eu> <mailto:f(dot)pardi(at)portavita(dot)eu
>> > <mailto:f(dot)pardi(at)portavita(dot)eu>>>>‬‏>:‬
>> > > > >
>> > > > > Hi Mariel,
>> > > > >
>> > > > > if i m not wrong, on the secondary you will see
>> > the messages you
>> > > > > mentioned when a checkpoint happens.
>> > > > >
>> > > > > What are checkpoint_timeout and max_wal_size on
>> > your standby?
>> > > > >
>> > > > > Did you ever see this on your standby log?
>> > > > >
>> > > > > "consistent recovery state reached at .."
>> > > > >
>> > > > >
>> > > > > Maybe you can post your whole configuration of
>> > your standby
>> > > > for easier
>> > > > > debug.
>> > > > >
>> > > > > regards,
>> > > > >
>> > > > > fabio pardi
>> > > > >
>> > > > >
>> > > > >
>> > > > >
>> > > > > On 5/27/19 10:49 AM, Mariel Cherkassky wrote:
>> > > > > > Hey,
>> > > > > > PG 9.6, I have a standalone configured. I tried
>> > to start up a
>> > > > > secondary,
>> > > > > > run standby clone (repmgr). The clone process
>> > took 3 hours
>> > > > and during
>> > > > > > that time wals were generated(mostly because of
>> the
>> > > > > checkpoint_timeout).
>> > > > > > As a result of that, when I start the secondary
>> > ,I see that the
>> > > > > > secondary keeps getting the wals but I dont see
>> > any messages
>> > > > that
>> > > > > > indicate that the secondary tried to replay the
>> > wals.
>> > > > > > messages that i see :
>> > > > > > receiving incremental file list
>> > > > > > 000000010000377B000000DE
>> > > > > >
>> > > > > > sent 30 bytes received 4.11M bytes 8.22M
>> bytes/sec
>> > > > > > total size is 4.15M speedup is 1.01
>> > > > > > 2019-05-22 12:48:10 EEST 60942 LOG: restored
>> > log file
>> > > > > > "000000010000377B000000DE" from archive
>> > > > > > 2019-05-22 12:48:11 EEST db63311 FATAL: the
>> > database system is
>> > > > > starting up
>> > > > > > 2019-05-22 12:48:12 EEST db63313 FATAL: the
>> > database system is
>> > > > > > starting up
>> > > > > >
>> > > > > > I was hoping to see the following messages
>> > (taken from a
>> > > > different
>> > > > > > machine) :
>> > > > > > 2019-05-27 01:15:37 EDT 7428 LOG:
>> > restartpoint starting: time
>> > > > > > 2019-05-27 01:16:18 EDT 7428 LOG:
>> > restartpoint complete:
>> > > > wrote 406
>> > > > > > buffers (0.2%); 1 transaction log file(s) added,
>> > 0 removed, 0
>> > > > > recycled;
>> > > > > > write=41.390 s, sync=0.001 s, total=41.582 s;
>> > sync file
>> > > > > > s=128, longest=0.000 s, average=0.000 s;
>> > distance=2005 kB,
>> > > > > estimate=2699 kB
>> > > > > > 2019-05-27 01:16:18 EDT 7428 LOG: recovery
>> > restart point at
>> > > > > 4/D096C4F8
>> > > > > >
>> > > > > > My primary settings(wals settings) :
>> > > > > > wal_buffers = 16MB
>> > > > > > checkpoint_completion_target = 0.9
>> > > > > > checkpoint_timeout = 30min
>> > > > > >
>> > > > > > Any idea what can explain why the secondary
>> > doesnt replay
>> > > > the wals ?
>> > > > >
>> > > > >
>> > > >
>> > >
>> >
>>
>