BUG #18417: Excessive log messages on warm standby server

From: PG Bug reporting form <noreply(at)postgresql(dot)org>
To: pgsql-bugs(at)lists(dot)postgresql(dot)org
Cc: dkorzunov(at)symmetryinvestments(dot)com
Subject: BUG #18417: Excessive log messages on warm standby server
Date: 2024-03-29 04:44:27
Message-ID: 18417-174d6d30bfbedda3@postgresql.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

The following bug has been logged on the website:

Bug reference: 18417
Logged by: Denis Korzunov
Email address: dkorzunov(at)symmetryinvestments(dot)com
PostgreSQL version: 16.2
Operating system: Debian Bullseye
Description:

I have log-shipping replication set up. The master server generates archive
files which are then sent to a remote location where replica server reads
them and applies changes.

The nature of the application is that writes occur in batches, large volumes
but infrequently, a few times per day.
The warm standby server generates the following messages every
wal_retrieve_retry_interval, which is 5 seconds by default:

2024-03-29 04:30:25.436 UTC [35160] LOG: waiting for WAL to become
available at 0/5000018
2024-03-29 04:30:30.441 UTC [35160] LOG: waiting for WAL to become
available at 0/5000018
2024-03-29 04:30:35.443 UTC [35160] LOG: waiting for WAL to become
available at 0/5000018
2024-03-29 04:30:40.448 UTC [35160] LOG: waiting for WAL to become
available at 0/5000018
2024-03-29 04:30:45.449 UTC [35160] LOG: waiting for WAL to become
available at 0/5000018

There were no such messages in PostgreSQL 14. From what I can tell, it
first appeared in PostgresQL 15 and continued in 16.

I did a bit of digging in the source code and in PostgreSQL 14 the
WaitForWALToBecomeAvailable (xlog.c) function[1] didn't have the code to log
such message, however starting from PostgresSQL 15 the function has been
moved to xlogrecovery.c[2] and contains the statement:

elog(LOG, "waiting for WAL to become available at %X/%X",
LSN_FORMAT_ARGS(RecPtr));

The problem is that the log level here is set to LOG and to turn the message
off I have to set log_min_messages to "fatal" which cuts off many useful
messages I'd prefer to keep in the log file.

The relevant configuration parameters are:

log_min_messages = info
archive_mode = on
archive_command = 'test ! -f /archive/%f && zstd --quiet %p -o
/archive/tmp/%f && mv /archive/tmp/%f /archive/%f'
archive_timeout = 30
restore_command = 'test -f /archive/%f && zstd --quiet --decompress
/archive/%f -o /archive/tmp/%f && mv /archive/tmp/%f %p'

Links to source code:
[1]
https://github.com/postgres/postgres/blob/REL_14_STABLE/src/backend/access/transam/xlog.c#L12761
[2]
https://github.com/postgres/postgres/blob/master/src/backend/access/transam/xlogrecovery.c#L3690

Browse pgsql-bugs by date

  From Date Subject
Next Message Ronan Dunklau 2024-03-29 08:47:52 Re: FSM Corruption (was: Could not read block at end of the relation)
Previous Message Scott Ribe 2024-03-29 02:03:31 Re: BUG #18405: flaw in dump of inherited/dropped constraints