Hi, On Mon, 11 Sept 2023 at 14:28, Karina Litskevich <litskevichkar...@gmail.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. 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 hope these help. Regards, Nazir Bilal Yavuz Microsoft