Re: add checkpoint stats of snapshot and mapping files of pg_logical dir

On Mon, Mar 14, 2022 at 1:33 PM Michael Paquier <michael(at)paquier(dot)xyz> wrote:
>
> On Mon, Mar 14, 2022 at 10:54:56AM +0530, Bharath Rupireddy wrote:
> > Yes, this is a concern. Also, when there were no logical replication
> > slots on a plain server or the server removed or cleaned up all the
> > snapshot/mappings files, why would anyone want to have these messages
> > with all 0s in the server log?
>
> The default settings don't enable that, so making things conditional
> roughly as you are suggesting with two different LOG messages sounds
> rather fine.

Attaching v3 patch which emits logs only when necessary and doesn't
clutter the existing "checkpoint/restartpoint completed" message, see
some sample logs at [1]. Please review it further.

Just another thought - after looking at sample logs at [1], once can
think why can't the checkpoint logs be like [2] or [3]?

[1]
2022-03-14 11:20:28.381 UTC [3257102] LOG: checkpoint starting:
immediate force wait
2022-03-14 11:20:28.444 UTC [3257102] 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.064 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=0 kB, estimate=35717 kB
2022-03-14 11:20:28.444 UTC [3257102] LOG: snapbuild snapshot file(s)
removed=2, size=280 bytes, time=0.001 s, cutoff LSN=0/40D2F40
2022-03-14 11:20:28.444 UTC [3257102] LOG: logical rewrite mapping
file(s) removed=16, size=1368 bytes, synced=16, size=1368 bytes,
time=0.047 s, cutoff LSN=0/40D2F40

[2]
2022-03-14 11:20:28.381 UTC [3257102] LOG: checkpoint starting:
immediate force wait
2022-03-14 11:20:28.444 UTC [3257102] LOG: wrote 0 buffers (0.0%); 0
WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s,
total=0.064 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=35717 kB
2022-03-14 11:20:28.444 UTC [3257102] LOG: snapbuild snapshot file(s)
removed=2, size=280 bytes, time=0.001 s, cutoff LSN=0/40D2F40
2022-03-14 11:20:28.444 UTC [3257102] LOG: logical rewrite mapping
file(s) removed=16, size=1368 bytes, synced=16, size=1368 bytes,
time=0.047 s, cutoff LSN=0/40D2F40
2022-03-14 11:20:28.444 UTC [3257102] LOG: checkpoint complete:
immediate force wait

[3]
2022-03-14 11:20:28.381 UTC [3257102] LOG: checkpoint starting:
immediate force wait
2022-03-14 11:20:28.444 UTC [3257102] LOG: wrote 0 buffers (0.0%); 0
WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s,
total=0.064 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=35717 kB
2022-03-14 11:20:28.444 UTC [3257102] LOG: snapbuild snapshot file(s)
removed=2, size=280 bytes, time=0.001 s, cutoff LSN=0/40D2F40
2022-03-14 11:20:28.444 UTC [3257102] LOG: logical rewrite mapping
file(s) removed=16, size=1368 bytes, synced=16, size=1368 bytes,
time=0.047 s, cutoff LSN=0/40D2F40
2022-03-14 11:20:28.444 UTC [3257102] LOG: checkpoint complete

Regards,
Bharath Rupireddy.