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

On Sat, Mar 19, 2022 at 4:39 AM Andres Freund <andres(at)anarazel(dot)de> wrote:
>
> before we further change this (as done in this patch) we should deduplicate
> these huge statements in a separate patch / commit.

Something like attached
v6-0001-Deduplicate-checkpoint-restartpoint-complete-mess.patch?

> As discussed in a bunch of other threads, we typically prefer to cast to long
> long and use %ll instead of using UINT64_FORMAT these days.

Changed.

> > + if (CheckpointStats.repl_map_files_rmvd_cnt ||
> > + CheckpointStats.repl_map_files_syncd_cnt > 0)
> > + {
> > + long t_msecs;
> > +
> > + t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
> > + CheckpointStats.repl_snap_end_t);
> > +
> > + appendStringInfo(&logmsg,
> > + _("; logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X"),
> > + CheckpointStats.repl_map_files_rmvd_cnt,
> > + CheckpointStats.repl_map_files_syncd_cnt,
> > + t_msecs / 1000, (int) (t_msecs % 1000),
> > + LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn));
> > + }
> > +
> > + ereport(LOG, errmsg_internal("%s", logmsg.data));
> > + pfree(logmsg.data);
> > }
>
> This practically doubles the size of the log message - doesn't that seem a bit
> disproportionate? Can we make this more dense? "logical decoding rewrite
> mapping file(s) removed=" and "logical decoding snapshot file(s) removed=" is
> quite long.

Do you suggest something like below? Or some other better wording like
"logical decoding rewrite map files" and "logical decoding snapshot
files" or "logical rewrite map files" and "logical snapshot files" or
just "rewrite mapping files" or "snapshot files" .... ?

if (repl_snap_files_rmvd_cnt > 0 && (repl_map_files_rmvd_cnt ||
repl_map_files_syncd_cnt > 0))
appendStringInfo(&logmsg,
_("; logical decoding snapshot file(s)
removed=%lu, time=%ld.%03d s, cutoff LSN=%X/%X", rewrite mapping
file(s), removed=%lu, synced=%lu, time=%ld.%03d s, cutoff LSN=%X/%X"
else if (repl_snap_files_rmvd_cnt > 0)
appendStringInfo(&logmsg,
_("; logical decoding snapshot file(s)
removed=%lu, time=%ld.%03d s, cutoff LSN=%X/%X",
else if (repl_map_files_rmvd_cnt || repl_map_files_syncd_cnt > 0
appendStringInfo(&logmsg,
_("; logical decoding rewrite mapping file(s),
removed=%lu, synced=%lu, time=%ld.%03d s, cutoff LSN=%X/%X"

On Sat, Mar 19, 2022 at 3:16 AM Nathan Bossart <nathandbossart(at)gmail(dot)com> wrote:
> /* buffer stats */
> appendStringInfo(&logmsg, "wrote %d buffers (%.1f%%); ",
> CheckpointStats.ckpt_bufs_written,
> (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers);
>
> /* WAL file stats */
> appendStringInfo(&logmsg, "%d WAL file(s) added, %d removed, %d recycled; ",
> CheckpointStats.ckpt_segs_added,
> CheckpointStats.ckpt_segs_removed,
> CheckpointStats.ckpt_segs_recycled);

Do we actually need to granularize the message like this? I actually
don't think so, because we print the stats even if they are 0 (buffers
written is 0 or WAL segments added is 0 and so on).

Regards,
Bharath Rupireddy.