Re: Track IO times in pg_stat_io

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