Re: Report checkpoint progress with pg_stat_progress_checkpoint (was: Report checkpoint progress in server logs) - Mailing list pgsql-hackers

Thanks for reviewing.

> 6) How about shutdown and end-of-recovery checkpoint? Are you planning
> to have an ereport_startup_progress mechanism as 0002?

I thought of including it earlier then I felt lets first make the
current patch stable. Once all the fields are properly decided and the
patch gets in then we can easily extend the functionality to shutdown
and end-of-recovery cases. I have also observed that the timer
functionality wont work properly in case of shutdown as we are doing
an immediate checkpoint. So this needs a lot of discussion and I would
like to handle this on a separate thread.
---

> 7) I think you don't need to call checkpoint_progress_start and
> pgstat_progress_update_param, any other progress reporting function
> for shutdown and end-of-recovery checkpoint right?

I had included the guards earlier and then removed later based on the
discussion upthread.
---

> [local]:5432 ashu@postgres=# select * from pg_stat_progress_checkpoint;
> -[ RECORD 1 ]-----+-------------------------------------
> pid               | 22043
> type              | checkpoint
> kind              | immediate force wait requested time
> start_lsn         | 0/14C60F8
> start_time        | 2022-03-03 18:59:56.018662+05:30
> phase             | performing two phase checkpoint
>
>
> This is the output I see when the checkpointer process has come out of
> the two phase checkpoint and is currently writing checkpoint xlog
> records and doing other stuff like updating control files etc. Is this
> okay?

The idea behind choosing the phases is based on the functionality
which takes longer time to execute. Since after two phase checkpoint
till post checkpoint cleanup won't take much time to execute, I have
not added any additional phase for that. But I also agree that this
gives wrong information to the user. How about mentioning the phase
information at the end of each phase like "Initializing",
"Initialization done", ..., "two phase checkpoint done", "post
checkpoint cleanup done", .., "finalizing". Except for the first phase
("initializing") and last phase ("finalizing"), all the other phases
describe the end of a certain operation. I feel this gives correct
information even though the phase name/description does not represent
the entire code block between two phases. For example if the current
phase is ''two phase checkpoint done". Then the user can infer that
the checkpointer has done till two phase checkpoint and it is doing
other stuff that are after that. Thoughts?

> The output of log_checkpoint shows the number of buffers written is 3
> whereas the output of pg_stat_progress_checkpoint shows it as 0. See
> below:
>
> 2022-03-03 20:04:45.643 IST [22043] LOG:  checkpoint complete: wrote 3
> buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
> write=24.652 s, sync=104.256 s, total=3889.625 s; sync files=2,
> longest=0.011 s, average=0.008 s; distance=0 kB, estimate=0 kB
>
> --
>
> [local]:5432 ashu@postgres=# select * from pg_stat_progress_checkpoint;
> -[ RECORD 1 ]-----+-------------------------------------
> pid               | 22043
> type              | checkpoint
> kind              | immediate force wait requested time
> start_lsn         | 0/14C60F8
> start_time        | 2022-03-03 18:59:56.018662+05:30
> phase             | finalizing
> buffers_total     | 0
> buffers_processed | 0
> buffers_written   | 0
>
> Any idea why this mismatch?

Good catch. In BufferSync() we have 'num_to_scan' (buffers_total)
which indicates the total number of buffers to be processed. Based on
that, the 'buffers_processed' and 'buffers_written' counter gets
incremented. I meant these values may reach upto 'buffers_total'. The
current pg_stat_progress_view support above information. There is
another place when 'ckpt_bufs_written' gets incremented (In
SlruInternalWritePage()). This increment is above the 'buffers_total'
value and it is included in the server log message (checkpoint end)
and not included in the view. I am a bit confused here. If we include
this increment in the view then we cannot calculate the exact
'buffers_total' beforehand. Can we increment the 'buffers_toal' also
when 'ckpt_bufs_written' gets incremented so that we can match the
behaviour with checkpoint end message?  Please share your thoughts.
---

> I think we can add a couple of more information to this view -
> start_time for buffer write operation and start_time for buffer sync
> operation. These are two very time consuming tasks in a checkpoint and
> people would find it useful to know how much time is being taken by
> the checkpoint in I/O operation phase. thoughts?

I felt the detailed progress is getting shown for these 2 phases of
the checkpoint like 'buffers_processed', 'buffers_written' and
'files_synced'. Hence I did not think about adding start time and If
it is really required, then I can add.

> Is it that hard or costly to do?  Just sending a message to increment
> the stat counter in RequestCheckpoint() would be enough.
>
> Also, unless I'm missing something it's still only showing the initial
> checkpoint flags, so it's *not* showing what the checkpoint is really
> doing, only what the checkpoint may be doing if nothing else happens.
> It just feels wrong.  You could even use that ckpt_flags info to know
> that at least one backend has requested a new checkpoint, if you don't
> want to have a number of backends.

I think using ckpt_flags to display whether any new requests have been
made or not is a good idea. I will include it in the next patch.

Thanks & Regards,
Nitin Jadhav
On Thu, Mar 3, 2022 at 11:58 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
>
> On Wed, Mar 2, 2022 at 7:15 PM Nitin Jadhav
> <nitinjadhavpostgres@gmail.com> wrote:
> >
> > > > > As mentioned upthread, there can be multiple backends that request a
> > > > > checkpoint, so unless we want to store an array of pid we should store a number
> > > > > of backend that are waiting for a new checkpoint.
> >
> > It's a good metric to show in the view but the information is not
> > readily available. Additional code is required to calculate the number
> > of requests. Is it worth doing that? I feel this can be added later if
> > required.
>
> Is it that hard or costly to do?  Just sending a message to increment
> the stat counter in RequestCheckpoint() would be enough.
>
> Also, unless I'm missing something it's still only showing the initial
> checkpoint flags, so it's *not* showing what the checkpoint is really
> doing, only what the checkpoint may be doing if nothing else happens.
> It just feels wrong.  You could even use that ckpt_flags info to know
> that at least one backend has requested a new checkpoint, if you don't
> want to have a number of backends.