Hi,
On 2023-03-06 11:30:13 -0500, Melanie Plageman wrote:
> > As pgstat_bktype_io_stats_valid() is called only in Assert(), I think that
> > would be a good idea
> > to also check that if counts are not Zero then times are not Zero.
>
> Yes, I think adding some validation around the relationship between
> counts and timing should help prevent developers from forgetting to call
> pg_stat_count_io_op() when calling pgstat_count_io_time() (as relevant).
>
> However, I think that we cannot check that if IO counts are non-zero
> that IO times are non-zero, because the user may not have
> track_io_timing enabled. We can check that if IO times are not zero, IO
> counts are not zero. I've done this in the attached v3.
And even if track_io_timing is enabled, the timer granularity might be so low
that we *still* get zeroes.
I wonder if we should get rid of pgStatBlockReadTime, pgStatBlockWriteTime,
> @@ -1000,11 +1000,27 @@ ReadBuffer_common(SMgrRelation smgr, char
> relpersistence, ForkNumber forkNum,
>
> if (isExtend)
> {
> + instr_time io_start,
> + io_time;
> +
> /* new buffers are zero-filled */
> MemSet((char *) bufBlock, 0, BLCKSZ);
> +
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> + else
> + INSTR_TIME_SET_ZERO(io_start);
> +
I wonder if there's an argument for tracking this in the existing IO stats as
well. But I guess we've lived with this for a long time...
> @@ -2981,16 +2998,16 @@ FlushBuffer(BufferDesc *buf, SMgrRelation reln,
> IOObject io_object,
> * When a strategy is not in use, the write can only be a "regular"
> write
> * of a dirty shared buffer (IOCONTEXT_NORMAL IOOP_WRITE).
> */
> - pgstat_count_io_op(IOOBJECT_RELATION, io_context, IOOP_WRITE);
> -
> if (track_io_timing)
> {
> INSTR_TIME_SET_CURRENT(io_time);
> INSTR_TIME_SUBTRACT(io_time, io_start);
>
> pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
> INSTR_TIME_ADD(pgBufferUsage.blk_write_time, io_time);
> + pgstat_count_io_time(IOOBJECT_RELATION, io_context, IOOP_WRITE,
> io_time);
> }
I think this needs a bit of cleanup - pgstat_count_buffer_write_time(),
pgBufferUsage.blk_write_time++, pgstat_count_io_time() is a bit excessive. We
might not be able to reduce the whole duplication at this point, but at least
it should be a bit more centralized.
> + pgstat_count_io_op(IOOBJECT_RELATION, io_context, IOOP_WRITE);
> pgBufferUsage.shared_blks_written++;
>
> /*
> @@ -3594,6 +3611,9 @@ FlushRelationBuffers(Relation rel)
>
> if (RelationUsesLocalBuffers(rel))
> {
> + instr_time io_start,
> + io_time;
> +
> for (i = 0; i < NLocBuffer; i++)
> {
> uint32 buf_state;
> @@ -3616,6 +3636,11 @@ FlushRelationBuffers(Relation rel)
>
> PageSetChecksumInplace(localpage,
> bufHdr->tag.blockNum);
>
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> + else
> + INSTR_TIME_SET_ZERO(io_start);
> +
> smgrwrite(RelationGetSmgr(rel),
>
> BufTagGetForkNum(&bufHdr->tag),
> bufHdr->tag.blockNum,
I don't think you need the INSTR_TIME_SET_ZERO() in the body of the loop, to
silence the compiler warnings you can do it one level up.
> @@ -228,6 +230,11 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum,
> BlockNumber blockNum,
>
> PageSetChecksumInplace(localpage, bufHdr->tag.blockNum);
>
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> + else
> + INSTR_TIME_SET_ZERO(io_start);
> +
> /* And write... */
> smgrwrite(oreln,
> BufTagGetForkNum(&bufHdr->tag),
> @@ -239,6 +246,13 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum,
> BlockNumber blockNum,
> buf_state &= ~BM_DIRTY;
> pg_atomic_unlocked_write_u32(&bufHdr->state, buf_state);
>
> + if (track_io_timing)
> + {
> + INSTR_TIME_SET_CURRENT(io_time);
> + INSTR_TIME_SUBTRACT(io_time, io_start);
> + pgstat_count_io_time(IOOBJECT_TEMP_RELATION,
> IOCONTEXT_NORMAL, IOOP_WRITE, io_time);
> + }
> +
> pgstat_count_io_op(IOOBJECT_TEMP_RELATION, IOCONTEXT_NORMAL,
> IOOP_WRITE);
> pgBufferUsage.local_blks_written++;
> }
Perhaps we can instead introduce a FlushLocalBuffer()? Then we don't need this
in multiple write paths.
> diff --git a/src/backend/storage/smgr/md.c b/src/backend/storage/smgr/md.c
> index 352958e1fe..052875d86a 100644
> --- a/src/backend/storage/smgr/md.c
> +++ b/src/backend/storage/smgr/md.c
> @@ -1030,6 +1030,30 @@ register_dirty_segment(SMgrRelation reln, ForkNumber
> forknum, MdfdVec *seg)
>
> if (!RegisterSyncRequest(&tag, SYNC_REQUEST, false /* retryOnError */ ))
> {
> + instr_time io_start,
> + io_time;
> +
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> + else
> + INSTR_TIME_SET_ZERO(io_start);
> +
> + ereport(DEBUG1,
> + (errmsg_internal("could not forward fsync
> request because request queue is full")));
> +
> + if (FileSync(seg->mdfd_vfd, WAIT_EVENT_DATA_FILE_SYNC) < 0)
> + ereport(data_sync_elevel(ERROR),
> + (errcode_for_file_access(),
> + errmsg("could not fsync file \"%s\":
> %m",
> +
> FilePathName(seg->mdfd_vfd))));
> +
> + if (track_io_timing)
> + {
> + INSTR_TIME_SET_CURRENT(io_time);
> + INSTR_TIME_SUBTRACT(io_time, io_start);
> + pgstat_count_io_time(IOOBJECT_RELATION,
> IOCONTEXT_NORMAL, IOOP_FSYNC, io_time);
> + }
> +
> /*
> * We have no way of knowing if the current IOContext is
> * IOCONTEXT_NORMAL or IOCONTEXT_[BULKREAD, BULKWRITE, VACUUM]
> at this
> @@ -1042,15 +1066,6 @@ register_dirty_segment(SMgrRelation reln, ForkNumber
> forknum, MdfdVec *seg)
> * backend fsyncs.
> */
> pgstat_count_io_op(IOOBJECT_RELATION, IOCONTEXT_NORMAL,
> IOOP_FSYNC);
> -
> - ereport(DEBUG1,
> - (errmsg_internal("could not forward fsync
> request because request queue is full")));
> -
> - if (FileSync(seg->mdfd_vfd, WAIT_EVENT_DATA_FILE_SYNC) < 0)
> - ereport(data_sync_elevel(ERROR),
> - (errcode_for_file_access(),
> - errmsg("could not fsync file \"%s\":
> %m",
> -
> FilePathName(seg->mdfd_vfd))));
> }
> }
>
> @@ -1399,6 +1414,8 @@ int
> mdsyncfiletag(const FileTag *ftag, char *path)
> {
> SMgrRelation reln = smgropen(ftag->rlocator, InvalidBackendId);
> + instr_time io_start,
> + io_time;
> File file;
> bool need_to_close;
> int result,
> @@ -1425,10 +1442,22 @@ mdsyncfiletag(const FileTag *ftag, char *path)
> need_to_close = true;
> }
>
> + if (track_io_timing)
> + INSTR_TIME_SET_CURRENT(io_start);
> + else
> + INSTR_TIME_SET_ZERO(io_start);
> +
> /* Sync the file. */
> result = FileSync(file, WAIT_EVENT_DATA_FILE_SYNC);
> save_errno = errno;
>
> + if (track_io_timing)
> + {
> + INSTR_TIME_SET_CURRENT(io_time);
> + INSTR_TIME_SUBTRACT(io_time, io_start);
> + pgstat_count_io_time(IOOBJECT_RELATION, IOCONTEXT_NORMAL,
> IOOP_FSYNC, io_time);
> + }
> +
> if (need_to_close)
> FileClose(file);
Perhaps we could have mdsyncfd(), used by both mdsyncfiletag() and
register_dirty_segment()?
> @@ -1359,20 +1378,31 @@ pg_stat_get_io(PG_FUNCTION_ARGS)
>
> for (int io_op = 0; io_op < IOOP_NUM_TYPES;
> io_op++)
> {
> - int col_idx =
> pgstat_get_io_op_index(io_op);
> + int i =
> pgstat_get_io_op_index(io_op);
>
> /*
> * Some combinations of BackendType and
> IOOp, of IOContext
> * and IOOp, and of IOObject and IOOp
> are not tracked. Set
> * these cells in the view NULL.
> */
> - nulls[col_idx] =
> !pgstat_tracks_io_op(bktype, io_obj, io_context, io_op);
> + if (pgstat_tracks_io_op(bktype, io_obj,
> io_context, io_op))
> + values[i] =
> Int64GetDatum(bktype_stats->counts[io_obj][io_context][io_op]);
> + else
> + nulls[i] = true;
> + }
These lines were already too long, and it's getting worse with this change.
> typedef struct PgStat_BktypeIO
> {
> - PgStat_Counter
> data[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES];
> + PgStat_Counter
> counts[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES];
> + instr_time
> times[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES];
> } PgStat_BktypeIO;
Ah, you're going to hate me. We can't store instr_time on disk. There's
another patch that gets substantial peformance gains by varying the frequency
at which instr_time keeps track of time based on the CPU frequency... It also
just doesn't have enough range to keep track of system wide time on a larger
system. A single backend won't run for 293 years, but with a few thousand
backends that's a whole different story.
I think we need to accumulate in instr_time, but convert to floating point
when flushing stats.
Greetings,
Andres Freund
