should we enable log_checkpoints out of the box?

Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> writes:

How about we enable it out of the box?

No.

The general policy at the moment is that a normally-functioning server
should emit *no* log traffic by default (other than a few messages
at startup and shutdown). log_checkpoints is a particularly poor
candidate for an exception to that policy, because it would produce so
much traffic. No DBA would be likely to consider it as anything but
log spam.

It seems the checkpoint stats, that are emitted to server logs when
the GUC log_checkpoints is enabled, are so important that a postgres
database provider would ever want to disable the GUC.

This statement seems ridiculous on its face. If users need to wait
with bated breath for a checkpoint report, we have something else
we need to fix.

regards, tom lane

Hi,

On 2021-10-31 10:59:19 -0400, Tom Lane wrote:

The general policy at the moment is that a normally-functioning server
should emit *no* log traffic by default (other than a few messages
at startup and shutdown). log_checkpoints is a particularly poor
candidate for an exception to that policy, because it would produce so
much traffic.

It shouldn't cause that much traffic - if the database is idle /
read-only, we don't trigger checkpoints. And these days that appears to
be reliable.

No DBA would be likely to consider it as anything but log spam.

I don't agree at all. No postgres instance should be run without
log_checkpoints enabled. Performance is poor if checkpoints are
triggered by anything but time, and that can only be diagnosed if
log_checkpoints is on.

It seems the checkpoint stats, that are emitted to server logs when
the GUC log_checkpoints is enabled, are so important that a postgres
database provider would ever want to disable the GUC.

This statement seems ridiculous on its face.

It matches my experience. I think it's negligent to not turn it on on
anything but an absolutely toy database. And there it has practically no
cost.

The typical course is that suddenly the database has slowed down to a
crawl because checkpoints happen on an accelerated schedule due
max_wal_size. Without log_checkpoints one cannot diagnose this, and even
just turning on going forward isn't quite sufficient, because that
doesn't tell you whether checkpoints always were triggered by "xlog".

If users need to wait with bated breath for a checkpoint report, we
have something else we need to fix.

Well, we probably do. But it's not that easy to fundamentally improve
the situation.

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:

On 2021-10-31 10:59:19 -0400, Tom Lane wrote:

No DBA would be likely to consider it as anything but log spam.

I don't agree at all. No postgres instance should be run without
log_checkpoints enabled. Performance is poor if checkpoints are
triggered by anything but time, and that can only be diagnosed if
log_checkpoints is on.

This is complete nonsense. If we think that's a generic problem, we
should be fixing the problem (ie, making the checkpointer smarter);
not expecting that DBAs will monitor their logs for an undocumented
issue. The number of installations where that would actually happen
is epsilon compared to the number where it won't.

regards, tom lane

Hi,

On 2021-10-31 15:43:57 -0400, Tom Lane wrote:

Andres Freund <andres@anarazel.de> writes:

On 2021-10-31 10:59:19 -0400, Tom Lane wrote:

No DBA would be likely to consider it as anything but log spam.

I don't agree at all. No postgres instance should be run without
log_checkpoints enabled. Performance is poor if checkpoints are
triggered by anything but time, and that can only be diagnosed if
log_checkpoints is on.

This is complete nonsense.

Shrug. It's based on many years of doing or being around people doing
postgres support escalation shifts. And it's not like log_checkpoints
incurs meaningful overhead or causes that much log volume.

If we think that's a generic problem, we should be fixing the problem
(ie, making the checkpointer smarter);

We've made it less bad (checkpoint_segments -> max_wal_size, sorting IO
for checkpoints, forcing the OS to flush writes earlier). But it's still
a significant issue. It's not that easy to make it better.

The largest issues are the spikes in data write and WAL volumes. Of
course, tuning max_wal_size up helps, but that has its own set of issues
(we e.g. still PANIC on WAL ENOSPC).

One motivation for working on AIO/DIO is precisely to make checkpoints
less painful, FWIW. We are going to have to do something to reduce the
impact of FPWs at some point, but it's hard.

Greetings,

Andres Freund

On 10/31/21 16:16, Andres Freund wrote:

Hi,

On 2021-10-31 15:43:57 -0400, Tom Lane wrote:

Andres Freund <andres@anarazel.de> writes:

On 2021-10-31 10:59:19 -0400, Tom Lane wrote:

No DBA would be likely to consider it as anything but log spam.

I don't agree at all. No postgres instance should be run without
log_checkpoints enabled. Performance is poor if checkpoints are
triggered by anything but time, and that can only be diagnosed if
log_checkpoints is on.

This is complete nonsense.

Shrug. It's based on many years of doing or being around people doing
postgres support escalation shifts. And it's not like log_checkpoints
incurs meaningful overhead or causes that much log volume.

I agree with Andres 100%. Whenever called to diagnose any type of
problems this is on the usual checklist and very few customers have it
turned on. The usefulness of this information very much outweighs the
tiny amount of extra log created.

If we think that's a generic problem, we should be fixing the problem
(ie, making the checkpointer smarter);

We've made it less bad (checkpoint_segments -> max_wal_size, sorting IO
for checkpoints, forcing the OS to flush writes earlier). But it's still
a significant issue. It's not that easy to make it better.

And we kept the default for max_wal_size at 1GB. While it is a "soft"
limit, it is the main reason why instances are running full bore with a
huge percentage of full page writes because it is way too small for
their throughput and nothing in the logs warns them about it. I can run
a certain TPC-C workload on an 8-core machine quite comfortably when
max_wal_size is configured at 100G. The exact same TPC-C configuration
will spiral the machine down if left with default max_wal_size and there
is zero hint in the logs as to why.

--
Jan Wieck

On 10/31/21 21:16, Andres Freund wrote:

Hi,

On 2021-10-31 15:43:57 -0400, Tom Lane wrote:

Andres Freund <andres@anarazel.de> writes:

On 2021-10-31 10:59:19 -0400, Tom Lane wrote:

No DBA would be likely to consider it as anything but log spam.

I don't agree at all. No postgres instance should be run without
log_checkpoints enabled. Performance is poor if checkpoints are
triggered by anything but time, and that can only be diagnosed if
log_checkpoints is on.

This is complete nonsense.

Shrug. It's based on many years of doing or being around people doing
postgres support escalation shifts. And it's not like log_checkpoints
incurs meaningful overhead or causes that much log volume.

Yeah. In tuned instances the checkpoints happen fairly infrequently most
of the time (occasional batch loads being an exception, etc.), so the
extra log traffic should be fairly negligible. And it's not like we can
make checkpointer infinitely smart - sometimes the cause is a change in
the workload etc.

OTOH most of this data (# of timed/xlog checkpoints, buffers written by
checkpointer etc.) is available in the pg_stat_bgwriter view, and people
generally have monitoring these days.

I don't have a strong opinion on changing the default - we generally
recommend changing it, and we'll keep doing it, but it's usually part of
various other recommendations so this one tweak does not eliminate that.

regards

--
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Hi,

On Sun, Oct 31, 2021 at 01:16:33PM -0700, Andres Freund wrote:

On 2021-10-31 15:43:57 -0400, Tom Lane wrote:

Andres Freund <andres@anarazel.de> writes:

On 2021-10-31 10:59:19 -0400, Tom Lane wrote:

No DBA would be likely to consider it as anything but log spam.

I don't agree at all. No postgres instance should be run without
log_checkpoints enabled. Performance is poor if checkpoints are
triggered by anything but time, and that can only be diagnosed if
log_checkpoints is on.

This is complete nonsense.

Shrug. It's based on many years of doing or being around people doing
postgres support escalation shifts. And it's not like log_checkpoints
incurs meaningful overhead or causes that much log volume.

It could be a bit of reverse-survivorship-bias, i.e., you're only seeing
the pathological cases, while 99% of the Postgres installations out
there just hum along fine without anybody ever having to look at the
checkpoint entries in the log.

But yeah, for serious production instances, it makes sense to turn that
option on, but I'm not convinced it should be the default.

To put another option on the table: maybe a compromise could be to log
xlog checkpoints unconditionally, and the (checkpoint_timeout) time ones
only if log_checkpoints are set (maybe with some exponential backoff to
avoid log spam)?

Michael

--
Michael Banck
Team Lead PostgreSQL
Project Manager
Tel.: +49 2166 9901-171
Mail: michael.banck@credativ.de

credativ GmbH, HRB M�nchengladbach 12080
USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 M�nchengladbach
Management: Dr. Michael Meskes, Geoff Richardson, Peter Lilley

Our handling of personal data is subject to:
https://www.credativ.de/en/contact/privacy/

On Sun, Oct 31, 2021 at 9:05 PM Tomas Vondra <tomas.vondra@enterprisedb.com>
wrote:

On 10/31/21 21:16, Andres Freund wrote:

Hi,

On 2021-10-31 15:43:57 -0400, Tom Lane wrote:

Andres Freund <andres@anarazel.de> writes:

On 2021-10-31 10:59:19 -0400, Tom Lane wrote:

No DBA would be likely to consider it as anything but log spam.

I don't agree at all. No postgres instance should be run without
log_checkpoints enabled. Performance is poor if checkpoints are
triggered by anything but time, and that can only be diagnosed if
log_checkpoints is on.

This is complete nonsense.

Shrug. It's based on many years of doing or being around people doing
postgres support escalation shifts. And it's not like log_checkpoints
incurs meaningful overhead or causes that much log volume.

Yeah. In tuned instances the checkpoints happen fairly infrequently most
of the time (occasional batch loads being an exception, etc.), so the
extra log traffic should be fairly negligible. And it's not like we can
make checkpointer infinitely smart - sometimes the cause is a change in
the workload etc.

OTOH most of this data (# of timed/xlog checkpoints, buffers written by
checkpointer etc.) is available in the pg_stat_bgwriter view, and people
generally have monitoring these days.

Yeah, I think you can get much of the data you need in pg_stat_bgwriter.
There is still some data that log_checkpoint gives you that the statistics
don't -- but maybe we should instead look at exposing that information in
pg_stat_bgwriter, rather than changing the default.

--
Magnus Hagander
Me: https://www.hagander.net/ <http://www.hagander.net/&gt;
Work: https://www.redpill-linpro.com/ <http://www.redpill-linpro.com/&gt;

On 1 Nov 2021, at 14:02, Magnus Hagander <magnus@hagander.net> wrote:

There is still some data that log_checkpoint gives you that the statistics don't -- but maybe we should instead look at exposing that information in pg_stat_bgwriter, rather than changing the default.

I don't have strong opinions on changing the default, but +1 on at
investigating exposing the information in the view for monitoring.

--
Daniel Gustafsson https://vmware.com/

On Sun, Oct 31, 2021 at 10:59 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

The general policy at the moment is that a normally-functioning server
should emit *no* log traffic by default (other than a few messages
at startup and shutdown). log_checkpoints is a particularly poor
candidate for an exception to that policy, because it would produce so
much traffic. No DBA would be likely to consider it as anything but
log spam.

That's absolutely false. On any system where there's anything actually
happening, there's going to be tons of stuff in the log because there
are going to be failed connection attempts, queries that result in
errors, and all kinds of other things like that. By any reasonable
metric, the log volume of log_checkpoints=on is tiny. It can't log
anything more than once per checkpoint interval, which means you're
not even talking about 1 message per minute. You can easily have
hundreds or thousands of errors or other log messages from user
activity *per second* and even on a relatively quiet system that stuff
is going to completely dwarf what you get from log_checkpoints. If
log_checkpoints=on is your biggest source of log output, what you need
isn't so much 'log_checkpoints=off' as 'pg_ctl stop'.

It seems the checkpoint stats, that are emitted to server logs when
the GUC log_checkpoints is enabled, are so important that a postgres
database provider would ever want to disable the GUC.

This statement seems ridiculous on its face. If users need to wait
with bated breath for a checkpoint report, we have something else
we need to fix.

Besides appearing to be unwarranted mockery of what Bharath wrote,
this statement also seems to reflect a complete lack of understanding
of what is involved with maintaining a production system. Most of the
time, things just work, so you don't need to look at the logs at all.
But when things do go wrong, then you need some way to figure out what
the problem is. System-wide performance problems not linked to an
individual query are most often caused by either of two things:
checkpoints, and big autovacuum jobs. If you've set up logging for
those things in advance, then if and when the problem happens, you
will have a chance of being able to understand it and solve it
quickly. If you have not, the very first piece of advice you're going
to get from me is to (1) check whether there are any autovacuum
workers still running and if so figure out what they're doing and (2)
set log_checkpoints=on and log_autovacuum_min_duration to the smallest
value that isn't going to fill up your logs with too much garbage.

I can tell you from long experience with this sort of situation that
users do not love it. It means that they often cannot troubleshoot
problems of this type that happened in the past, because there's
simply no information in the log file that is of any use, and they
have to wait for the problem to recur... and I don't think it is
overstating anything to say that some of them probably DO wait with
bated breath, because they'd like whatever the issue is to get fixed!

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best things
we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues. The idea that users care more about
the inconvenience of a handful of extra log messages than they do
about being able to find problems when they have them matches no part
of my experience. I suspect that many users would be willing to incur
*way more* useless log messages than those settings would ever
generate if it meant that they could actually find problems when and
if they have them. And these messages would in fact be the most
valuable thing in the log for a lot of users. What reasonable DBA
cares more about the fact that the application attempted an insert
that violated a foreign key constraint than they do about a checkpoint
that took 20 minutes to fsync everything? The former is expected; if
you thought that foreign key violations would never occur, you
wouldn't need to incur the expense of having the system enforce them.
The latter is unexpected and basically undiscoverable with default
settings.

--
Robert Haas
EDB: http://www.enterprisedb.com

On Tue, Nov 2, 2021 at 8:55 AM Robert Haas <robertmhaas@gmail.com> wrote:

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best things
we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues. The idea that users care more about
the inconvenience of a handful of extra log messages than they do
about being able to find problems when they have them matches no part
of my experience. I suspect that many users would be willing to incur
*way more* useless log messages than those settings would ever
generate if it meant that they could actually find problems when and
if they have them.

I fully agree.

--
Peter Geoghegan

On 11/2/21 12:09, Peter Geoghegan wrote:

On Tue, Nov 2, 2021 at 8:55 AM Robert Haas <robertmhaas@gmail.com> wrote:

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best things
we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues. The idea that users care more about
the inconvenience of a handful of extra log messages than they do
about being able to find problems when they have them matches no part
of my experience. I suspect that many users would be willing to incur
*way more* useless log messages than those settings would ever
generate if it meant that they could actually find problems when and
if they have them.

I fully agree.

/metoo

cheers

andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

Le mer. 3 nov. 2021 à 00:18, Andrew Dunstan <andrew@dunslane.net> a écrit :

On 11/2/21 12:09, Peter Geoghegan wrote:

On Tue, Nov 2, 2021 at 8:55 AM Robert Haas <robertmhaas@gmail.com>

wrote:

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best things
we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues. The idea that users care more about
the inconvenience of a handful of extra log messages than they do
about being able to find problems when they have them matches no part
of my experience. I suspect that many users would be willing to incur
*way more* useless log messages than those settings would ever
generate if it meant that they could actually find problems when and
if they have them.

I fully agree.

/metoo

same here

On 11/2/21 12:35 PM, Julien Rouhaud wrote:

Le mer. 3 nov. 2021 à 00:18, Andrew Dunstan <andrew@dunslane.net
<mailto:andrew@dunslane.net>> a écrit :

On 11/2/21 12:09, Peter Geoghegan wrote:

On Tue, Nov 2, 2021 at 8:55 AM Robert Haas <robertmhaas@gmail.com

<mailto:robertmhaas@gmail.com>> wrote:

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best

things

we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues. The idea that users care more about
the inconvenience of a handful of extra log messages than they do
about being able to find problems when they have them matches no

part

of my experience. I suspect that many users would be willing to

incur

*way more* useless log messages than those settings would ever
generate if it meant that they could actually find problems when and
if they have them.

I fully agree.

/metoo

same here

+1

--
-David
david@pgmasters.net

On 11/2/21 12:09, Peter Geoghegan wrote:

On Tue, Nov 2, 2021 at 8:55 AM Robert Haas <robertmhaas@gmail.com> wrote:

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best things
we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues. The idea that users care more about
the inconvenience of a handful of extra log messages than they do
about being able to find problems when they have them matches no part
of my experience. I suspect that many users would be willing to incur
*way more* useless log messages than those settings would ever
generate if it meant that they could actually find problems when and
if they have them.

I fully agree.

+1

--
Jan Wieck

On Tue, Nov 2, 2021 at 8:55 AM Robert Haas <robertmhaas@gmail.com> wrote:

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best things
we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues.

Fully agree, it would be really great. Glad that you added autovacuum
logging
into the picture.

Maybe, 1m would be better – I recently observed a system with
high TPS, where autoANALYZE took very long for a system, causing
huge slowdown on standbys, starting after a few minutes of ANALYZE launched.
Correlation and then causation was confirmed only thanks to
log_autovacuum_min_duration configured -- without it, no one would be
able to understand what happened.

Back to checkpoint logging. With log_checkpoints = off, and high write
activity
with low max_wal_size we're already "spamming" the logs with lots of
"checkpoints are occurring too frequently" – and this happens very often,
any DBA running a restore process on Postgres with default max_wal_size
(1GB, very low for modern DBs) saw it.

Without details, this definitely looks like "spam" – and it's already
happening
here and there. Details provided by log_checkpoints = on will give
something
leading to making the decision on max_wal_size reconfiguration based on
data,
not guesswork.

+1 for log_checkpoints = on
and +1 for log_autovacuum_min_duration = 1m or so.

On 2021-Nov-02, Robert Haas wrote:

I think shipping with log_checkpoints=on and
log_autovacuum_min_duration=10m or so would be one of the best things
we could possibly do to allow ex-post-facto troubleshooting of
system-wide performance issues. The idea that users care more about
the inconvenience of a handful of extra log messages than they do
about being able to find problems when they have them matches no part
of my experience.

I agree.

There are things that are much more likely to be unhelpful and
irritating -- say, enabling log_connections by default. Such messages
would be decididly useless for a large fraction of users and a burden.
That's not something you can claim about checkpoints and large-autovac
messages, though; not only because they are much less frequent, but also
because each line concisely represents a large amount of work.

--
Álvaro Herrera 39°49'30"S 73°17'W — https://www.EnterpriseDB.com/
"En las profundidades de nuestro inconsciente hay una obsesiva necesidad
de un universo lógico y coherente. Pero el universo real se halla siempre
un paso más allá de la lógica" (Irulan)

On 2021-Nov-02, Nikolay Samokhvalov wrote:

Back to checkpoint logging. With log_checkpoints = off, and high write
activity with low max_wal_size we're already "spamming" the logs with
lots of "checkpoints are occurring too frequently" – and this happens
very often, any DBA running a restore process on Postgres with default
max_wal_size (1GB, very low for modern DBs) saw it.

Without details, this definitely looks like "spam"

Speaking of which -- I think we could easily remove checkpoint_warning
without any loss of useful functionality. Or, if we have to keep it, we
could change the way it works: when that condition triggers, then cause
regular "checkpoint started/complete" messages to occur (if they are
disabled), rather than the current "checkpoints are occurring too
frequently" message.

--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
"E pur si muove" (Galileo Galilei)

On Tue, Nov 2, 2021 at 2:39 PM Nikolay Samokhvalov
<samokhvalov@gmail.com> wrote:

+1 for log_checkpoints = on
and +1 for log_autovacuum_min_duration = 1m or so.

I almost proposed 1m rather than 10m, but then I thought the better of
it. I think it's unlikely that an autovacuum that takes 1 minute is
really the cause of some big problem you're having on your system.
Typical problem cases I see are hours or days long, so even 10 minutes
is pretty short. compared to what's likely to cause you real issues.
And at the same time 10 minutes is also high enough that you won't get
frequent log messages. 1 minute might not be: with 3 autovacuum
workers by default, that could print out a message every 20 seconds,
which does not feel worthwhile. I think a 10 minute threshold is much
more likely to only capture events that you actually care about.

Now I do think that a lot of people would benefit from a lower setting
than 10 minutes, just to get more information about what's happening.
But IMHO, making the default as low as 1 minute is a bit much.

--
Robert Haas
EDB: http://www.enterprisedb.com