Horton

Thread

Commits

  1. Close yet another race condition in replication slot test code

  2. Make new replication slot test code even less racy

  3. Make new replication slot test code less racy

  4. Advance old-segment horizon properly after slot invalidation

  1. BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    The Post Office <noreply@postgresql.org> — 2021-07-13T09:15:17Z

    The following bug has been logged on the website:

Bug reference:      17103
Logged by:          Marcin Krupowicz
Email address:      mk@071.ovh
PostgreSQL version: 13.3
Operating system:   CentOS 7.6
Description:        

Hi,

After the replication fell behind and the lag exceeded
max_slot_wal_keep_size, WAL on master were not removed. It seems that
Postgres tried to maintain max_slot_wal_keep_size worth of segments. Please
find the details below (sligthly redacted version of what I wrote here:
https://stackoverflow.com/questions/68314222/replication-lag-exceeding-max-slot-wal-keep-size-wal-segments-not-removed).


-- Summary --
We are using max_slot_wal_keep_size from Postgresql 13 to prevent master
from being killed by a lagging replication. It seems, that in our case, WAL
storage wasn't freed up after exceeding this parameter which resulted in a
replication failure. WAL which, as I believe, should have been freed up did
not seem to be needed by any other transaction at a time.

-- Configuration --
master & one replica - streaming replication using a slot
~700GB available for pg_wal
max_slot_wal_keep_size = 600GB
min_wal_size = 20GB
max_wal_size = 40GB
default checkpoint_timeout = 5 minutes (no problem with checkpoints)
archiving is on and is catching up well

-- What happened --
Under heavy load (large COPY/INSERT transactions, loading hundreds of GB of
data), the replication started falling behind. Available space on pg_wal was
being reduced in the same rate as safe_slot
pg_replication_slot.safe_wal_size - as expected. At some point safe_wal_size
went negative and streaming stopped working. It wasn't a problem, because
replica started recovery from WAL archive. I expected that once the slot is
lost, WALs will be removed up to max_wal_size. This did not happen though.
It seems that Postgres tried to maintain something close to
max_slot_wal_keep_size (600GB) available, in case replica starts catching up
again. Over the time, there was no single transaction which would require
this much WAL to be kept. archiving wasn't behind either.

Amount of free space on pg_wal was more or less 70GB for most of the time,
however at some point, during heavy autovacuuming, it dipped to 0 :( This is
when PG crashed and (auto-recovered soon after). After getting back up,
there was 11GB left on pg_wal and no transaction running, no loading. This
lasted for hours. During this time replica finally caught up from the
archive and restored the replication with no delay. None of the WALs were
removed. I manually run checkpoint but it did not clear any WALs. I finally
restarted Postgresql and during the restarting pg_wal were finally
cleared.

Again - why PG did not clear WAL? WALs, even more clearly, were not needed
by any process.

Many thanks,
-- Marcin

  2. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-14T02:12:14Z

    At Tue, 13 Jul 2021 09:15:17 +0000, PG Bug reporting form <noreply@postgresql.org> wrote in 
> We are using max_slot_wal_keep_size from Postgresql 13 to prevent master
> from being killed by a lagging replication. It seems, that in our case, WAL
> storage wasn't freed up after exceeding this parameter which resulted in a
> replication failure. WAL which, as I believe, should have been freed up did
> not seem to be needed by any other transaction at a time.

Yeah, the max_slot_wal_keep_size is the maximum WAL size that
replication slots are guaranteed to be able to keep files up to.  It
is not the size that replication slot are guaranteed not to keep WAL
files beyond it.  Addition to that, WAL removal happens only at the
ending of a checkpoint so WAL files can grow up to
max_slot_wal_keep_size plus checkpoint distance assuming an even load.

> -- Configuration --
> master & one replica - streaming replication using a slot
> ~700GB available for pg_wal
> max_slot_wal_keep_size = 600GB
> min_wal_size = 20GB
> max_wal_size = 40GB
> default checkpoint_timeout = 5 minutes (no problem with checkpoints)
> archiving is on and is catching up well

Assuming an even load (or WAL speed) and 0.5 for
checkpoint_completion_target, 40GB of max_wal_size causes checkpoints
every 27GB (1706 segments) (*1) at longest (in the case where xlog
checkpoint fires before timeout checkpoint).

Thus with 600GB of max_slot_wal_keep_size, the maximum size of WAL
files can reach 627GB, which size can even be exceeded if a sudden
high-load is given.

[1] checkpoint distance = max_wal_size / (1.0 + checkpoint_completion_target)

> -- What happened --
> Under heavy load (large COPY/INSERT transactions, loading hundreds of GB of
> data), the replication started falling behind. Available space on pg_wal was
> being reduced in the same rate as safe_slot
> pg_replication_slot.safe_wal_size - as expected. At some point safe_wal_size
> went negative and streaming stopped working. It wasn't a problem, because
> replica started recovery from WAL archive. I expected that once the slot is
> lost, WALs will be removed up to max_wal_size. This did not happen though.
> It seems that Postgres tried to maintain something close to
> max_slot_wal_keep_size (600GB) available, in case replica starts catching up
> again. Over the time, there was no single transaction which would require
> this much WAL to be kept. archiving wasn't behind either.

Useless WAL files will be removd after a checkpoint runs.

> Amount of free space on pg_wal was more or less 70GB for most of the time,
> however at some point, during heavy autovacuuming, it dipped to 0 :( This is
> when PG crashed and (auto-recovered soon after). After getting back up,
> there was 11GB left on pg_wal and no transaction running, no loading. This
> lasted for hours. During this time replica finally caught up from the
> archive and restored the replication with no delay. None of the WALs were
> removed. I manually run checkpoint but it did not clear any WALs. I finally
> restarted Postgresql and during the restarting pg_wal were finally
> cleared.
>
> Again - why PG did not clear WAL? WALs, even more clearly, were not needed
> by any process.

Maybe manual CHECKPINT work for you , however, you should reconsider
the setting assuming the above behavior to prevent a crash due to WAL
storage exhaustion.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  3. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Marcin Krupowicz <marcin@071.ovh> — 2021-07-14T07:52:34Z

    Hi,

> > We are using max_slot_wal_keep_size from Postgresql 13 to prevent master
> > from being killed by a lagging replication. It seems, that in our case, WAL
> > storage wasn't freed up after exceeding this parameter which resulted in a
> > replication failure. WAL which, as I believe, should have been freed up did
> > not seem to be needed by any other transaction at a time.
>
> Yeah, the max_slot_wal_keep_size is the maximum WAL size that
> replication slots are guaranteed to be able to keep files up to.  It
> is not the size that replication slot are guaranteed not to keep WAL
> files beyond it.  Addition to that, WAL removal happens only at the
> ending of a checkpoint so WAL files can grow up to
> max_slot_wal_keep_size plus checkpoint distance assuming an even load.

I understand, but the situation lasted for many hours, until my manual
reboot. checkpoint timeout is 5 minutes, there were many checkpoints
between the time when the slot got lost (exceeding
max_slow_wal_keep_size) and my manual reboot. During all that time
load was fairly even and the amount of WAL segments stored wasn't
changing much.


> > -- Configuration --
> > master & one replica - streaming replication using a slot
> > ~700GB available for pg_wal
> > max_slot_wal_keep_size = 600GB
> > min_wal_size = 20GB
> > max_wal_size = 40GB
> > default checkpoint_timeout = 5 minutes (no problem with checkpoints)
> > archiving is on and is catching up well
>
> Assuming an even load (or WAL speed) and 0.5 for
> checkpoint_completion_target, 40GB of max_wal_size causes checkpoints
> every 27GB (1706 segments) (*1) at longest (in the case where xlog
> checkpoint fires before timeout checkpoint).
>
> Thus with 600GB of max_slot_wal_keep_size, the maximum size of WAL
> files can reach 627GB, which size can even be exceeded if a sudden
> high-load is given.
>
> [1] checkpoint distance = max_wal_size / (1.0 + checkpoint_completion_target)

Fair point, I should change my settings slightly - but that's not the
issue here.

>
> > -- What happened --
> > Under heavy load (large COPY/INSERT transactions, loading hundreds of GB of
> > data), the replication started falling behind. Available space on pg_wal was
> > being reduced in the same rate as safe_slot
> > pg_replication_slot.safe_wal_size - as expected. At some point safe_wal_size
> > went negative and streaming stopped working. It wasn't a problem, because
> > replica started recovery from WAL archive. I expected that once the slot is
> > lost, WALs will be removed up to max_wal_size. This did not happen though.
> > It seems that Postgres tried to maintain something close to
> > max_slot_wal_keep_size (600GB) available, in case replica starts catching up
> > again. Over the time, there was no single transaction which would require
> > this much WAL to be kept. archiving wasn't behind either.
>
> Useless WAL files will be removd after a checkpoint runs.

That did not happen.

> > Amount of free space on pg_wal was more or less 70GB for most of the time,
> > however at some point, during heavy autovacuuming, it dipped to 0 :( This is
> > when PG crashed and (auto-recovered soon after). After getting back up,
> > there was 11GB left on pg_wal and no transaction running, no loading. This
> > lasted for hours. During this time replica finally caught up from the
> > archive and restored the replication with no delay. None of the WALs were
> > removed. I manually run checkpoint but it did not clear any WALs. I finally
> > restarted Postgresql and during the restarting pg_wal were finally
> > cleared.
> >
> > Again - why PG did not clear WAL? WALs, even more clearly, were not needed
> > by any process.
>
> Maybe manual CHECKPINT work for you , however, you should reconsider
> the setting assuming the above behavior to prevent a crash due to WAL
> storage exhaustion.

Sorry, I'm confused. I did run manual CHECKPOINT (even though there
were many, many non-manual checkpoints run before that) and WAL
segments were NOT cleared, until I restarted postgresql.

Thanks,
-- Marcin

  4. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Jeff Janes <jeff.janes@gmail.com> — 2021-07-14T23:10:26Z

    On Tue, Jul 13, 2021 at 10:12 PM Kyotaro Horiguchi <horikyota.ntt@gmail.com>
wrote:

> At Tue, 13 Jul 2021 09:15:17 +0000, PG Bug reporting form <
> noreply@postgresql.org> wrote in
> > We are using max_slot_wal_keep_size from Postgresql 13 to prevent master
> > from being killed by a lagging replication. It seems, that in our case,
> WAL
> > storage wasn't freed up after exceeding this parameter which resulted in
> a
> > replication failure. WAL which, as I believe, should have been freed up
> did
> > not seem to be needed by any other transaction at a time.
>
> Yeah, the max_slot_wal_keep_size is the maximum WAL size that
> replication slots are guaranteed to be able to keep files up to.  It
> is not the size that replication slot are guaranteed not to keep WAL
> files beyond it.  Addition to that, WAL removal happens only at the
> ending of a checkpoint so WAL files can grow up to
> max_slot_wal_keep_size plus checkpoint distance assuming an even load.
>
> > -- Configuration --
> > master & one replica - streaming replication using a slot
> > ~700GB available for pg_wal
> > max_slot_wal_keep_size = 600GB
> > min_wal_size = 20GB
> > max_wal_size = 40GB
> > default checkpoint_timeout = 5 minutes (no problem with checkpoints)
> > archiving is on and is catching up well
>
> Assuming an even load (or WAL speed) and 0.5 for
> checkpoint_completion_target, 40GB of max_wal_size causes checkpoints
> every 27GB (1706 segments) (*1) at longest (in the case where xlog
> checkpoint fires before timeout checkpoint).
>
> Thus with 600GB of max_slot_wal_keep_size, the maximum size of WAL
> files can reach 627GB, which size can even be exceeded if a sudden
> high-load is given.
>
> [1] checkpoint distance = max_wal_size / (1.0 +
> checkpoint_completion_target)
>
> > -- What happened --
> > Under heavy load (large COPY/INSERT transactions, loading hundreds of GB
> of
> > data), the replication started falling behind. Available space on pg_wal
> was
> > being reduced in the same rate as safe_slot
> > pg_replication_slot.safe_wal_size - as expected. At some point
> safe_wal_size
> > went negative and streaming stopped working. It wasn't a problem, because
> > replica started recovery from WAL archive. I expected that once the slot
> is
> > lost, WALs will be removed up to max_wal_size. This did not happen
> though.
> > It seems that Postgres tried to maintain something close to
> > max_slot_wal_keep_size (600GB) available, in case replica starts
> catching up
> > again. Over the time, there was no single transaction which would require
> > this much WAL to be kept. archiving wasn't behind either.
>
> Useless WAL files will be removd after a checkpoint runs.
>

They should be, but they are not.  That is the bug.   They just hang
around, checkpoint after checkpoint.  Some of them do get cleaned up, to
make up for new ones created during that cycle.  It treats
max_slot_wal_keep the same way it treats wal_keep_size (but only if a
"lost" slot is hanging around).  If you drop the lost slot, only then does
it remove all the accumulated WAL at the next checkpoint.

Cheers,

Jeff

  5. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-15T05:22:35Z

    At Wed, 14 Jul 2021 19:10:26 -0400, Jeff Janes <jeff.janes@gmail.com> wrote in 
> On Tue, Jul 13, 2021 at 10:12 PM Kyotaro Horiguchi <horikyota.ntt@gmail.com>
> wrote:
> > Useless WAL files will be removd after a checkpoint runs.
> >
> 
> They should be, but they are not.  That is the bug.   They just hang
> around, checkpoint after checkpoint.  Some of them do get cleaned up, to
> make up for new ones created during that cycle.  It treats
> max_slot_wal_keep the same way it treats wal_keep_size (but only if a
> "lost" slot is hanging around).  If you drop the lost slot, only then does
> it remove all the accumulated WAL at the next checkpoint.

Thanks! I saw the issue here.  Some investigation showd me a doubious
motion of XLogCtl->repliationSlotMinLSN.  Slot invalidation is
forgetting to recalculate it and that misbehavior retreats the segment
horizon.

So the attached worked for me.  I'll repost the polished version
including test.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  6. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-15T07:33:48Z

    At Thu, 15 Jul 2021 14:22:35 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> At Wed, 14 Jul 2021 19:10:26 -0400, Jeff Janes <jeff.janes@gmail.com> wrote in 
> > They should be, but they are not.  That is the bug.   They just hang
> > around, checkpoint after checkpoint.  Some of them do get cleaned up, to
> > make up for new ones created during that cycle.  It treats
> > max_slot_wal_keep the same way it treats wal_keep_size (but only if a
> > "lost" slot is hanging around).  If you drop the lost slot, only then does
> > it remove all the accumulated WAL at the next checkpoint.
> 
> Thanks! I saw the issue here.  Some investigation showd me a doubious
> motion of XLogCtl->repliationSlotMinLSN.  Slot invalidation is
> forgetting to recalculate it and that misbehavior retreats the segment
> horizon.
> 
> So the attached worked for me.  I'll repost the polished version
> including test.

This is it. It is for the master branch but also applicable to 14 as
is. Not needed for earlier version.
I believe the test works for Windows but haven't checked.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  7. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Marcin Krupowicz <marcin@071.ovh> — 2021-07-15T08:59:38Z

    On Thu, 15 Jul 2021 at 08:33, Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote:
> This is it. It is for the master branch but also applicable to 14 as
> is. Not needed for earlier version.
> I believe the test works for Windows but haven't checked.

Thanks for that. To clarify - is it not going to be fixed in 13.x?

-- Marcin

  8. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-15T16:09:45Z

    On 2021-Jul-15, Marcin Krupowicz wrote:

> On Thu, 15 Jul 2021 at 08:33, Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote:
> > This is it. It is for the master branch but also applicable to 14 as
> > is. Not needed for earlier version.
> > I believe the test works for Windows but haven't checked.

Oh my, what an oversight.  Thanks Kyotaro for the investigation and fix;
I'll get it pushed today.

> Thanks for that. To clarify - is it not going to be fixed in 13.x?

It definitely is, since the feature is there.  I'll fix the apply
conflicts, since they're pretty trivial.  (No need to send a new patch.)

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"Ed is the standard text editor."
      http://groups.google.com/group/alt.religion.emacs/msg/8d94ddab6a9b0ad3

  9. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Jeff Janes <jeff.janes@gmail.com> — 2021-07-15T16:11:07Z

    On Thu, Jul 15, 2021 at 1:22 AM Kyotaro Horiguchi <horikyota.ntt@gmail.com>
wrote:

> At Wed, 14 Jul 2021 19:10:26 -0400, Jeff Janes <jeff.janes@gmail.com>
> wrote in
> > On Tue, Jul 13, 2021 at 10:12 PM Kyotaro Horiguchi <
> horikyota.ntt@gmail.com>
> > wrote:
> > > Useless WAL files will be removd after a checkpoint runs.
> > >
> >
> > They should be, but they are not.  That is the bug.   They just hang
> > around, checkpoint after checkpoint.  Some of them do get cleaned up, to
> > make up for new ones created during that cycle.  It treats
> > max_slot_wal_keep the same way it treats wal_keep_size (but only if a
> > "lost" slot is hanging around).  If you drop the lost slot, only then
> does
> > it remove all the accumulated WAL at the next checkpoint.
>
> Thanks! I saw the issue here.  Some investigation showd me a doubious
> motion of XLogCtl->repliationSlotMinLSN.  Slot invalidation is
> forgetting to recalculate it and that misbehavior retreats the segment
> horizon.
>
> So the attached worked for me.  I'll repost the polished version
> including test.
>

Thank you.  That works for me.  But I did not test on Windows.

   * Some slots may have been gone,

"been invalidated" reads better than "been gone", and matches the wording
used elsewhere.

Cheers,

Jeff

  10. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-15T19:09:55Z

    On 2021-Jul-15, Kyotaro Horiguchi wrote:

> This is it. It is for the master branch but also applicable to 14 as
> is. Not needed for earlier version.
> I believe the test works for Windows but haven't checked.

I looked at it.  I think it is better to make the calls to 
ReplicationSlotsComputeRequiredLSN() in slot.c (which is where most other
calls to that function are).  Also we should recompute the minimum
required Xmin at that point.

Another change I did was move the "*invalidated=true" assignment to the
block where we actually invalidate the slot; in your patch you were
doing it possibly too early if the slot was in use by some other
process.  (For end effect it probably doesn't matter much, but it's
better to have it right.)

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/

  11. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-15T20:49:10Z

    On 2021-Jul-15, Kyotaro Horiguchi wrote:

> > Thanks! I saw the issue here.  Some investigation showd me a doubious
> > motion of XLogCtl->repliationSlotMinLSN.  Slot invalidation is
> > forgetting to recalculate it and that misbehavior retreats the segment
> > horizon.

Actually, looking again, isn't this supposed to happen in KeepLogSeg()?
We have a block that caps to max_slot_wal_keep_size_mb there ... why did
that not work?

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"Sallah, I said NO camels! That's FIVE camels; can't you count?"
(Indiana Jones)

  12. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-15T21:33:20Z

    On 2021-Jul-15, Alvaro Herrera wrote:

> Actually, looking again, isn't this supposed to happen in KeepLogSeg()?
> We have a block that caps to max_slot_wal_keep_size_mb there ... why did
> that not work?

I find that this smaller patch is sufficient to make the added test case
work.  However, I'm not sure I understand *why* ...

-- 
Álvaro Herrera           39°49'30"S 73°17'W  —  https://www.EnterpriseDB.com/

  13. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-16T02:05:00Z

    At Thu, 15 Jul 2021 17:33:20 -0400, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote in 
> On 2021-Jul-15, Alvaro Herrera wrote:
> 
> > Actually, looking again, isn't this supposed to happen in KeepLogSeg()?
> > We have a block that caps to max_slot_wal_keep_size_mb there ... why did
> > that not work?
> 
> I find that this smaller patch is sufficient to make the added test case
> work.  However, I'm not sure I understand *why* ...

It's because another checkpoint is running at the time the manual
checkpoint just before is invoked.  Two successive checkpoint hides
the defect.  The checkpoint works as the rendezvous point for the
succeeding tests so I added another sync point instead of the manual
checkpoint.  The test in the attached correctly fails if _logSegNo
were not updated by slot invalidation.

By the way, about the previous version, XLByteToSeg is needed since
KeepLogSeg doesn't advance _logSegNo, which is the wanted action
here. The test in the attached fails if only KeepLogSeg is called
again.

I confirmed that *the previous* version of the test works for Windows.
(So there's no reason that the current version doesn't work.)

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  14. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-16T02:49:11Z

    On 2021-Jul-16, Kyotaro Horiguchi wrote:

> It's because another checkpoint is running at the time the manual
> checkpoint just before is invoked.  Two successive checkpoint hides
> the defect.  The checkpoint works as the rendezvous point for the
> succeeding tests so I added another sync point instead of the manual
> checkpoint.  The test in the attached correctly fails if _logSegNo
> were not updated by slot invalidation.

OK, I thought as much and tried to catch it in the act but couldn't.
Your explanation makes sense.

> By the way, about the previous version, XLByteToSeg is needed since
> KeepLogSeg doesn't advance _logSegNo, which is the wanted action
> here. The test in the attached fails if only KeepLogSeg is called
> again.

Oh, true.

> I confirmed that *the previous* version of the test works for Windows.
> (So there's no reason that the current version doesn't work.)

Great, thanks.

-- 
Álvaro Herrera              Valdivia, Chile  —  https://www.EnterpriseDB.com/
"Siempre hay que alimentar a los dioses, aunque la tierra esté seca" (Orual)

  15. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-16T16:13:40Z

    Okay, I've now pushed it.  Thanks!

-- 
Álvaro Herrera              Valdivia, Chile  —  https://www.EnterpriseDB.com/
"La libertad es como el dinero; el que no la sabe emplear la pierde" (Alvarez)

  16. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-16T18:09:33Z

    I was running tests for another patch, and this one failed once:

Testing REL_14_BETA2-168-g1cb94c3c4c started: vie jul 16 14:02:11 -04 2021

#   Failed test 'check that the warning is logged'
#   at t/019_replslot_limit.pl line 187.

#   Failed test 'check that the slot became inactive and the state "lost" persists'
#   at t/019_replslot_limit.pl line 198.
#          got: 'rep1|t|t|lost|'
#     expected: 'rep1|f|t|lost|'

#   Failed test 'check that segments have been removed'
#   at t/019_replslot_limit.pl line 213.
#          got: '000000010000000000000014'
#     expected: '00000001000000000000001C'
# Looks like you failed 3 tests of 19.
make[2]: *** [Makefile:23: check] Error 1

The buildfarm has remained green so far, but clearly this is something
we need to fix.  Maybe it's as simple as adding the loop we use below,
starting at line 219.

-- 
Álvaro Herrera           39°49'30"S 73°17'W  —  https://www.EnterpriseDB.com/

  17. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-17T14:28:09Z

    On 2021-Jul-16, Alvaro Herrera wrote:

> The buildfarm has remained green so far, but clearly this is something
> we need to fix.  Maybe it's as simple as adding the loop we use below,
> starting at line 219.

There are a few failures of this on buildfarm now,

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=flaviventris&dt=2021-07-16%2022%3A30%3A35
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=desmoxytes&dt=2021-07-16%2021%3A52%3A04
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dragonet&dt=2021-07-16%2021%3A52%3A05

I am running the test in a loop with the attached; if it doesn't fail in
a few more rounds I'll push it.

There are two instances of a different failure:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-17%2013%3A39%3A43
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hornet&dt=2021-07-16%2021%3A14%3A14

#   Failed test 'check that segments have been removed'
#   at t/019_replslot_limit.pl line 213.
#          got: '000000010000000000000021'
#     expected: '000000010000000000000022'
# Looks like you failed 1 test of 19.
[23:55:14] t/019_replslot_limit.pl .............. 
Dubious, test returned 1 (wstat 256, 0x100)

I'm afraid about this not being something we can fix with some
additional wait points ...

-- 
Álvaro Herrera              Valdivia, Chile  —  https://www.EnterpriseDB.com/
"La grandeza es una experiencia transitoria.  Nunca es consistente.
Depende en gran parte de la imaginación humana creadora de mitos"
(Irulan)

  18. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-19T02:13:18Z

    At Sat, 17 Jul 2021 10:28:09 -0400, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote in 
> On 2021-Jul-16, Alvaro Herrera wrote:
> 
> > The buildfarm has remained green so far, but clearly this is something
> > we need to fix.  Maybe it's as simple as adding the loop we use below,
> > starting at line 219.
> 
> There are a few failures of this on buildfarm now,
..
> I am running the test in a loop with the attached; if it doesn't fail in
> a few more rounds I'll push it.
> 
> There are two instances of a different failure:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-17%2013%3A39%3A43
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hornet&dt=2021-07-16%2021%3A14%3A14
> 
> #   Failed test 'check that segments have been removed'
> #   at t/019_replslot_limit.pl line 213.
> #          got: '000000010000000000000021'
> #     expected: '000000010000000000000022'
> # Looks like you failed 1 test of 19.
> [23:55:14] t/019_replslot_limit.pl .............. 
> Dubious, test returned 1 (wstat 256, 0x100)
> 
> I'm afraid about this not being something we can fix with some
> additional wait points ...

Sorry for the mistake.  It seems to me the cause the above is that
segment removal happens *after* invalidation. Since (at least
currently) the "slot is invalidated" warning issued only at the time
just before WAL-removal, we should expect that old segments are gone
after the checkpoint-ending log, which should be seen after
WAL-removal.  If not, that shows that there's a bug.

What do you think about the attached?

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  19. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-19T21:24:48Z

    On 2021-Jul-19, Kyotaro Horiguchi wrote:

> Sorry for the mistake.  It seems to me the cause the above is that
> segment removal happens *after* invalidation. Since (at least
> currently) the "slot is invalidated" warning issued only at the time
> just before WAL-removal, we should expect that old segments are gone
> after the checkpoint-ending log, which should be seen after
> WAL-removal.  If not, that shows that there's a bug.
> 
> What do you think about the attached?

Sounds sensible -- I verified the logs for one of the cases that failed
in the buildfarm, and indeed the "checkpoint ended" message appears
after the s2 slot is created, so it should fix the problem.  (I didn't
actually try to reproduce the problem locally, so I didn't verify the
fix any further than ensuring the test still passes.)

Pushed, thanks!

-- 
Álvaro Herrera           39°49'30"S 73°17'W  —  https://www.EnterpriseDB.com/

  20. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-20T04:18:20Z

    At Mon, 19 Jul 2021 17:24:48 -0400, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote in 
> On 2021-Jul-19, Kyotaro Horiguchi wrote:
> 
> > Sorry for the mistake.  It seems to me the cause the above is that
> > segment removal happens *after* invalidation. Since (at least
> > currently) the "slot is invalidated" warning issued only at the time
> > just before WAL-removal, we should expect that old segments are gone
> > after the checkpoint-ending log, which should be seen after
> > WAL-removal.  If not, that shows that there's a bug.
> > 
> > What do you think about the attached?
> 
> Sounds sensible -- I verified the logs for one of the cases that failed
> in the buildfarm, and indeed the "checkpoint ended" message appears
> after the s2 slot is created, so it should fix the problem.  (I didn't
> actually try to reproduce the problem locally, so I didn't verify the
> fix any further than ensuring the test still passes.)
> 
> Pushed, thanks!

Thaks, and sorry for the series of bugs.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  21. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Tom Lane <tgl@sss.pgh.pa.us> — 2021-07-28T15:38:28Z

    Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> On 2021-Jul-19, Kyotaro Horiguchi wrote:
>> What do you think about the attached?

> Sounds sensible -- I verified the logs for one of the cases that failed
> in the buildfarm, and indeed the "checkpoint ended" message appears
> after the s2 slot is created, so it should fix the problem.  (I didn't
> actually try to reproduce the problem locally, so I didn't verify the
> fix any further than ensuring the test still passes.)

This test is still unstable :-(

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tern&dt=2021-07-20%2012%3A46%3A11
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-20%2015%3A05%3A39
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-28%2014%3A33%3A01
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-28%2014%3A33%3A01

These all look like

#   Failed test 'check that segments have been removed'
#   at t/019_replslot_limit.pl line 226.
#          got: '000000010000000000000020'
#     expected: '000000010000000000000024'
# Looks like you failed 1 test of 16.

with varying values mentioned.  It looks to me like WAL file cleanup
is not as synchronous with slot creation as the test thinks.
Maybe it needs to loop until the oldest WAL file matches what it
expects?

			regards, tom lane

  22. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-29T07:20:38Z

    At Wed, 28 Jul 2021 11:38:28 -0400, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> This test is still unstable :-(
> 
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tern&dt=2021-07-20%2012%3A46%3A11
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-20%2015%3A05%3A39
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-28%2014%3A33%3A01
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-28%2014%3A33%3A01
> 
> These all look like
> 
> #   Failed test 'check that segments have been removed'
> #   at t/019_replslot_limit.pl line 226.
> #          got: '000000010000000000000020'
> #     expected: '000000010000000000000024'
> # Looks like you failed 1 test of 16.
> 
> with varying values mentioned.  It looks to me like WAL file cleanup
> is not as synchronous with slot creation as the test thinks.
> Maybe it needs to loop until the oldest WAL file matches what it
> expects?

Sorry for the kludge.

Mmm. In the failure cases, directory scan(@16:52:22.036) runs before
the targetted checkpoint completes(@16:52:22.144).

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=kittiwake&dt=2021-07-28%2014%3A33%3A01
16:52:17.328 LOG:  checkpoint starting: wal
16:52:19.140 LOG:  invalidating slot "rep1" because its restart_lsn 0/1D00000 exceeds max_slot_wal_keep_size
16:52:19.316 019_replslot_limit.pl LOG:  statement: SELECT pg_walfile_name(lsn) FROM pg_create_physical_replication_slot('s2', true)
16:52:22.036 019_replslot_limit.pl LOG:  statement: SELECT pg_ls_dir AS f FROM pg_ls_dir('pg_wal') WHERE pg_ls_dir ~ '^[0-9A-F]{24}$' ORDER BY 1 LIMIT
16:52:22.077 019_replslot_limit.pl LOG:  statement: SELECT pg_drop_replication_slot('s2')
16:52:22.144 LOG:  checkpoint complete: wrote 18 buffers (14.1%); 0 WAL file(s) added, 4 removed, 3 recycled; write=1.806 s, sync=0.001 s, total=4.817 s; sync files=0, longest=0.000 s, average=0.000 s; distance=3072 kB, estimate=3072 kB

The reason is the previous checkpoint completed after starting to
advance segments

> my $logstart = get_log_size($node_primary);
> advance_wal($node_primary, 7);   !!!! another checkpoint runs/ends
...
16:52:19.140  # check for "invalidate slots" in log.
              # check for the "lost" state in pg_replication_slots.
             !! checkfor "checkpint complete" in log.
16:52:22.077  # read redo segment and oldest wal.
16:52:22.144 !! The target checkpoint ends.

So it seems to me we need to explicitly prevent unexpected checkpoints
from happening maybe by enlarging max_wal_size temporily.

I'll going that way.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  23. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-29T07:45:40Z

    At Thu, 29 Jul 2021 16:20:38 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> So it seems to me we need to explicitly prevent unexpected checkpoints
> from happening maybe by enlarging max_wal_size temporily.
> 
> I'll going that way.

I ended up with the attached. It causes a checkpoint reliably exactly
at the aimed timing without.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  24. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-07-29T07:50:07Z

    (Somehow the previous mail was broken in many ways. I re-send it.)

At Thu, 29 Jul 2021 16:20:38 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> So it seems to me we need to explicitly prevent unexpected checkpoints
> from happening maybe by enlarging max_wal_size temporily.
> 
> I'll going that way.

I ended up with the attached. It causes a checkpoint reliably exactly
at the aimed timing without.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  25. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-07-29T21:19:24Z

    On 2021-Jul-29, Kyotaro Horiguchi wrote:

> At Thu, 29 Jul 2021 16:20:38 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> > So it seems to me we need to explicitly prevent unexpected checkpoints
> > from happening maybe by enlarging max_wal_size temporily.
> 
> I ended up with the attached. It causes a checkpoint reliably exactly
> at the aimed timing without.

Thanks for looking into it.  The explanation makes sense, so I pushed
your patch and also fixed one outdated comment I noticed while reading
the related code.  I hope this commit will solve the problem ... it is
quite low probability, so we'll have to wait at least two weeks to make
any conclusion.

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/

  26. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-08-02T06:00:39Z

    At Thu, 29 Jul 2021 17:19:24 -0400, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote in 
> On 2021-Jul-29, Kyotaro Horiguchi wrote:
> 
> > At Thu, 29 Jul 2021 16:20:38 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> > > So it seems to me we need to explicitly prevent unexpected checkpoints
> > > from happening maybe by enlarging max_wal_size temporily.
> > 
> > I ended up with the attached. It causes a checkpoint reliably exactly
> > at the aimed timing without.
> 
> Thanks for looking into it.  The explanation makes sense, so I pushed
> your patch and also fixed one outdated comment I noticed while reading
> the related code.  I hope this commit will solve the problem ... it is
> quite low probability, so we'll have to wait at least two weeks to make
> any conclusion.

Agreed. I hope this is the last failure..

Thanks.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  27. Re: BUG #17103: WAL segments are not removed after exceeding max_slot_wal_keep_size

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-08-02T13:08:35Z

    On 2021-Aug-02, Kyotaro Horiguchi wrote:

> Agreed. I hope this is the last failure..

There have been no failures since:

https://buildfarm.postgresql.org/cgi-bin/show_failures.pl?max_days=20&branch=HEAD&branch=REL_14_STABLE&branch=REL_13_STABLE&member=&stage=recoveryCheck&filter=Submit

-- 
Álvaro Herrera           39°49'30"S 73°17'W  —  https://www.EnterpriseDB.com/
"El hombre nunca sabe de lo que es capaz hasta que lo intenta" (C. Dickens)