Subject: Report checkpoint progress in server logs

From: Bharath Rupireddy <[email-masked]>
Date: Wed, 29 Dec 2021 20:00:54 +0530

Hi,

At times, some of the checkpoint operations such as removing old WAL
files, dealing with replication snapshot or mapping files etc. may
take a while during which the server doesn't emit any logs or
information, the only logs emitted are LogCheckpointStart and
LogCheckpointEnd. Many times this isn't a problem if the checkpoint is
quicker, but there can be extreme situations which require the users
to know what's going on with the current checkpoint.

Given that the commit 9ce346ea [1] introduced a nice mechanism to
report the long running operations of the startup process in the
server logs, I'm thinking we can have a similar progress mechanism for
the checkpoint as well. There's another idea suggested in a couple of
other threads to have a pg_stat_progress_checkpoint similar to
pg_stat_progress_analyze/vacuum/etc. But the problem with this idea is
during the end-of-recovery or shutdown checkpoints, the
pg_stat_progress_checkpoint view isn't accessible as it requires a
connection to the server which isn't allowed.

Therefore, reporting the checkpoint progress in the server logs, much
like [1], seems to be the best way IMO. We can 1) either make
ereport_startup_progress and log_startup_progress_interval more
generic (something like ereport_log_progress and
log_progress_interval),  move the code to elog.c, use it for
checkpoint progress and if required for other time-consuming
operations 2) or have an entirely different GUC and API for checkpoint
progress.

IMO, option (1) i.e. ereport_log_progress and log_progress_interval
(better names are welcome) seems a better idea.

Thoughts?

[1]
commit 9ce346eabf350a130bba46be3f8c50ba28506969
Author: Robert Haas <[email-masked]>
Date:   Mon Oct 25 11:51:57 2021 -0400

    Report progress of startup operations that take a long time.

Regards,
Bharath Rupireddy.

---

From: Magnus Hagander <[email-masked]>
Date: Wed, 29 Dec 2021 15:35:40 +0100

> (better names are welcome) seems a better idea.

I find progress reporting in the logfile to generally be a terrible
way of doing things, and the fact that we do it for the startup
process is/should be only because we have no other choice, not because
it's the right choice.

I think the right choice to solve the *general* problem is the
mentioned pg_stat_progress_checkpoints.

We may want to *additionally* have the ability to log the progress
specifically for the special cases when we're not able to use that
view. And in those case, we can perhaps just use the existing
log_startup_progress_interval parameter for this as well -- at least
for the startup checkpoint.

-- 
 Magnus Hagander
 Me: https://www.hagander.net/
 Work: https://www.redpill-linpro.com/

---

From: Tom Lane <[email-masked]>
Date: Wed, 29 Dec 2021 10:40:59 -0500

Magnus Hagander <[email-masked]> writes:
>> like [1], seems to be the best way IMO.

> process is/should be only because we have no other choice, not because

I'm already pretty seriously unhappy about the log-spamming effects of
64da07c41 (default to log_checkpoints=on), and am willing to lay a side
bet that that gets reverted after we have some field experience with it.
This proposal seems far worse from that standpoint.  Keep in mind that
our out-of-the-box logging configuration still doesn't have any log
rotation ability, which means that the noisier the server is in normal
operation, the sooner you fill your disk.

> mentioned pg_stat_progress_checkpoints.

+1

			regards, tom lane

---

From: SATYANARAYANA NARLAPURAM <[email-masked]>
Date: Wed, 29 Dec 2021 10:54:06 -0800

Coincidentally, I was thinking about the same yesterday after tired of
waiting for the checkpoint completion on a server.

> operation, the sooner you fill your disk.

Server is not open up for the queries while running the end of recovery
checkpoint and a catalog view may not help here but the process title
change or logging would be helpful in such cases. When the server is
running the recovery, anxious customers ask several times the ETA for
recovery completion, and not having visibility into these operations makes
life difficult for the DBA/operations.

> > mentioned pg_stat_progress_checkpoints.

+1 to this. We need at least a trace of the number of buffers to sync
(num_to_scan) before the checkpoint start, instead of just emitting the
stats at the end.

Bharat, it would be good to show the buffers synced counter and the total
buffers to sync, checkpointer pid, substep it is running, whether it is on
target for completion, checkpoint_Reason (manual/times/forced). BufferSync
has several variables tracking the sync progress locally, and we may need
some refactoring here.