Re: pg_stat_wal_write statistics view

Hi,

On 2017-03-30 13:10:41 +1100, Haribabu Kommi wrote:
> diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
> index 5d58f09..a29c108 100644
> --- a/src/backend/access/transam/xlog.c
> +++ b/src/backend/access/transam/xlog.c
> @@ -600,6 +600,9 @@ typedef struct XLogCtlData
> */
> XLogwrtResult LogwrtResult;
>
> + /* Protected by WALWriteLock */
> + PgStat_WalWritesCounts stats;

> /*
> + * Check whether the current process is a normal backend or not.
> + * This function checks for the background processes that does
> + * some WAL write activity only and other background processes
> + * are not considered. It considers all the background workers
> + * as WAL write activity workers.
> + *
> + * Returns FALSE - when the current process is a normal backend
> + * TRUE - when the current process a background process/worker
> + */

I don't think we commonly capitalize true/false these days.

> +static bool
> +am_background_process()
> +{
> + /* check whether current process is a background process/worker? */
> + if (AmBackgroundWriterProcess() ||
> + AmWalWriterProcess() ||
> + AmCheckpointerProcess() ||
> + AmStartupProcess() ||
> + IsBackgroundWorker ||
> + am_walsender ||
> + am_autovacuum_worker)
> + {
> + return true;
> + }
> +
> + return false;
> +}

Uhm, wouldn't inverting this be a lot easier and future proof? There's
far fewer non-background processes.

> +/*
> * Write and/or fsync the log at least as far as WriteRqst indicates.
> *
> * If flexible == TRUE, we don't have to write as far as WriteRqst, but
> @@ -2341,6 +2377,9 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible)
> int npages;
> int startidx;
> uint32 startoffset;
> + instr_time io_start,
> + io_time;
> + bool is_background_process = am_background_process();
>
> /* We should always be inside a critical section here */
> Assert(CritSectionCount > 0);
> @@ -2458,6 +2497,11 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible)
> /* OK to write the page(s) */
> from = XLogCtl->pages + startidx * (Size) XLOG_BLCKSZ;
> nbytes = npages * (Size) XLOG_BLCKSZ;
> +
> + /* Start timer to acquire start time of the wal write */
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> +

I'm more than a bit hesitant adding overhead to WAL writing - it's
already quite a bit of a bottleneck. Normally track_io_timing just
makes things a tiny bit slower, but doesn't cause a scalability issue,
here it does. This is all done under an already highly contended lock.

> nleft = nbytes;
> do
> {
> @@ -2480,6 +2524,34 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible)
> from += written;
> } while (nleft > 0);
>
> + /* calculate the total time spent for wal writing */
> + if (track_io_timing)
> + {
> + INSTR_TIME_SET_CURRENT(io_time);
> + INSTR_TIME_SUBTRACT(io_time, io_start);
> +
> + if (is_background_process)
> + XLogCtl->stats.total_write_time += INSTR_TIME_GET_MILLISEC(io_time);
> + else
> + XLogCtl->stats.backend_total_write_time += INSTR_TIME_GET_MILLISEC(io_time);
> + }
> + else
> + {
> + XLogCtl->stats.total_write_time = 0;
> + XLogCtl->stats.backend_total_write_time = 0;
> + }
> +
> + /* check whether writer is a normal backend or not? */
> + if (is_background_process)
> + XLogCtl->stats.writes++;
> + else
> + XLogCtl->stats.backend_writes++;
> +
> + if (is_background_process)
> + XLogCtl->stats.write_blocks += npages;
> + else
> + XLogCtl->stats.backend_write_blocks += npages;
> +
> /* Update state for write */
> openLogOff += nbytes;
> npages = 0;
> @@ -2499,8 +2571,29 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible)
> */
> if (finishing_seg)
> {
> + /* Start timer to acquire start time of the wal sync */
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> +
> issue_xlog_fsync(openLogFile, openLogSegNo);
>
> + /* calculate the total time spent for wal sync */
> + if (track_io_timing)
> + {
> + INSTR_TIME_SET_CURRENT(io_time);
> + INSTR_TIME_SUBTRACT(io_time, io_start);
> +
> + if (is_background_process)
> + XLogCtl->stats.total_sync_time += INSTR_TIME_GET_MILLISEC(io_time);
> + else
> + XLogCtl->stats.backend_total_sync_time += INSTR_TIME_GET_MILLISEC(io_time);
> + }
> + else
> + {
> + XLogCtl->stats.total_sync_time = 0;
> + XLogCtl->stats.backend_total_sync_time = 0;
> + }
> +
> /* signal that we need to wakeup walsenders later */
> WalSndWakeupRequest();
>
> @@ -2568,7 +2661,28 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible)
> openLogOff = 0;
> }
>
> + /* Start timer to acquire start time of the wal sync */
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> +
> issue_xlog_fsync(openLogFile, openLogSegNo);
> +
> + /* calculate the total time spent for wal sync */
> + if (track_io_timing)
> + {
> + INSTR_TIME_SET_CURRENT(io_time);
> + INSTR_TIME_SUBTRACT(io_time, io_start);
> +
> + if (is_background_process)
> + XLogCtl->stats.total_sync_time += INSTR_TIME_GET_MILLISEC(io_time);
> + else
> + XLogCtl->stats.backend_total_sync_time += INSTR_TIME_GET_MILLISEC(io_time);
> + }
> + else
> + {
> + XLogCtl->stats.total_sync_time = 0;
> + XLogCtl->stats.backend_total_sync_time = 0;
> + }
> }

I'm *very* doubtful about this, but even if we do it, this needs careful
benchmarking.

> /* signal that we need to wakeup walsenders later */
> @@ -3043,6 +3157,9 @@ XLogBackgroundFlush(void)
> {
> XLogWrite(WriteRqst, flexible);
> }
> +
> + /* Collect all the wal write shared counters into local, and report it to stats collector */
> + memcpy(&LocalWalWritesStats.stats, &XLogCtl->stats, sizeof(PgStat_WalWritesCounts));
> LWLockRelease(WALWriteLock);

Hm. I think in a good number of workloads hti sis never reached, because
we return early.

I think this is an interesting feature, but I don't think it's ready,
and it was submitted very late in the v10 release cycle. Therefore I
think this should be moved to the next CF.

Greetings,

Andres Freund