Re: Report planning memory in EXPLAIN ANALYZE - Mailing list pgsql-hackers

Replying to both Alvaro and Abhijit in this email.

On Fri, Jan 12, 2024 at 10:22 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
>
> I think this patch is mostly OK and decided to use it to test something
> else.  In doing so I noticed one small thing that bothers me: if
> planning uses buffers, and those were requested to be reported, we get
> something like this at the end of the explain
>
>  Planning:
>    Buffers: shared hit=120 read=30
>  Planning Memory: used=67944 bytes allocated=73728 bytes
>  Planning Time: 0.892 ms
>
> This looks a bit unpleasant.  Wouldn't it be much nicer if the Planning
> thingies were all reported together in the Planning group?
>
>  Planning:
>    Buffers: shared hit=120 read=30
>    Memory: used=67944 bytes allocated=73728 bytes
>    Time: 0.892 ms
>
> This is easier said than done.  First, moving "Time" to be in the same
> group would break tools that are already parsing the current format.  So
> maybe we should leave that one alone.  So that means we end up with
> this:


We have not been careful when reporting buffer usage. Both Buffers and
I/O timings are related to buffers. Ideally we should have created a
separate section for buffers and reported the usage and timings stats
under it. If done that way, actually the output looks better.

Planning Buffers:
 usage: shared hit = ...
 i/o timings: shared read =...
Planning Memory:
Planning Time:

Further we may move the Buffers, Memory and Timing under "Planning"
section. So it looks like
Planning
   Buffers
      Usage
      I/O Timings
   Memory
   Time

We could bite the bullet and fix it in the next major release when
such compatibility breakage is expected if not welcome. If we go this
route, it will be good to commit this patch and then work on
refactoring.


>
>  Planning:
>    Buffers: shared hit=120 read=30
>    Memory: used=67944 bytes allocated=73728 bytes
>  Planning Time: 0.892 ms
>
> Better than the original, I think, even if not perfect.  Looking at the
> code, this is a bit of a mess to implement, because of the way
> show_buffer_usage is coded; currently it has an internal
> increment/decrement of indentation, so in order to report memory we
> would have to move the indentation change to outside show_buffer_usage
> (I think it does belong outside, but the determination of whether to
> print or not is quite messy, so we'd need a new function returning
> boolean).

If we could change show_buffer_usage() to print something like below
when no buffers are used or no time is spent in I/O, we won't need the
boolean and all the complexity in showing "Planning" and indenting.
Planning:
    Buffers: no buffers used
    I/O timings: none
    Memory: used ...

That would be a backward compatibility break, but impact would be
minor. Still that will bring I/O Timings at the same level as Memory
which is wrong.

Using a boolean return and moving es->indent-- outside of
show_buffer_usage would be less elegant.

>
> Alternatively we could move the memory reportage to within
> show_buffer_usage, but that seems worse.

Agreed.

On Fri, Jan 12, 2024 at 10:53 PM Abhijit Menon-Sen <ams@toroid.org> wrote:
>
> At 2024-01-12 17:52:27 +0100, alvherre@alvh.no-ip.org wrote:
> >
> > I think this patch is mostly OK
>
> (After the last few rounds of changes, it looks fine to me too.)
>
> >  Planning:
> >    Buffers: shared hit=120 read=30
> >    Memory: used=67944 bytes allocated=73728 bytes
> >  Planning Time: 0.892 ms
> >
> > […]
> >
> > Or we could leave it as you have it, but to me that's akin to giving up
> > on doing it nicely.
>
> For completeness, there's a third option, which is easier to write and a
> bit more friendly to the sort of thing that might already be parsing
> "Planning Time", viz.,
>
>     Planning Buffers: shared hit=120 read=30
>     Planning Memory: used=67944 bytes allocated=73728 bytes
>     Planning Time: 0.892 ms

And
Planning I/O Timings: shared ... .

To me it looks similar to Alvaro's first option.

>
> (Those "bytes" look slightly odd to me in the midst of all the x=y
> pieces, but that's probably not worth thinking about.)

How about separating those with ",". That would add a minor
inconsistency with how values in Buffers and I/O Timings sections are
reported.


--
Best Wishes,
Ashutosh Bapat