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

On Tue, Mar 22, 2022 at 8:12 PM Andres Freund <andres(at)anarazel(dot)de> wrote:
> > Do you mean like this?
> > ereport(LOG,
> > /* translator: the placeholders show checkpoint options */
> > (errmsg("%s starting:%s%s%s%s%s%s%s%s",
> > restartpoint ? _("restartpoint") : _("checkpoint"),
> > (flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
> > (flags & CHECKPOINT_END_OF_RECOVERY) ? "
> > end-of-recovery" : "",
> > (flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
> > (flags & CHECKPOINT_FORCE) ? " force" : "",
> > (flags & CHECKPOINT_WAIT) ? " wait" : "",
> > (flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
> > (flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
> > (flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
>
> Yes.

Done that way, see
v7-0001-Deduplicate-checkpoint-restartpoint-starting-comp.patch.

> > I think the reason in this case might be that some flag names with hyphens
> > and spaces before words may not have the right/matching words in all
> > languages. What happens if we choose to translate/not translate the entire
> > message?
>
> If individual words aren't translated the "original" word would be used.

Interestingly, the translated message for "checkpoint/restart
complete" is empty. Maybe because it has untranslatable strings?

#: access/transam/xlog.c:8752
#, c-format
msgid "restartpoint complete: wrote %d buffers (%.1f%%); %d WAL
file(s) added, %d removed, %d recycled; write=%ld.%03d s,
sync=%ld.%03d s, total=%ld.%03d s; sync files=%d, longest=%ld.%03d s,
average=%ld.%03d s; distance=%d kB, estimate=%d kB"
msgstr ""

> > > Both seem still very long. I still am doubtful this level of detail is
> > > appropriate. Seems more like a thing for a tracepoint or such. How about just
> > > printing the time for the logical decoding operations in aggregate, without
> > > breaking down into files, adding LSNs etc?
> >
> > The distinction that the patch makes right now is for snapshot and
> > rewrite mapping files and it makes sense to have them separately.
>
> -1. The line also needs to be readable...

IMHO, that's subjective. Even now, the existing
"checkpoint/restartpoint complete" message has a good amount of info
which makes it unreadable for some.

The number of logical decoding files(snapshot and mapping) the
checkpoint processed is a good metric to have in server logs along
with the time it took for removing/syncing them. Thoughts?

[1]
2022-03-23 04:13:06.050 UTC [1322043] LOG: checkpoint complete: wrote
506 buffers (3.1%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.010 s, sync=0.193 s, total=0.287 s; sync files=8,
longest=0.189 s, average=0.025 s; distance=12866 kB, estimate=12866
kB; logical snapshot file(s) removed=3, time=0.001 s
2022-03-23 04:14:33.937 UTC [1322043] LOG: checkpoint complete: wrote
37 buffers (0.2%); 0 WAL file(s) added, 0 removed, 1 recycled;
write=0.004 s, sync=0.012 s, total=0.060 s; sync files=21,
longest=0.007 s, average=0.001 s; distance=1857 kB, estimate=11765 kB;
logical snapshot file(s) removed=3, time=0.001 s; logical rewrite
mapping file(s) removed=0, synced=28, time=0.001 s
2022-03-23 04:15:04.306 UTC [1322043] LOG: checkpoint complete: wrote
32 buffers (0.2%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.004 s, sync=0.008 s, total=0.078 s; sync files=11,
longest=0.006 s, average=0.001 s; distance=109 kB, estimate=10600 kB;
logical snapshot file(s) removed=4, time=0.001 s; logical rewrite
mapping file(s) removed=28, synced=28, time=0.001 s

Regards,
Bharath Rupireddy.