MIME-Version: 1.0
References: <CALj2ACUGWAC56yqhVOisNPXhewfRdeHG4NGTOK_sOStL=7yP+w@mail.gmail.com>
 <CAMm1aWY_wThAxmhC_7mkFsYHcNP2_JQLAKJEoY5EcHBi0Q42QQ@mail.gmail.com>
 <CAEze2WhfmEWDKcFx8jhcSFhbSoP7ettdYiikNSsVWCNpe5ME0g@mail.gmail.com>
 <CAMm1aWYsfgO91mXxy7kzrDcML8nuY3Ab4w9RnSjZ_mr6=Y-hwQ@mail.gmail.com>
 <20220217110515.zssjnez4lq2lmrdq@jrouhaud> <CAMm1aWZ1YY6n8T=0OkwQJJdua7fpkJdKr1fRqfTSrJb1ME9Q5g@mail.gmail.com>
 <20220217172724.uhs2v3mgio7y6ga5@jrouhaud> <CAMm1aWbjzP9g9ebkYqqJvNAW4jh6wP0maKW2Ozcv8PLVu76cFA@mail.gmail.com>
 <20220218074351.wgfosjt5lql2vjbr@jrouhaud> <CAMm1aWadyUhb89DEfgrs2j5i2u--O06x6oTp0EEhgGHtnw-SXA@mail.gmail.com>
 <20220219053215.r4wqatln5awklecf@jrouhaud> <CAMm1aWZzPVpLs7k5sQU4DObvh6YpOhjibcq2ykDrC_n25jeJNA@mail.gmail.com>
 <CAEze2Wh3dmGhsnkvv9D3krU9m+o86SEXnBdRQB=krjFgX2ANRg@mail.gmail.com>
In-Reply-To: <CAEze2Wh3dmGhsnkvv9D3krU9m+o86SEXnBdRQB=krjFgX2ANRg@mail.gmail.com>
From: Nitin Jadhav <nitinjadhavpostgres@gmail.com>
Date: Wed, 23 Feb 2022 19:53:28 +0530
Message-ID: <CAMm1aWaKSPNdFGYjTxqh21b_EfYBpd+kpL7bnVHFJeOPPqoq4A@mail.gmail.com>
Subject: Re: Report checkpoint progress with pg_stat_progress_checkpoint (was:
 Report checkpoint progress in server logs)
To: Matthias van de Meent <boekewurm+postgres@gmail.com>
Cc: Julien Rouhaud <rjuju123@gmail.com>, 
	Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>, Bruce Momjian <bruce@momjian.us>, 
	Tom Lane <tgl@sss.pgh.pa.us>, Magnus Hagander <magnus@hagander.net>, 
	PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Content-Type: text/plain; charset="UTF-8"
Archived-At: <https://www.postgresql.org/message-id/CAMm1aWaKSPNdFGYjTxqh21b_EfYBpd%2BkpL7bnVHFJeOPPqoq4A%40mail.gmail.com>
Precedence: bulk

> At least for pg_stat_progress_checkpoint, storing only a timestamp in
> the pg_stat storage (instead of repeatedly updating the field as a
> duration) seems to provide much more precise measures of 'time
> elapsed' for other sessions if one step of the checkpoint is taking a
> long time.

I am storing the checkpoint start timestamp in the st_progress_param[]
and this gets set only once during the checkpoint (at the start of the
checkpoint). I have added function
pg_stat_get_progress_checkpoint_elapsed() which calculates the elapsed
time and returns a string. This function gets called whenever
pg_stat_progress_checkpoint view is queried. Kindly refer v2 patch and
share your thoughts.

> I understand the want to integrate the log-based reporting in the same
> API, but I don't think that is necessarily the right approach:
> pg_stat_progress_* has low-overhead infrastructure specifically to
> ensure that most tasks will not run much slower while reporting, never
> waiting for locks. Logging, however, needs to take locks (if only to
> prevent concurrent writes to the output file at a kernel level) and
> thus has a not insignificant overhead and thus is not very useful for
> precise and very frequent statistics updates.

I understand that the log based reporting is very costly and very
frequent updates are not advisable.  I am planning to use the existing
infrastructure of 'log_startup_progress_interval' which provides an
option for the user to configure the interval between each progress
update. Hence it avoids frequent updates to server logs. This approach
is used only during shutdown and end-of-recovery cases because we
cannot access pg_stat_progress_checkpoint view during those scenarios.

> So, although similar in nature, I don't think it is smart to use the
> exact same infrastructure between pgstat_progress*-based reporting and
> log-based progress reporting, especially if your logging-based
> progress reporting is not intended to be a debugging-only
> configuration option similar to log_min_messages=DEBUG[1..5].

Yes. I agree that we cannot use the same infrastructure for both.
Progress views and servers logs have different APIs to report the
progress information. But since both of this are required for the same
purpose, I am planning to use a common function which increases the
code readability than calling it separately in all the scenarios. I am
planning to include log based reporting in the next patch. Even after
that if using the same function is not recommended, I am happy to
change.

Thanks & Regards,
Nitin Jadhav

On Wed, Feb 23, 2022 at 12:13 AM Matthias van de Meent
<boekewurm+postgres@gmail.com> wrote:
>
> On Tue, 22 Feb 2022 at 07:39, Nitin Jadhav
> <nitinjadhavpostgres@gmail.com> wrote:
> >
> > > > Thank you for sharing the information.  'triggering backend PID' (int)
> > > > - can be stored without any problem. 'checkpoint or restartpoint?'
> > > > (boolean) - can be stored as a integer value like
> > > > PROGRESS_CHECKPOINT_TYPE_CHECKPOINT(0) and
> > > > PROGRESS_CHECKPOINT_TYPE_RESTARTPOINT(1). 'elapsed time' (store as
> > > > start time in stat_progress, timestamp fits in 64 bits) - As
> > > > Timestamptz is of type int64 internally, so we can store the timestamp
> > > > value in the progres parameter and then expose a function like
> > > > 'pg_stat_get_progress_checkpoint_elapsed' which takes int64 (not
> > > > Timestamptz) as argument and then returns string representing the
> > > > elapsed time.
> > >
> > > No need to use a string there; I think exposing the checkpoint start
> > > time is good enough. The conversion of int64 to timestamp[tz] can be
> > > done in SQL (although I'm not sure that exposing the internal bitwise
> > > representation of Interval should be exposed to that extent) [0].
> > > Users can then extract the duration interval using now() - start_time,
> > > which also allows the user to use their own preferred formatting.
> >
> > The reason for showing the elapsed time rather than exposing the
> > timestamp directly is in case of checkpoint during shutdown and
> > end-of-recovery, I am planning to log a message in server logs using
> > 'log_startup_progress_interval' infrastructure which displays elapsed
> > time. So just to match both of the behaviour I am displaying elapsed
> > time here. I feel that elapsed time gives a quicker feel of the
> > progress. Kindly let me know if you still feel just exposing the
> > timestamp is better than showing the elapsed time.
>
> At least for pg_stat_progress_checkpoint, storing only a timestamp in
> the pg_stat storage (instead of repeatedly updating the field as a
> duration) seems to provide much more precise measures of 'time
> elapsed' for other sessions if one step of the checkpoint is taking a
> long time.
>
> I understand the want to integrate the log-based reporting in the same
> API, but I don't think that is necessarily the right approach:
> pg_stat_progress_* has low-overhead infrastructure specifically to
> ensure that most tasks will not run much slower while reporting, never
> waiting for locks. Logging, however, needs to take locks (if only to
> prevent concurrent writes to the output file at a kernel level) and
> thus has a not insignificant overhead and thus is not very useful for
> precise and very frequent statistics updates.
>
> So, although similar in nature, I don't think it is smart to use the
> exact same infrastructure between pgstat_progress*-based reporting and
> log-based progress reporting, especially if your logging-based
> progress reporting is not intended to be a debugging-only
> configuration option similar to log_min_messages=DEBUG[1..5].
>
> - Matthias