Thread: May be BUG. Periodic burst growth of the checkpoint_req counter on replica.

Hello!

Found a periodic spike growth of the checkpoint_req counter on replica by 20-30 units
after large insert (~350Mb) on master.
Reproduction on master and replica with default conf:
1) execute the command "insert into test values (generate_series(1,1E7));".
This leads to the table's growth by about 350Mb during about 15 secs (on my pc).
2)The wal records start coming to the replica, and when their number exceeds a certain limit, a request is emitted to
thecheckpointer process to create restartpoint on the replica and checkpoint_req is incremented. With default settings,
thislimit is 42 segments.
 
3) Restartpoint creation fails because a new restartpoint can only be created if the replica has received new WAL
recordsabout the checkpoint from the moment of the previous restartpoint. But there were no such records.
 
4) When the next WAL segment is received by replica, the next request is generated to create a restartpoint on the
replica,and so on.
 
5) Finally, a WAL record about the checkpoint arrives on the replica, restartpoint is created and the growth of
checkpoint_reqstops.
 
The described process can be observed in the log with additional debugging. See insert_1E7_once.log attached. This
log is for v13 but master has the same behavior.

Can we treat such behavior as a bug?
If so it seems possible to check if a creating of restartpoint is obviously impossible before sending request and don't
sendit at all if so.
 

The patch applied tries to fix it.

With best regards.
-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

At Tue, 6 Sep 2022 14:02:53 +0300, "Anton A. Melnikov" <aamelnikov@inbox.ru> wrote in 
> Can we treat such behavior as a bug?

Depends on how we see the counter value. I think this can be annoying
but not a bug. CreateRestartPoint already handles that case.

While standby is well catching up, startup may make requests once per
segment switch while primary is running the latest checkpoint since
standby won't receive a checkpoint record until the primary ends the
last checkpoint.

> If so it seems possible to check if a creating of restartpoint is
> obviously impossible before sending request and don't send it at all
> if so.
> 
> The patch applied tries to fix it.

It lets XLogPageRead run the same check with what CreateRestartPoint
does, so it basically works (it is forgetting a lock, though. The
reason for omitting the lock in CreateRestartPoint is that it knows
checkopinter is the only updator of the shared variable.). I'm not
sure I like that for the code duplication.


I'm not sure we need to fix that but if we do that, I would impletent
IsNewCheckPointWALRecs() using XLogCtl->RedoRecPtr and
XLogCtl->lastCheckPoint.redo instead since they are protected by the
same lock, and they work more correct way, that is, that can avoid
restartpoint requests while the last checkpoint is running.  And I
would rename it as RestartPointAvailable() or something like that.

Or I might want to add XLogRestartpointNeeded(readSegNo) to reduce the
required number of info_lck by reading XLogCtl members at once.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

Hello!

Thank you very much for your feedback and essential remarks.

On 07.09.2022 10:39, Kyotaro Horiguchi wrote:
> 
> It lets XLogPageRead run the same check with what CreateRestartPoint
> does, so it basically works (it is forgetting a lock, though. The
> reason for omitting the lock in CreateRestartPoint is that it knows
> checkopinter is the only updator of the shared variable.). I'm not
> sure I like that for the code duplication.
> 
> I'm not sure we need to fix that but if we do that, I would impletent
> IsNewCheckPointWALRecs() using XLogCtl->RedoRecPtr and
> XLogCtl->lastCheckPoint.redo instead since they are protected by the
> same lock, and they work more correct way, that is, that can avoid
> restartpoint requests while the last checkpoint is running.  And I
> would rename it as RestartPointAvailable() or something like that.

Corrected patch is attached (v2-0001-Fix-burst-checkpoint_req-growth.patch).
The access to Controlfile was removed so lwlock seems to be not needed.
Some logic duplication is still present and and i'm not quite sure if
it's possible to get rid of it. Would be glad to any suggestions.

> Or I might want to add XLogRestartpointNeeded(readSegNo) to reduce the
> required number of info_lck by reading XLogCtl members at once.

If we place this check into the XLogCheckpointNeeded() this will lead to a double
take of info_lck in XLogPageRead() when the restartpoint request is forming.
As it's done now taking of info_lck will be more rarely.
It seems i probably didn't understand your idea, please clarify it for me.

> Depends on how we see the counter value. I think this can be annoying
> but not a bug. CreateRestartPoint already handles that case. 

Yes! It is in fact annoying as docs says that checkpoint_req counts
"the number of requested checkpoints that have been performed".
But really checkpoints_req counts both the number of checkpoints requests
and restartpoint ones which may not be performed and resources are not spent.
The second frightening factor is the several times faster growth
of the checkpoints_timed counter on the replica vs primary due to scheduling
replays in 15 second if an attempt to create the restartpoint failed.

Here is a patch that leaves all logic as is, but adds a stats about
restartpoints. (v1-0001-Add-restartpoint-stats.patch)
.
For instance, for the same period on primary with this patch:
# SELECT CURRENT_TIME; select * from pg_stat_bgwriter \gx
     current_time
--------------------
  00:19:15.794561+03
(1 row)

-[ RECORD 1 ]---------+-----------------------------
checkpoints_timed     | 4
checkpoints_req       | 10
restartpoints_timed   | 0
restartpoints_req     | 0
restartpoints_done    | 0

On replica:
# SELECT CURRENT_TIME; select * from pg_stat_bgwriter \gx
     current_time
--------------------
  00:19:11.363009+03
(1 row)

-[ RECORD 1 ]---------+------------------------------
checkpoints_timed     | 0
checkpoints_req       | 0
restartpoints_timed   | 42
restartpoints_req     | 67
restartpoints_done    | 10

Only the counters checkpoints_timed, checkpoints_req and restartpoints_done give
the indication of resource-intensive operations.
Without this patch, the user would see on the replica something like this:

checkpoints_timed     | 42
checkpoints_req       | 109


With best regards,

-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

Hi,

On 2022-09-19 01:29:21 +0300, Anton A. Melnikov wrote:
> Corrected patch is attached (v2-0001-Fix-burst-checkpoint_req-growth.patch).

This patch doesn't pass the main regression tests tests successfully:

https://cirrus-ci.com/task/5502700019253248

diff -U3 /tmp/cirrus-ci-build/src/test/regress/expected/rules.out
/tmp/cirrus-ci-build/build/testrun/regress/regress/results/rules.out
--- /tmp/cirrus-ci-build/src/test/regress/expected/rules.out    2022-12-06 05:49:53.687424000 +0000
+++ /tmp/cirrus-ci-build/build/testrun/regress/regress/results/rules.out    2022-12-06 05:53:04.642690000 +0000
@@ -1816,6 +1816,9 @@
    FROM pg_stat_get_archiver() s(archived_count, last_archived_wal, last_archived_time, failed_count, last_failed_wal,
last_failed_time,stats_reset);
 
 pg_stat_bgwriter| SELECT pg_stat_get_bgwriter_timed_checkpoints() AS checkpoints_timed,
     pg_stat_get_bgwriter_requested_checkpoints() AS checkpoints_req,
+    pg_stat_get_bgwriter_timed_restartpoints() AS restartpoints_timed,
+    pg_stat_get_bgwriter_requested_restartpoints() AS restartpoints_req,
+    pg_stat_get_bgwriter_performed_restartpoints() AS restartpoints_done,
     pg_stat_get_checkpoint_write_time() AS checkpoint_write_time,
     pg_stat_get_checkpoint_sync_time() AS checkpoint_sync_time,
     pg_stat_get_bgwriter_buf_written_checkpoints() AS buffers_checkpoint,

Greetings,

Andres Freund

Hello!

On 06.12.2022 21:44, Andres Freund wrote:
> Hi,
> 
> On 2022-09-19 01:29:21 +0300, Anton A. Melnikov wrote:
>> Corrected patch is attached (v2-0001-Fix-burst-checkpoint_req-growth.patch).
> 
> This patch doesn't pass the main regression tests tests successfully:
> 
> https://cirrus-ci.com/task/5502700019253248
> 
> diff -U3 /tmp/cirrus-ci-build/src/test/regress/expected/rules.out
/tmp/cirrus-ci-build/build/testrun/regress/regress/results/rules.out
> --- /tmp/cirrus-ci-build/src/test/regress/expected/rules.out    2022-12-06 05:49:53.687424000 +0000
> +++ /tmp/cirrus-ci-build/build/testrun/regress/regress/results/rules.out    2022-12-06 05:53:04.642690000 +0000
> @@ -1816,6 +1816,9 @@
>      FROM pg_stat_get_archiver() s(archived_count, last_archived_wal, last_archived_time, failed_count,
last_failed_wal,last_failed_time, stats_reset);
 
>   pg_stat_bgwriter| SELECT pg_stat_get_bgwriter_timed_checkpoints() AS checkpoints_timed,
>       pg_stat_get_bgwriter_requested_checkpoints() AS checkpoints_req,
> +    pg_stat_get_bgwriter_timed_restartpoints() AS restartpoints_timed,
> +    pg_stat_get_bgwriter_requested_restartpoints() AS restartpoints_req,
> +    pg_stat_get_bgwriter_performed_restartpoints() AS restartpoints_done,
>       pg_stat_get_checkpoint_write_time() AS checkpoint_write_time,
>       pg_stat_get_checkpoint_sync_time() AS checkpoint_sync_time,
>       pg_stat_get_bgwriter_buf_written_checkpoints() AS buffers_checkpoint,
> 
> Greetings,
> 
> Andres Freund

Thank you for pointing!

I didn't think that the patch tester would apply both patch variants simultaneously,
assuming that these are two different possible solutions of the problem.
But it's even good, let it check both at once!

There was an error in the second variant (Add-restartpoint-stats), i forgot to correct the rules.out.
So fixed the second variant and rebased the first one (Fix-burst-checkpoint_req-growth)
to the current master.


With the best wishes,

-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

Hello!


On 15.03.2023 21:29, Gregory Stark (as CFM) wrote:

> These patches that are "Needs Review" and have received no comments at
> all since before March 1st are these. If your patch is amongst this
> list I would suggest any of:
> 
> 1) Move it yourself to the next CF (or withdraw it)
> 2) Post to the list with any pending questions asking for specific
> feedback -- it's much more likely to get feedback than just a generic
> "here's a patch plz review"...
> 3) Mark it Ready for Committer and possibly post explaining the
> resolution to any earlier questions to make it easier for a committer
> to understand the state
>

There are two different patch variants and some discussion expected.
So moved them to the next CF.

With the best wishes!

-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

Hi, Anton!

On Thu, Mar 16, 2023 at 2:39 PM Anton A. Melnikov <aamelnikov@inbox.ru> wrote:
> On 15.03.2023 21:29, Gregory Stark (as CFM) wrote:
>
> > These patches that are "Needs Review" and have received no comments at
> > all since before March 1st are these. If your patch is amongst this
> > list I would suggest any of:
> >
> > 1) Move it yourself to the next CF (or withdraw it)
> > 2) Post to the list with any pending questions asking for specific
> > feedback -- it's much more likely to get feedback than just a generic
> > "here's a patch plz review"...
> > 3) Mark it Ready for Committer and possibly post explaining the
> > resolution to any earlier questions to make it easier for a committer
> > to understand the state
> >
>
> There are two different patch variants and some discussion expected.
> So moved them to the next CF.

Thank you for your detailed observation regarding the spike growth of
the checkpoint_req counter on the replica following a large insert
operation on the master.  After reviewing your description and the
log, I agree with Kyotaro Horiguchi that the behavior you've outlined,
though potentially perceived as annoying, does not constitute a bug in
the PostgreSQL.

After examining the second patch
("v2-0001-Add-restartpoint-stats.patch"), it appears that adding
additional statistics as outlined in the patch is the most suitable
approach to address the concerns raised. This solution provides more
visibility into the system's behavior without altering its core
mechanics. However, it's essential that this additional functionality
is accompanied by comprehensive documentation to ensure clear
understanding and ease of use by the PostgreSQL community.

Please consider expanding the documentation to include detailed
explanations of the new statistics and their implications in various
scenarios.

------
Regards,
Alexander Korotkov

Thanks for remarks!

On 28.11.2023 21:34, Alexander Korotkov wrote:
> After examining the second patch
> ("v2-0001-Add-restartpoint-stats.patch"), it appears that adding
> additional statistics as outlined in the patch is the most suitable
> approach to address the concerns raised. This solution provides more
> visibility into the system's behavior without altering its core
> mechanics.

Agreed. I left only this variant of the patch and rework it due to commit 96f05261.
So the new counters is in the pg_stat_checkpointer view now.
Please see the v3-0001-add-restartpoints-stats.patch attached.


> However, it's essential that this additional functionality
> is accompanied by comprehensive documentation to ensure clear
> understanding and ease of use by the PostgreSQL community.
> 
> Please consider expanding the documentation to include detailed
> explanations of the new statistics and their implications in various
> scenarios.

In the separate v3-0002-doc-for-restartpoints-stats.patch i added the definitions
of the new counters into the "28.2.15. pg_stat_checkpointer" section
and explanation of them with examples into the "30.5.WAL Configuration" one.

Would be glad for any comments and and concerns.

With the best wishes,

-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

On Sat, Dec 23, 2023 at 12:04 AM Alexander Korotkov
<aekorotkov@gmail.com> wrote:
> On Mon, Dec 4, 2023 at 3:50 AM Anton A. Melnikov <a.melnikov@postgrespro.ru> wrote:
>>
>> Thanks for remarks!
>>
>> On 28.11.2023 21:34, Alexander Korotkov wrote:
>> > After examining the second patch
>> > ("v2-0001-Add-restartpoint-stats.patch"), it appears that adding
>> > additional statistics as outlined in the patch is the most suitable
>> > approach to address the concerns raised. This solution provides more
>> > visibility into the system's behavior without altering its core
>> > mechanics.
>>
>> Agreed. I left only this variant of the patch and rework it due to commit 96f05261.
>> So the new counters is in the pg_stat_checkpointer view now.
>> Please see the v3-0001-add-restartpoints-stats.patch attached.
>>
>>
>> > However, it's essential that this additional functionality
>> > is accompanied by comprehensive documentation to ensure clear
>> > understanding and ease of use by the PostgreSQL community.
>> >
>> > Please consider expanding the documentation to include detailed
>> > explanations of the new statistics and their implications in various
>> > scenarios.
>>
>> In the separate v3-0002-doc-for-restartpoints-stats.patch i added the definitions
>> of the new counters into the "28.2.15. pg_stat_checkpointer" section
>> and explanation of them with examples into the "30.5.WAL Configuration" one.
>>
>> Would be glad for any comments and and concerns.
>
>
> I made some grammar corrections to the docs and have written the commit message.
>
> I think this patch now looks good.  I'm going to push this if there are no objections.

Pushed!

------
Regards,
Alexander Korotkov

On 25.12.2023 02:38, Alexander Korotkov wrote:

> Pushed!

Thanks a lot!

With the best regards!

-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

On Fri, Dec 22, 2023 at 11:04 PM Alexander Korotkov
<aekorotkov@gmail.com> wrote:
>
> Hi, Anton!
>
> On Mon, Dec 4, 2023 at 3:50 AM Anton A. Melnikov <a.melnikov@postgrespro.ru> wrote:
>>
>> Thanks for remarks!
>>
>> On 28.11.2023 21:34, Alexander Korotkov wrote:
>> > After examining the second patch
>> > ("v2-0001-Add-restartpoint-stats.patch"), it appears that adding
>> > additional statistics as outlined in the patch is the most suitable
>> > approach to address the concerns raised. This solution provides more
>> > visibility into the system's behavior without altering its core
>> > mechanics.
>>
>> Agreed. I left only this variant of the patch and rework it due to commit 96f05261.
>> So the new counters is in the pg_stat_checkpointer view now.
>> Please see the v3-0001-add-restartpoints-stats.patch attached.
>>
>>
>> > However, it's essential that this additional functionality
>> > is accompanied by comprehensive documentation to ensure clear
>> > understanding and ease of use by the PostgreSQL community.
>> >
>> > Please consider expanding the documentation to include detailed
>> > explanations of the new statistics and their implications in various
>> > scenarios.
>>
>> In the separate v3-0002-doc-for-restartpoints-stats.patch i added the definitions
>> of the new counters into the "28.2.15. pg_stat_checkpointer" section
>> and explanation of them with examples into the "30.5.WAL Configuration" one.
>>
>> Would be glad for any comments and and concerns.
>
>
> I made some grammar corrections to the docs and have written the commit message.
>
> I think this patch now looks good.  I'm going to push this if there are no objections.

Per the docs, the sync_time, write_time and buffers_written only apply
to checkpoints, not restartpoints. Is this correct? AFAICT from a
quick look at the code they include both checkpoints and restartpoints
in which case I think the docs should be clarified to indicate that?
(Or if I'm wrong, and it doesn't include them, then shouldn't we have
separate counters for them?)

//Magnus

On Sat, Mar 9, 2024 at 4:38 PM Magnus Hagander <magnus@hagander.net> wrote:
> Per the docs, the sync_time, write_time and buffers_written only apply
> to checkpoints, not restartpoints. Is this correct? AFAICT from a
> quick look at the code they include both checkpoints and restartpoints
> in which case I think the docs should be clarified to indicate that?

Right, these fields work as before reflecting both checkpoints and
restartpoints.  Documentation said checkpoints implying restartpoints
as well.  Now that we distinguish stats for checkpoints and
restartpoints, we need to update the docs.  Please, check the patch
attached.

------
Regards,
Alexander Korotkov

On 11.03.2024 03:39, Alexander Korotkov wrote:
> Now that we distinguish stats for checkpoints and
> restartpoints, we need to update the docs.  Please, check the patch
> attached.

Maybe bring the pg_stat_get_checkpointer_buffers_written() description in consistent with these changes?
Like that:

--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5740 +5740 @@
-  descr => 'statistics: number of buffers written by the checkpointer',
+  descr => 'statistics: number of buffers written during checkpoints and restartpoints',

And after i took a fresh look at this patch i noticed a simple way to extract
write_time and sync_time counters for restartpoints too.

What do you think, is there a sense to do this?


With the best wishes,


-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

On Mon, Mar 11, 2024 at 5:43 AM Anton A. Melnikov
<a.melnikov@postgrespro.ru> wrote:
> On 11.03.2024 03:39, Alexander Korotkov wrote:
> > Now that we distinguish stats for checkpoints and
> > restartpoints, we need to update the docs.  Please, check the patch
> > attached.
>
> Maybe bring the pg_stat_get_checkpointer_buffers_written() description in consistent with these changes?
> Like that:
>
> --- a/src/include/catalog/pg_proc.dat
> +++ b/src/include/catalog/pg_proc.dat
> @@ -5740 +5740 @@
> -  descr => 'statistics: number of buffers written by the checkpointer',
> +  descr => 'statistics: number of buffers written during checkpoints and restartpoints',

This makes sense.  I've included this into the revised patch.

> And after i took a fresh look at this patch i noticed a simple way to extract
> write_time and sync_time counters for restartpoints too.
>
> What do you think, is there a sense to do this?

I'm not sure we need this.  The ways we trigger checkpoints and
restartpoints are different.  This is why we needed separate
statistics.  But the process of writing buffers is the same.

------
Regards,
Alexander Korotkov

On Mon, Mar 11, 2024 at 11:48 AM Alexander Korotkov
<aekorotkov@gmail.com> wrote:
>
> On Mon, Mar 11, 2024 at 5:43 AM Anton A. Melnikov
> <a.melnikov@postgrespro.ru> wrote:
> > On 11.03.2024 03:39, Alexander Korotkov wrote:
> > > Now that we distinguish stats for checkpoints and
> > > restartpoints, we need to update the docs.  Please, check the patch
> > > attached.
> >
> > Maybe bring the pg_stat_get_checkpointer_buffers_written() description in consistent with these changes?
> > Like that:
> >
> > --- a/src/include/catalog/pg_proc.dat
> > +++ b/src/include/catalog/pg_proc.dat
> > @@ -5740 +5740 @@
> > -  descr => 'statistics: number of buffers written by the checkpointer',
> > +  descr => 'statistics: number of buffers written during checkpoints and restartpoints',
>
> This makes sense.  I've included this into the revised patch.

Pushed.

------
Regards,
Alexander Korotkov

On 14.03.2024 03:19, Alexander Korotkov wrote:
> 
> Pushed.
> 

Thanks!


-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company