Hi,
On 2022-03-18 13:32:52 +0530, Bharath Rupireddy wrote:
> @@ -6115,46 +6116,81 @@ LogCheckpointEnd(bool restartpoint)
> CheckpointStats.ckpt_sync_rels;
> average_msecs = (long) ((average_sync_time + 999) / 1000);
>
> + initStringInfo(&logmsg);
> +
> if (restartpoint)
> - ereport(LOG,
> - (errmsg("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",
> -
> CheckpointStats.ckpt_bufs_written,
> - (double)
> CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
> - CheckpointStats.ckpt_segs_added,
> -
> CheckpointStats.ckpt_segs_removed,
> -
> CheckpointStats.ckpt_segs_recycled,
> - write_msecs / 1000, (int)
> (write_msecs % 1000),
> - sync_msecs / 1000, (int)
> (sync_msecs % 1000),
> - total_msecs / 1000, (int)
> (total_msecs % 1000),
> - CheckpointStats.ckpt_sync_rels,
> - longest_msecs / 1000, (int)
> (longest_msecs % 1000),
> - average_msecs / 1000, (int)
> (average_msecs % 1000),
> - (int) (PrevCheckPointDistance /
> 1024.0),
> - (int)
> (CheckPointDistanceEstimate / 1024.0))));
> + appendStringInfo(&logmsg,
> + _("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"),
> +
> CheckpointStats.ckpt_bufs_written,
> + (double)
> CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
> +
> CheckpointStats.ckpt_segs_added,
> +
> CheckpointStats.ckpt_segs_removed,
> +
> CheckpointStats.ckpt_segs_recycled,
> + write_msecs / 1000, (int)
> (write_msecs % 1000),
> + sync_msecs / 1000, (int)
> (sync_msecs % 1000),
> + total_msecs / 1000, (int)
> (total_msecs % 1000),
> +
> CheckpointStats.ckpt_sync_rels,
> + longest_msecs / 1000, (int)
> (longest_msecs % 1000),
> + average_msecs / 1000, (int)
> (average_msecs % 1000),
> + (int) (PrevCheckPointDistance
> / 1024.0),
> + (int)
> (CheckPointDistanceEstimate / 1024.0));
> else
> - ereport(LOG,
> - (errmsg("checkpoint 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",
> -
> CheckpointStats.ckpt_bufs_written,
> - (double)
> CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
> - CheckpointStats.ckpt_segs_added,
> -
> CheckpointStats.ckpt_segs_removed,
> -
> CheckpointStats.ckpt_segs_recycled,
> - write_msecs / 1000, (int)
> (write_msecs % 1000),
> - sync_msecs / 1000, (int)
> (sync_msecs % 1000),
> - total_msecs / 1000, (int)
> (total_msecs % 1000),
> - CheckpointStats.ckpt_sync_rels,
> - longest_msecs / 1000, (int)
> (longest_msecs % 1000),
> - average_msecs / 1000, (int)
> (average_msecs % 1000),
> - (int) (PrevCheckPointDistance /
> 1024.0),
> - (int)
> (CheckPointDistanceEstimate / 1024.0))));
> + appendStringInfo(&logmsg,
> + _("checkpoint 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"),
> +
> CheckpointStats.ckpt_bufs_written,
> + (double)
> CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
> +
> CheckpointStats.ckpt_segs_added,
> +
> CheckpointStats.ckpt_segs_removed,
> +
> CheckpointStats.ckpt_segs_recycled,
> + write_msecs / 1000, (int)
> (write_msecs % 1000),
> + sync_msecs / 1000, (int)
> (sync_msecs % 1000),
> + total_msecs / 1000, (int)
> (total_msecs % 1000),
> +
> CheckpointStats.ckpt_sync_rels,
> + longest_msecs / 1000, (int)
> (longest_msecs % 1000),
> + average_msecs / 1000, (int)
> (average_msecs % 1000),
> + (int) (PrevCheckPointDistance
> / 1024.0),
> + (int)
> (CheckPointDistanceEstimate / 1024.0));
before we further change this (as done in this patch) we should deduplicate
these huge statements in a separate patch / commit.
> + if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
> + {
> + long t_msecs;
> +
> + t_msecs =
> TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
> +
> CheckpointStats.repl_snap_end_t);
> +
> + appendStringInfo(&logmsg,
> + _("; logical decoding snapshot
> file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X"),
> +
> CheckpointStats.repl_snap_files_rmvd_cnt,
> + t_msecs / 1000, (int)
> (t_msecs % 1000),
> +
> LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn));
> + }
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.
> + 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.
Greetings,
Andres Freund
