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

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

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

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

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

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

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

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

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

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/

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)

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/

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

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)

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)

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/

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&amp;dt=2021-07-16%2022%3A30%3A35
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=desmoxytes&amp;dt=2021-07-16%2021%3A52%3A04
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dragonet&amp;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&amp;dt=2021-07-17%2013%3A39%3A43
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hornet&amp;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)

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&amp;dt=2021-07-17%2013%3A39%3A43
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hornet&amp;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

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/

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