Re: BufferUsage counters' values have changed

Hi,

On 2023-09-13 16:04:00 +0300, Nazir Bilal Yavuz wrote:
> On Mon, 11 Sept 2023 at 14:28, Karina Litskevich
> <litskevichkarina(at)gmail(dot)com> wrote:
> >
> > Hi hackers,
> >
> > I noticed that BufferUsage counters' values are strangely different for the
> > same queries on REL_15_STABLE and REL_16_STABLE. For example, I run
> >
> > CREATE EXTENSION pg_stat_statements;
> > CREATE TEMP TABLE test(b int);
> > INSERT INTO test(b) SELECT generate_series(1,1000);
> > SELECT query, local_blks_hit, local_blks_read, local_blks_written,
> > local_blks_dirtied, temp_blks_written FROM pg_stat_statements;
> >
> > and output on REL_15_STABLE contains
> >
> > query | INSERT INTO test(b) SELECT generate_series($1,$2)
> > local_blks_hit | 1005
> > local_blks_read | 2
> > local_blks_written | 5
> > local_blks_dirtied | 5
> > temp_blks_written | 0
> >
> > while output on REL_16_STABLE contains
> >
> > query | INSERT INTO test(b) SELECT generate_series($1,$2)
> > local_blks_hit | 1006
> > local_blks_read | 0
> > local_blks_written | 0
> > local_blks_dirtied | 5
> > temp_blks_written | 8
> >
> >
> > I found a bug that causes one of the differences. Wrong counter is incremented
> > in ExtendBufferedRelLocal(). The attached patch fixes it and should be applied
> > to REL_16_STABLE and master. With the patch applied output contains
>
> Nice finding! I agree, it should be changed.
>
> > query | INSERT INTO test(b) SELECT generate_series($1,$2)
> > local_blks_hit | 1006
> > local_blks_read | 0
> > local_blks_written | 8
> > local_blks_dirtied | 5
> > temp_blks_written | 0
> >
> >
> > I still wonder why local_blks_written is greater than it was on REL_15_STABLE,
> > and why local_blks_read became zero. These changes are caused by fcdda1e4b5.
> > This code is new to me, and I'm still trying to understand whether it's a bug
> > in computing the counters or just changes in how many blocks are read/written
> > during the query execution. If anyone can help me, I would be grateful.
>
> I spent some time on it:
>
> local_blks_read became zero because:
> 1_ One more cache hit. It was supposed to be local_blks_read but it is
> local_blks_hit now. This is an assumption, I didn't check this deeply.
> 2_ Before fcdda1e4b5, there was one local_blks_read coming from
> buf = ReadBufferExtended(rel, VISIBILITYMAP_FORKNUM, blkno,
> RBM_ZERO_ON_ERROR, NULL) in freespace.c -> ReadBuffer_common() ->
> pgBufferUsage.local_blks_read++.
> But buf = ReadBufferExtended(rel, VISIBILITYMAP_FORKNUM, blkno,
> RBM_ZERO_ON_ERROR, NULL) is moved into the else case, so it didn't
> called and local_blks_read isn't incremented.

That imo is a legitimate difference / improvement. The read we previously did
here was unnecessary.

> local_blks_written is greater because of the combination of fcdda1e4b5
> and 00d1e02be2.
> In PG_15:
> RelationGetBufferForTuple() -> ReadBufferBI(P_NEW, RBM_ZERO_AND_LOCK)
> -> ReadBufferExtended() -> ReadBuffer_common() ->
> pgBufferUsage.local_blks_written++; (called 5 times) [0]
> In PG_16:
> 1_ 5 of the local_blks_written is coming from:
> RelationGetBufferForTuple() -> RelationAddBlocks() ->
> ExtendBufferedRelBy() -> ExtendBufferedRelCommon() ->
> ExtendBufferedRelLocal() -> pgBufferUsage.local_blks_written +=
> extend_by; (extend_by is 1, this is called 5 times) [1]
> 2_ 3 of the local_blks_written is coming from:
> RelationGetBufferForTuple() -> RecordAndGetPageWithFreeSpace() ->
> fsm_set_and_search() -> fsm_readbuf() -> fsm_extend() ->
> ExtendBufferedRelTo() -> ExtendBufferedRelCommon() ->
> ExtendBufferedRelLocal() -> pgBufferUsage.local_blks_written +=
> extend_by; (extend_by is 3, this is called 1 time) [2]
>
> I think [0] is the same path as [1] but [2] is new. 'fsm extends'
> wasn't counted in local_blks_written in PG_15. Calling
> ExtendBufferedRelTo() from fsm_extend() caused 'fsm extends' to be
> counted in local_blks_written. I am not sure which one is correct.

I think it's correct to count the fsm writes here. The pg_stat_statement
columns aren't specific to the main relation for or such... If anything it was
a bug to not count them before.

Thanks for looking into this.

Greetings,

Andres Freund