Re: should we enable log_checkpoints out of the box?

On Thu, Nov 4, 2021 at 1:11 PM Michael Paquier <michael(at)paquier(dot)xyz> wrote:
>
> On Tue, Nov 02, 2021 at 11:55:23AM -0400, 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 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.
>
> +1.

Thanks all for your inputs. Here's the v1 doing above. Please review it.

With log_checkpoints=on, the "./initdb -D data" generates few
checkpoints logs [1]. I hope this is okay as it's a one-time thing per
database cluster. Thoughts?

[1]
creating configuration files ... ok
running bootstrap script ... 2021-11-04 14:50:34.163 UTC [865574] LOG:
checkpoint starting: shutdown immediate
2021-11-04 14:50:34.166 UTC [865574] LOG: checkpoint complete: wrote
222 buffers (1.4%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.002 s, sync=0.001 s, total=0.003 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=698 kB, estimate=698 kB
ok
performing post-bootstrap initialization ... 2021-11-04 14:50:35.069
UTC [865576] LOG: checkpoint starting: immediate force wait flush-all
2021-11-04 14:50:35.069 UTC [865576] STATEMENT: CREATE DATABASE
template0 IS_TEMPLATE = true ALLOW_CONNECTIONS = false;

2021-11-04 14:50:35.076 UTC [865576] LOG: checkpoint complete: wrote
731 buffers (4.5%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.008 s, sync=0.001 s, total=0.008 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=3889 kB, estimate=3889 kB
2021-11-04 14:50:35.076 UTC [865576] STATEMENT: CREATE DATABASE
template0 IS_TEMPLATE = true ALLOW_CONNECTIONS = false;

2021-11-04 14:50:35.094 UTC [865576] LOG: checkpoint starting:
immediate force wait
2021-11-04 14:50:35.094 UTC [865576] STATEMENT: CREATE DATABASE
template0 IS_TEMPLATE = true ALLOW_CONNECTIONS = false;

2021-11-04 14:50:35.095 UTC [865576] LOG: checkpoint complete: wrote
0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=0 kB, estimate=3500 kB
2021-11-04 14:50:35.095 UTC [865576] STATEMENT: CREATE DATABASE
template0 IS_TEMPLATE = true ALLOW_CONNECTIONS = false;

2021-11-04 14:50:35.101 UTC [865576] LOG: checkpoint starting:
immediate force wait flush-all
2021-11-04 14:50:35.101 UTC [865576] STATEMENT: CREATE DATABASE postgres;

2021-11-04 14:50:35.102 UTC [865576] LOG: checkpoint complete: wrote
12 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=18 kB, estimate=3152 kB
2021-11-04 14:50:35.102 UTC [865576] STATEMENT: CREATE DATABASE postgres;

2021-11-04 14:50:35.120 UTC [865576] LOG: checkpoint starting:
immediate force wait
2021-11-04 14:50:35.120 UTC [865576] STATEMENT: CREATE DATABASE postgres;

2021-11-04 14:50:35.122 UTC [865576] LOG: checkpoint complete: wrote
0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=0 kB, estimate=2836 kB
2021-11-04 14:50:35.122 UTC [865576] STATEMENT: CREATE DATABASE postgres;

2021-11-04 14:50:35.123 UTC [865576] LOG: checkpoint starting:
shutdown immediate
2021-11-04 14:50:35.124 UTC [865576] LOG: checkpoint complete: wrote
4 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=0 kB, estimate=2553 kB
ok
syncing data to disk ... ok

initdb: warning: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.

Success. You can now start the database server using:

./pg_ctl -D data -l logfile start

Regards,
Bharath Rupireddy.