Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}

On Fri, Sep 15, 2023 at 12:34 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
> On Fri, Sep 15, 2023 at 9:24 AM Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:
> > I found that pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
>
> Yes, good catch. This is a bug. I will note that at least in 15 and
> likely before, pgBufferUsage.local_blks_written is incremented for
> local buffers but pgBufferUsage.blk_write_time is only added to for
> shared buffers (in FlushBuffer()). I think it makes sense to propose a
> bug fix to stable branches counting blk_write_time for local buffers
> as well.

My first thought was to wonder whether this was even a bug. I
remembered that EXPLAIN treats shared, local, and temp buffers as
three separate categories of things. But it seems that someone decided
to conflate two of them for I/O timing purposes:

                        if (has_timing)
                        {
                                appendStringInfoString(es->str, "
shared/local");

^^^^ Notice this bit in particular.

                                if (!INSTR_TIME_IS_ZERO(usage->blk_read_time))
                                        appendStringInfo(es->str, " read=%0.3f",

  INSTR_TIME_GET_MILLISEC(usage->blk_read_time));
                                if (!INSTR_TIME_IS_ZERO(usage->blk_write_time))
                                        appendStringInfo(es->str, "
write=%0.3f",

  INSTR_TIME_GET_MILLISEC(usage->blk_write_time));
                                if (has_temp_timing)
                                        appendStringInfoChar(es->str, ',');
                        }
                        if (has_temp_timing)
                        {
                                appendStringInfoString(es->str, " temp");
                                if
(!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time))
                                        appendStringInfo(es->str, " read=%0.3f",

  INSTR_TIME_GET_MILLISEC(usage->temp_blk_read_time));
                                if
(!INSTR_TIME_IS_ZERO(usage->temp_blk_write_time))
                                        appendStringInfo(es->str, "
write=%0.3f",

  INSTR_TIME_GET_MILLISEC(usage->temp_blk_write_time));
                        }

Given that, I'm inclined to agree that this is a bug. But we might
need to go through and make sure all of the code that deals with these
counters is on the same page about what the values represent. Maybe
there is code lurking somewhere that thinks these counters are only
supposed to include "shared" rather than, as the fragment above
suggests, "shared/local".

-- 
Robert Haas
EDB: http://www.enterprisedb.com