Thread

Commits

Add EXPLAIN (MEMORY) to report planner memory consumption
- 5de890e3610d 17.0 landed
Fix explain regression test failure.
- eabba4a3eb71 14.0 cited

Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-08T06:10:45Z

Hi All,
I have been looking at memory consumed when planning a partitionwise join
[1], [2] and [3]. I am using the attached patch to measure the memory
consumption. The patch has been useful to detect an increased memory
consumption in other patches e.g. [4] and [5]. The patch looks useful by
itself. So I propose this enhancement in EXPLAIN ANALYZE.

Comments/suggestions welcome.

[1]
https://www.postgresql.org/message-id/CAExHW5tHqEf3ASVqvFFcghYGPfpy7o3xnvhHwBGbJFMRH8KjNw@mail.gmail.com
[2]
https://www.postgresql.org/message-id/CAExHW5tUcVsBkq9qT=L5vYz4e-cwQNw=KAGJrtSyzOp3F=XacA@mail.gmail.com
[3]
https://www.postgresql.org/message-id/CAExHW5s=bCLMMq8n_bN6iU+Pjau0DS3z_6Dn6iLE69ESmsPMJQ@mail.gmail.com
[4]
https://www.postgresql.org/message-id/CAExHW5uVZ3E5RT9cXHaxQ_DEK7tasaMN=D6rPHcao5gcXanY5w@mail.gmail.com
[5]
https://www.postgresql.org/message-id/CAExHW5s4EqY43oB=ne6B2=-xLgrs9ZGeTr1NXwkGFt2j-OmaQQ@mail.gmail.com

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-09T14:39:13Z

Hi David,
Replying to your comments on this thread.

> On Tue, Aug 8, 2023 at 11:40 AM Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> wrote:
>>
>> Hi All,
>> I have been looking at memory consumed when planning a partitionwise join [1], [2] and [3]. I am using the attached patch to measure the memory consumption. The patch has been useful to detect an increased memory consumption in other patches e.g. [4] and [5]. The patch looks useful by itself. So I propose this enhancement in EXPLAIN ANALYZE.
>>

On Wed, Aug 9, 2023 at 10:12 AM David Rowley <dgrowleyml@gmail.com> wrote:
>
> I see you're recording the difference in the CurrentMemoryContext of
> palloc'd memory before and after planning.  That won't really alert us
> to problems if the planner briefly allocates, say 12GBs of memory
> during, say the join search then quickly pfree's it again.  unless
> it's an oversized chunk, aset.c won't free() any memory until
> MemoryContextReset(). Chunks just go onto a freelist for reuse later.
> So at the end of planning, the context may still have that 12GBs
> malloc'd, yet your new EXPLAIN ANALYZE property might end up just
> reporting a tiny fraction of that.
>
> I wonder if it would be more useful to just have ExplainOneQuery()
> create a new memory context and switch to that and just report the
> context's mem_allocated at the end.

The memory allocated but not used is still available for use in rest
of the query processing stages. The memory context which is
CurrentMemoryContext at the time of planning is also
CurrentMemoryContext at the time of its execution if it's not
PREPAREd. So it's not exactly "consumed" by memory. But your point is
valid, that it indicates how much was allocated. Just reporting
allocated memory wont' be enough since it might have been allocated
before planning began. How about reporting both used and net allocated
memory? If we use a separate memory context as you suggest, context's
mem_allocated would be net allocated.

>
> It's also slightly annoying that these planner-related summary outputs
> are linked to EXPLAIN ANALYZE. We could be showing them in EXPLAIN
> without ANALYZE.  If we were to change that now, it might be a bit
> annoying for the regression tests as we'd need to go and add SUMMARY
> OFF in a load of places...

We do report planning time when SUMMARY ON without ANALYZE. Am I
missing something?

#select version();
                                                 version
----------------------------------------------------------------------------------------------------------
 PostgreSQL 16devel on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu
9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit
(1 row)
#explain (summary on) select * from pg_class;
                         QUERY PLAN
-------------------------------------------------------------
 Seq Scan on pg_class  (cost=0.00..18.13 rows=413 width=273)
 Planning Time: 0.282 ms
(2 rows)
#explain (summary off) select * from pg_class;
                         QUERY PLAN
-------------------------------------------------------------
 Seq Scan on pg_class  (cost=0.00..18.13 rows=413 width=273)
(1 row)

I need to just make sure that the Planning Memory is reported with SUMMARY ON.


-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-09T15:11:58Z

On Wed, Aug 9, 2023 at 8:09 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
>
> Hi David,
> Replying to your comments on this thread.
>
> > On Tue, Aug 8, 2023 at 11:40 AM Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> wrote:
> >>
> >> Hi All,
> >> I have been looking at memory consumed when planning a partitionwise join [1], [2] and [3]. I am using the attached patch to measure the memory consumption. The patch has been useful to detect an increased memory consumption in other patches e.g. [4] and [5]. The patch looks useful by itself. So I propose this enhancement in EXPLAIN ANALYZE.
> >>
>
> On Wed, Aug 9, 2023 at 10:12 AM David Rowley <dgrowleyml@gmail.com> wrote:
> >
> > I see you're recording the difference in the CurrentMemoryContext of
> > palloc'd memory before and after planning.  That won't really alert us
> > to problems if the planner briefly allocates, say 12GBs of memory
> > during, say the join search then quickly pfree's it again.  unless
> > it's an oversized chunk, aset.c won't free() any memory until
> > MemoryContextReset(). Chunks just go onto a freelist for reuse later.
> > So at the end of planning, the context may still have that 12GBs
> > malloc'd, yet your new EXPLAIN ANALYZE property might end up just
> > reporting a tiny fraction of that.
> >
> > I wonder if it would be more useful to just have ExplainOneQuery()
> > create a new memory context and switch to that and just report the
> > context's mem_allocated at the end.
>
> The memory allocated but not used is still available for use in rest
> of the query processing stages. The memory context which is
> CurrentMemoryContext at the time of planning is also
> CurrentMemoryContext at the time of its execution if it's not
> PREPAREd. So it's not exactly "consumed" by memory. But your point is
> valid, that it indicates how much was allocated. Just reporting
> allocated memory wont' be enough since it might have been allocated
> before planning began. How about reporting both used and net allocated
> memory? If we use a separate memory context as you suggest, context's
> mem_allocated would be net allocated.

Thinking more about it, I think memory used is the only right metrics.
It's an optimization in MemoryContext implementation that malloc'ed
memory is not freed when it is returned using pfree().

If we have to report allocated memory, maybe we should report as two
properties Planning Memory used, Planning Memory allocated
respectively. But again the later is an implementation detail which
may not be relevant.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

David Rowley <dgrowleyml@gmail.com> — 2023-08-09T15:26:40Z

On Thu, 10 Aug 2023 at 03:12, Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
> Thinking more about it, I think memory used is the only right metrics.
> It's an optimization in MemoryContext implementation that malloc'ed
> memory is not freed when it is returned using free().

I guess it depends on the problem you're trying to solve. I had
thought you were trying to do some work to reduce the memory used by
the planner, so I imagined you wanted this so you could track your
progress and also to help ensure we don't make too many mistakes in
the future which makes memory consumption worse again.  For that, I
imagined you'd want to know how much memory is held to ransom by the
context with malloc(), not palloc(). Is it really useful to reduce the
palloc'd memory by the end of planning if it does not reduce the
malloc'd memory?

Another way we might go about reducing planner memory is to make
changes to the allocators themselves.  For example, aset rounds up to
the next power of 2.  If we decided to do something like add more
freelists to double the number so we could add a mid-way point
freelist between each power of 2, then we might find it reduces the
planner memory by, say 12.5%.  If we just tracked what was consumed by
palloc() that would appear to save us nothing, but it might actually
save us several malloced blocks.

David

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-10T08:33:11Z

On Wed, Aug 9, 2023 at 8:56 PM David Rowley <dgrowleyml@gmail.com> wrote:
>
> On Thu, 10 Aug 2023 at 03:12, Ashutosh Bapat
> <ashutosh.bapat.oss@gmail.com> wrote:
> > Thinking more about it, I think memory used is the only right metrics.
> > It's an optimization in MemoryContext implementation that malloc'ed
> > memory is not freed when it is returned using free().
>
> I guess it depends on the problem you're trying to solve. I had
> thought you were trying to do some work to reduce the memory used by
> the planner, so I imagined you wanted this so you could track your
> progress and also to help ensure we don't make too many mistakes in
> the future which makes memory consumption worse again.

Right.

>  For that, I
> imagined you'd want to know how much memory is held to ransom by the
> context with malloc(), not palloc(). Is it really useful to reduce the
> palloc'd memory by the end of planning if it does not reduce the
> malloc'd memory?

AFAIU, the memory freed by the end of planning can be used by later
stages of query processing. The memory malloc'ed during planning can
also be used at the time of execution if it was not palloc'ed or
palloc'ed but pfree'd. So I think it's useful to reduce palloc'ed
memory by the end of planning.

>
> Another way we might go about reducing planner memory is to make
> changes to the allocators themselves.  For example, aset rounds up to
> the next power of 2.  If we decided to do something like add more
> freelists to double the number so we could add a mid-way point
> freelist between each power of 2, then we might find it reduces the
> planner memory by, say 12.5%.  If we just tracked what was consumed by
> palloc() that would appear to save us nothing, but it might actually
> save us several malloced blocks.
>

This won't just affect planner but every subsystem of PostgreSQL, not
just planner, unless we device a new context type for planner.

My point is what's relevant here is how much net memory planner asked
for. Internally how much memory PostgreSQL allocated seems relevant
for the memory context infra as such but not so much for planner
alone.

If you think that memory allocated is important, I will add both used
and (net) allocated memory to EXPLAIN output.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-10T08:34:31Z

Hi David,

On Wed, Aug 9, 2023 at 8:09 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
>
> I need to just make sure that the Planning Memory is reported with SUMMARY ON.
>
The patch reports planning memory in EXPLAIN without ANALYZE when SUMMARY = ON.

#explain (summary on) select * from a, b where a.c1 = b.c1 and a.c1 < b.c2;
                                  QUERY PLAN
-------------------------------------------------------------------------------
 Append  (cost=55.90..245.70 rows=1360 width=24)
   ->  Hash Join  (cost=55.90..119.45 rows=680 width=24)
         Hash Cond: (a_1.c1 = b_1.c1)
         Join Filter: (a_1.c1 < b_1.c2)
         ->  Seq Scan on a_p1 a_1  (cost=0.00..30.40 rows=2040 width=12)
         ->  Hash  (cost=30.40..30.40 rows=2040 width=12)
               ->  Seq Scan on b_p1 b_1  (cost=0.00..30.40 rows=2040 width=12)
   ->  Hash Join  (cost=55.90..119.45 rows=680 width=24)
         Hash Cond: (a_2.c1 = b_2.c1)
         Join Filter: (a_2.c1 < b_2.c2)
         ->  Seq Scan on a_p2 a_2  (cost=0.00..30.40 rows=2040 width=12)
         ->  Hash  (cost=30.40..30.40 rows=2040 width=12)
               ->  Seq Scan on b_p2 b_2  (cost=0.00..30.40 rows=2040 width=12)
 Planning Time: 2.220 ms
 Planning Memory: 124816 bytes
(15 rows)

We are good there.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Andrei Lepikhov <a.lepikhov@postgrespro.ru> — 2023-08-11T05:11:21Z

On 10/8/2023 15:33, Ashutosh Bapat wrote:
> On Wed, Aug 9, 2023 at 8:56 PM David Rowley <dgrowleyml@gmail.com> wrote:
>>
>> On Thu, 10 Aug 2023 at 03:12, Ashutosh Bapat
>> <ashutosh.bapat.oss@gmail.com> wrote:
>> I guess it depends on the problem you're trying to solve. I had
>> thought you were trying to do some work to reduce the memory used by
>> the planner, so I imagined you wanted this so you could track your
>> progress and also to help ensure we don't make too many mistakes in
>> the future which makes memory consumption worse again.
>> Another way we might go about reducing planner memory is to make
>> changes to the allocators themselves.  For example, aset rounds up to
>> the next power of 2.  If we decided to do something like add more
>> freelists to double the number so we could add a mid-way point
>> freelist between each power of 2, then we might find it reduces the
>> planner memory by, say 12.5%.  If we just tracked what was consumed by
>> palloc() that would appear to save us nothing, but it might actually
>> save us several malloced blocks.
>>
> 
> This won't just affect planner but every subsystem of PostgreSQL, not
> just planner, unless we device a new context type for planner.
> 
> My point is what's relevant here is how much net memory planner asked
> for. Internally how much memory PostgreSQL allocated seems relevant
> for the memory context infra as such but not so much for planner
> alone.
> 
> If you think that memory allocated is important, I will add both used
> and (net) allocated memory to EXPLAIN output.
As a developer, I like having as much internal info in my EXPLAIN as 
possible. But this command is designed mainly for users, not core 
developers. The size of memory allocated usually doesn't make sense for 
users. On the other hand, developers can watch it easily in different 
ways, if needed. So, I vote for the 'memory used' metric only.

The patch looks good, passes the tests.

-- 
regards,
Andrey Lepikhov
Postgres Professional

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-11T13:20:52Z

On Fri, Aug 11, 2023 at 10:41 AM Andrey Lepikhov
<a.lepikhov@postgrespro.ru> wrote:
> >>
> >
> > This won't just affect planner but every subsystem of PostgreSQL, not
> > just planner, unless we device a new context type for planner.
> >
> > My point is what's relevant here is how much net memory planner asked
> > for. Internally how much memory PostgreSQL allocated seems relevant
> > for the memory context infra as such but not so much for planner
> > alone.
> >
> > If you think that memory allocated is important, I will add both used
> > and (net) allocated memory to EXPLAIN output.
> As a developer, I like having as much internal info in my EXPLAIN as
> possible. But this command is designed mainly for users, not core
> developers. The size of memory allocated usually doesn't make sense for
> users. On the other hand, developers can watch it easily in different
> ways, if needed. So, I vote for the 'memory used' metric only.
>
> The patch looks good, passes the tests.

Thanks Andrey.

David, are you against reporting "memory used"? If you are not against
reporting used memory and still think that memory allocated is worth
reporting, I am fine reporting allocated memory too.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

David Rowley <dgrowleyml@gmail.com> — 2023-08-13T23:53:02Z

On Thu, 10 Aug 2023 at 20:33, Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
> My point is what's relevant here is how much net memory planner asked
> for.

But that's not what your patch is reporting. All you're reporting is
the difference in memory that's *currently* palloc'd from before and
after the planner ran.  If we palloc'd 600 exabytes then pfree'd it
again, your metric won't change.

I'm struggling a bit to understand your goals here.  If your goal is
to make a series of changes that reduces the amount of memory that's
palloc'd at the end of planning, then your patch seems to suit that
goal, but per the quote above, it seems you care about how many bytes
are palloc'd during planning and your patch does not seem track that.

With your patch as it is, to improve the metric you're reporting we
could go off and do things like pfree Paths once createplan.c is done,
but really, why would we do that? Just to make the "Planning Memory"
metric looks better doesn't seem like a worthy goal.

Instead, if we reported the context's mem_allocated, then it would
give us the flexibility to make changes to the memory context code to
have the metric look better. It might also alert us to planner
inefficiencies and problems with new code that may cause a large spike
in the amount of memory that gets allocated.  Now, I'm not saying we
should add a patch that shows mem_allocated. I'm just questioning if
your proposed patch meets the goals you're trying to achieve.  I just
suggested that you might want to consider something else as a metric
for your memory usage reduction work.

David

Re: Report planning memory in EXPLAIN ANALYZE

Andrei Lepikhov <a.lepikhov@postgrespro.ru> — 2023-08-14T02:52:47Z

On 14/8/2023 06:53, David Rowley wrote:
> On Thu, 10 Aug 2023 at 20:33, Ashutosh Bapat
> <ashutosh.bapat.oss@gmail.com> wrote:
>> My point is what's relevant here is how much net memory planner asked
>> for.
> 
> But that's not what your patch is reporting. All you're reporting is
> the difference in memory that's *currently* palloc'd from before and
> after the planner ran.  If we palloc'd 600 exabytes then pfree'd it
> again, your metric won't change.
> 
> I'm struggling a bit to understand your goals here.  If your goal is
> to make a series of changes that reduces the amount of memory that's
> palloc'd at the end of planning, then your patch seems to suit that
> goal, but per the quote above, it seems you care about how many bytes
> are palloc'd during planning and your patch does not seem track that.
> 
> With your patch as it is, to improve the metric you're reporting we
> could go off and do things like pfree Paths once createplan.c is done,
> but really, why would we do that? Just to make the "Planning Memory"
> metric looks better doesn't seem like a worthy goal.
> 
> Instead, if we reported the context's mem_allocated, then it would
> give us the flexibility to make changes to the memory context code to
> have the metric look better. It might also alert us to planner
> inefficiencies and problems with new code that may cause a large spike
> in the amount of memory that gets allocated.  Now, I'm not saying we
> should add a patch that shows mem_allocated. I'm just questioning if
> your proposed patch meets the goals you're trying to achieve.  I just
> suggested that you might want to consider something else as a metric
> for your memory usage reduction work.
Really, the current approach with the final value of consumed memory 
smooths peaks of memory consumption. I recall examples likewise massive 
million-sized arrays or reparameterization with many partitions where 
the optimizer consumes much additional memory during planning.
Ideally, to dive into the planner issues, we should have something like 
a report-in-progress in the vacuum, reporting on memory consumption at 
each subquery and join level. But it looks too much for typical queries.

-- 
regards,
Andrey Lepikhov
Postgres Professional

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-14T07:03:35Z

On Mon, Aug 14, 2023 at 5:23 AM David Rowley <dgrowleyml@gmail.com> wrote:
>
> On Thu, 10 Aug 2023 at 20:33, Ashutosh Bapat
> <ashutosh.bapat.oss@gmail.com> wrote:
> > My point is what's relevant here is how much net memory planner asked
> > for.
>
> But that's not what your patch is reporting. All you're reporting is
> the difference in memory that's *currently* palloc'd from before and
> after the planner ran.  If we palloc'd 600 exabytes then pfree'd it
> again, your metric won't change.

May be I didn't use the right phrase "asked for". But I expected that
to be read in the context of "net memory" - net as an adjective.
Anyway, I will make it more clear below.

>
> I'm struggling a bit to understand your goals here.  If your goal is
> to make a series of changes that reduces the amount of memory that's
> palloc'd at the end of planning, then your patch seems to suit that
> goal, but per the quote above, it seems you care about how many bytes
> are palloc'd during planning and your patch does not seem track that.

There are three metrics here. M1: The total number of bytes that the
planner "requests". M2: The total number of bytes that "remain
palloc'ed" at a given point in time. M3: Maximum number of bytes that
were palloc'ed at any point in time during planning. Following
sequence of operations will explain the difference
p1 palloc: 100 - M1 = 100, M2 = 100, M3 = 100
p2 palloc: 100, M1 = 200, M2 = 200, M3 = 200
p3 pfree: 100, M1 = 200, M2 = 100, M3 = 200
p4 palloc: 100, M1 = 300, M2 = 200, M3 = 200
p5 palloc: 100, M1 = 400, M2 = 300, M3 = 300
p6 pfree: 100, M1 = 400, M2 = 200, M3 = 300

The patch reports M2 at the end of planning.
MemoryContextData::mem_allocated is not exactly the same as M3 but
gives indication of M3.

My goal is to reduce all three M1, M2 and M3. I don't it's easy to
track M1 and also worth the complexity. M2 and M3 instead act as rough
indicators of M1.
>
> With your patch as it is, to improve the metric you're reporting we
> could go off and do things like pfree Paths once createplan.c is done,
> but really, why would we do that? Just to make the "Planning Memory"
> metric looks better doesn't seem like a worthy goal.
>

As I mentioned earlier the CurrentMemoryContext at the time of
planning is also used during query execution. There are other contexts
like per row, per operator contexts but anything which is specific to
the running query and does not fit those contexts is allocated in this
context. If we reduce memory that remains palloc'ed (M2) at the end of
the planning, it can be used during execution. So it looks like a
worthy goal.

> Instead, if we reported the context's mem_allocated, then it would
> give us the flexibility to make changes to the memory context code to
> have the metric look better. It might also alert us to planner
> inefficiencies and problems with new code that may cause a large spike
> in the amount of memory that gets allocated.

This is M3. I agree with your reasoning here. We should report M3 as
well. I will make changes to the patch.

> Now, I'm not saying we
> should add a patch that shows mem_allocated. I'm just questioning if
> your proposed patch meets the goals you're trying to achieve.  I just
> suggested that you might want to consider something else as a metric
> for your memory usage reduction work.

Ok. Thanks for the suggestions. More suggestions are welcome too.

[1] https://www.merriam-webster.com/dictionary/net

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-14T07:09:15Z

On Mon, Aug 14, 2023 at 8:22 AM Andrey Lepikhov
<a.lepikhov@postgrespro.ru> wrote:
>
> Really, the current approach with the final value of consumed memory
> smooths peaks of memory consumption. I recall examples likewise massive
> million-sized arrays or reparameterization with many partitions where
> the optimizer consumes much additional memory during planning.
> Ideally, to dive into the planner issues, we should have something like
> a report-in-progress in the vacuum, reporting on memory consumption at
> each subquery and join level. But it looks too much for typical queries.

Planner finishes usually finish within a second. When partitioning is
involved it might take a few dozens of seconds but it's still within a
minute and we are working to reduce that as well to a couple hundred
milliseconds at max. Tracking memory usages during this small time may
not be worth it. The tracking itself might make the planning
in-efficient and we might still miss the spikes in memory allocations,
if they are very short lived. If the planner runs for more than a few
minutes, maybe we could add some tracking.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

jian he <jian.universality@gmail.com> — 2023-08-22T07:46:44Z

On Mon, Aug 14, 2023 at 3:13 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
>
> On Mon, Aug 14, 2023 at 8:22 AM Andrey Lepikhov
> <a.lepikhov@postgrespro.ru> wrote:
> >
> > Really, the current approach with the final value of consumed memory
> > smooths peaks of memory consumption. I recall examples likewise massive
> > million-sized arrays or reparameterization with many partitions where
> > the optimizer consumes much additional memory during planning.
> > Ideally, to dive into the planner issues, we should have something like
> > a report-in-progress in the vacuum, reporting on memory consumption at
> > each subquery and join level. But it looks too much for typical queries.
>
> Planner finishes usually finish within a second. When partitioning is
> involved it might take a few dozens of seconds but it's still within a
> minute and we are working to reduce that as well to a couple hundred
> milliseconds at max. Tracking memory usages during this small time may
> not be worth it. The tracking itself might make the planning
> in-efficient and we might still miss the spikes in memory allocations,
> if they are very short lived. If the planner runs for more than a few
> minutes, maybe we could add some tracking.
>
> --
> Best Wishes,
> Ashutosh Bapat
>
>

Hi. I tested it.
not sure if following is desired behavior. first run with explain,
then run with explain(summary on).
the second time,  Planning Memory: 0 bytes.

regression=# PREPARE q4 AS SELECT 1 AS a;
explain EXECUTE q4;
                QUERY PLAN
------------------------------------------
 Result  (cost=0.00..0.01 rows=1 width=4)
(1 row)

regression=# explain(summary on) EXECUTE q4;
                QUERY PLAN
------------------------------------------
 Result  (cost=0.00..0.01 rows=1 width=4)
 Planning Time: 0.009 ms
 Planning Memory: 0 bytes
(3 rows)
---------------------------------------------
previously, if you want stats of a given memory context and its
children, you can only use MemoryContextStatsDetail.
but it will only go to stderr or LOG_SERVER_ONLY.
Now, MemoryContextMemUsed is being exposed. I can do something like:

mem_consumed = MemoryContextMemUsed(CurrentMemoryContext);
//do stuff.
mem_consumed = MemoryContextMemUsed(CurrentMemoryContext) - mem_consumed;

it will give me the NET memory consumed by doing staff in between. Is
my understanding correct?

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-08-24T10:31:17Z

Sorry for the late reply. I was working on David's suggestion.

Here's a response to your questions and also a new set of patches.

On Tue, Aug 22, 2023 at 1:16 PM jian he <jian.universality@gmail.com> wrote:
> Hi. I tested it.
> not sure if following is desired behavior. first run with explain,
> then run with explain(summary on).
> the second time,  Planning Memory: 0 bytes.
>
> regression=# PREPARE q4 AS SELECT 1 AS a;
> explain EXECUTE q4;
>                 QUERY PLAN
> ------------------------------------------
>  Result  (cost=0.00..0.01 rows=1 width=4)
> (1 row)
>
> regression=# explain(summary on) EXECUTE q4;
>                 QUERY PLAN
> ------------------------------------------
>  Result  (cost=0.00..0.01 rows=1 width=4)
>  Planning Time: 0.009 ms
>  Planning Memory: 0 bytes
> (3 rows)
> ---------------------------------------------

Yes. This is expected since the plan is already available and no
memory is required to fetch it from the cache. I imagine, if there
were parameters to the prepared plan, it would consume some memory to
evaluate those parameters and some more memory if replanning was
required.

> previously, if you want stats of a given memory context and its
> children, you can only use MemoryContextStatsDetail.
> but it will only go to stderr or LOG_SERVER_ONLY.
> Now, MemoryContextMemUsed is being exposed. I can do something like:
>
> mem_consumed = MemoryContextMemUsed(CurrentMemoryContext);
> //do stuff.
> mem_consumed = MemoryContextMemUsed(CurrentMemoryContext) - mem_consumed;
>
> it will give me the NET memory consumed by doing staff in between. Is
> my understanding correct?

Yes.

Here are three patches based on the latest master.

0001
====
this is same as the previous patch with few things fixed. 1. Call
MemoryContextMemUsed() before INSTR_TIME_SET_CURRENT so that the time
taken by MemoryContextMemUsed() is not counted in planning time. 2. In
ExplainOnePlan, use a separate code block for reporting memory.

0002
====
This patch reports both memory allocated and memory used in the
CurrentMemoryContext at the time of planning. It converts "Planning
Memory" into a section with two values reported as "used" and
"allocated" as below

#explain (summary on) select * from pg_class c, pg_type t where
c.reltype = t.oid;
                                QUERY PLAN
--------------------------------------------------------------------------
 Hash Join  (cost=28.84..47.08 rows=414 width=533)
   ... snip ...
 Planning Time: 9.274 ms
 Planning Memory: used=80848 bytes allocated=90112 bytes
(7 rows)

In JSON format
#explain (summary on, format json) select * from pg_class c, pg_type t
where c.reltype = t.oid;
                  QUERY PLAN
-----------------------------------------------
 [                                            +
   {                                          +
     "Plan": {                                +
      ... snip ...
     },                                       +
     "Planning Time": 0.466,                  +
     "Planning Memory": {                     +
       "Used": 80608,                         +
       "Allocated": 90112                     +
     }                                        +
   }                                          +
 ]
(1 row)

PFA explain and explain analyze output in all the formats.

The patch adds MemoryContextMemConsumed() which is similar to
MemoryContextStats() or MemoryContextStatsDetails() except 1. the
later always prints the memory statistics to either stderr or to the
server error log and 2. it doesn't return MemoryContextCounters that
it gathered. We should probably change MemoryContextStats or
MemoryContextStatsDetails() according to those two points and not add
MemoryContextMemConsumed().

I have not merged this into 0001 yet. But once we agree upon whether
this is the right thing to do, I will merge it into 0001.

0003
====
When reporting memory allocated, a confusion may arise as to whether
to report the "net" memory allocated between start and end of planner
OR only the memory that remains allocated after end. This confusion
can be avoided by using an exclusive memory context (child of
CurrentMemoryContext) for planning. That's what 0003 implements as
suggested by David. As mentioned in one of the comments in the patch,
in order to measure memory allocated accurately the new MemoryContext
has to be of the same type as the memory context that will be used
otherwise by the planner i.e. CurrentMemoryContext, and should use the
same parameters. IIUC, it will always be AllocSet. So the patch uses
AllocSet and Asserts so. But in case this changes in future, we will
need a way to create a new memory context with the same properties as
the CurrentMemoryContext, a functionality missing right now. Once we
agree upon the approach, the patch will need to be merged into 0002
and in turn 0001.

--
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Andrei Lepikhov <a.lepikhov@postgrespro.ru> — 2023-09-05T03:18:13Z

Using your patch I found out one redundant memory usage in the planner [1]. It can be interesting as an example of how this patch can detect problems.

[1] Optimize planner memory consumption for huge arrays
https://www.postgresql.org/message-id/flat/em9939439a-441a-4b27-a977-ebdf5987dc49%407d14f008.com

-- 
Regards,
Andrei Lepikhov

On Thu, Aug 24, 2023, at 5:31 PM, Ashutosh Bapat wrote:
> Sorry for the late reply. I was working on David's suggestion.
>
> Here's a response to your questions and also a new set of patches.
>
> On Tue, Aug 22, 2023 at 1:16 PM jian he <jian.universality@gmail.com> wrote:
>> Hi. I tested it.
>> not sure if following is desired behavior. first run with explain,
>> then run with explain(summary on).
>> the second time,  Planning Memory: 0 bytes.
>>
>> regression=# PREPARE q4 AS SELECT 1 AS a;
>> explain EXECUTE q4;
>>                 QUERY PLAN
>> ------------------------------------------
>>  Result  (cost=0.00..0.01 rows=1 width=4)
>> (1 row)
>>
>> regression=# explain(summary on) EXECUTE q4;
>>                 QUERY PLAN
>> ------------------------------------------
>>  Result  (cost=0.00..0.01 rows=1 width=4)
>>  Planning Time: 0.009 ms
>>  Planning Memory: 0 bytes
>> (3 rows)
>> ---------------------------------------------
>
> Yes. This is expected since the plan is already available and no
> memory is required to fetch it from the cache. I imagine, if there
> were parameters to the prepared plan, it would consume some memory to
> evaluate those parameters and some more memory if replanning was
> required.
>
>
>> previously, if you want stats of a given memory context and its
>> children, you can only use MemoryContextStatsDetail.
>> but it will only go to stderr or LOG_SERVER_ONLY.
>> Now, MemoryContextMemUsed is being exposed. I can do something like:
>>
>> mem_consumed = MemoryContextMemUsed(CurrentMemoryContext);
>> //do stuff.
>> mem_consumed = MemoryContextMemUsed(CurrentMemoryContext) - mem_consumed;
>>
>> it will give me the NET memory consumed by doing staff in between. Is
>> my understanding correct?
>
> Yes.
>
> Here are three patches based on the latest master.
>
> 0001
> ====
> this is same as the previous patch with few things fixed. 1. Call
> MemoryContextMemUsed() before INSTR_TIME_SET_CURRENT so that the time
> taken by MemoryContextMemUsed() is not counted in planning time. 2. In
> ExplainOnePlan, use a separate code block for reporting memory.
>
> 0002
> ====
> This patch reports both memory allocated and memory used in the
> CurrentMemoryContext at the time of planning. It converts "Planning
> Memory" into a section with two values reported as "used" and
> "allocated" as below
>
> #explain (summary on) select * from pg_class c, pg_type t where
> c.reltype = t.oid;
>                                 QUERY PLAN
> --------------------------------------------------------------------------
>  Hash Join  (cost=28.84..47.08 rows=414 width=533)
>    ... snip ...
>  Planning Time: 9.274 ms
>  Planning Memory: used=80848 bytes allocated=90112 bytes
> (7 rows)
>
> In JSON format
> #explain (summary on, format json) select * from pg_class c, pg_type t
> where c.reltype = t.oid;
>                   QUERY PLAN
> -----------------------------------------------
>  [                                            +
>    {                                          +
>      "Plan": {                                +
>       ... snip ...
>      },                                       +
>      "Planning Time": 0.466,                  +
>      "Planning Memory": {                     +
>        "Used": 80608,                         +
>        "Allocated": 90112                     +
>      }                                        +
>    }                                          +
>  ]
> (1 row)
>
> PFA explain and explain analyze output in all the formats.
>
> The patch adds MemoryContextMemConsumed() which is similar to
> MemoryContextStats() or MemoryContextStatsDetails() except 1. the
> later always prints the memory statistics to either stderr or to the
> server error log and 2. it doesn't return MemoryContextCounters that
> it gathered. We should probably change MemoryContextStats or
> MemoryContextStatsDetails() according to those two points and not add
> MemoryContextMemConsumed().
>
> I have not merged this into 0001 yet. But once we agree upon whether
> this is the right thing to do, I will merge it into 0001.
>
> 0003
> ====
> When reporting memory allocated, a confusion may arise as to whether
> to report the "net" memory allocated between start and end of planner
> OR only the memory that remains allocated after end. This confusion
> can be avoided by using an exclusive memory context (child of
> CurrentMemoryContext) for planning. That's what 0003 implements as
> suggested by David. As mentioned in one of the comments in the patch,
> in order to measure memory allocated accurately the new MemoryContext
> has to be of the same type as the memory context that will be used
> otherwise by the planner i.e. CurrentMemoryContext, and should use the
> same parameters. IIUC, it will always be AllocSet. So the patch uses
> AllocSet and Asserts so. But in case this changes in future, we will
> need a way to create a new memory context with the same properties as
> the CurrentMemoryContext, a functionality missing right now. Once we
> agree upon the approach, the patch will need to be merged into 0002
> and in turn 0001.

Re: Report planning memory in EXPLAIN ANALYZE

Andy Fan <zhihui.fan1213@gmail.com> — 2023-09-22T02:52:12Z

Hi Ashutosh,

Thanks for the patch!

I think the reason why others are not excited about this is because the
benefit is not clear enough to them after the first glance and plus the
chosen wolds "Planning Memory: used " is still confusing for different
people. I admit it is clear to you absolutely, just not for others.  Here
are some minor feedback from me:

1). The commit message of patch 1 just says how it does but doesn't
say why it does. After reading through the discussion, I suggest making
it clearer to others.

...
After the planning is done, it may still occupy lots of memory which is
allocated but not pfree-d. All of these memories can't be used in the later
stage. This patch will report such memory usage in order to making some
future mistakes can be found in an easier way.
...

(a description of how it works just like what you have done in the commit
message).

So if the people read the commit message, they can understand where the
function is used for.

2). at the second level, it would be cool that the user can understand the
metric without reading the commit message.

Planning Memory: used=15088 bytes allocated=16384 bytes

Word 'Planning' is kind of a time duration, so the 'used' may be the
'used' during the duration or 'used' after the duration. Obviously you
means the later one but it is not surprising others think it in the other
way. So I'd like to reword the metrics to:

Memory Occupied (Now): Parser: 1k Planner: 10k

'Now' is a cleaner signal that is a time point rather than a time
duration. 'Parser' and 'Planner' also show a timeline about the
important time point. At the same time, it cost very little coding
effort based on patch 01. Different people may have different
feelings about these words, I just hope I describe the goal clearly.

About patch 2 & patch 3, since I didn't find a good usage of it, so I
didn't put much effort on it. interesting probably is not a enough
reason for adding it IMO, since there are too many interesting things.

Personally I am pretty like patch 1, we just need to refactor some words
to make everything clearer.

--
Best Regards
Andy Fan

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-09-22T09:56:18Z

Hi Andy,
Thanks for your feedback.

On Fri, Sep 22, 2023 at 8:22 AM Andy Fan <zhihui.fan1213@gmail.com> wrote:
>
> 1). The commit message of patch 1 just says how it does but doesn't
> say why it does. After reading through the discussion, I suggest making
> it clearer to others.
>
> ...
> After the planning is done, it may still occupy lots of memory which is
> allocated but not pfree-d. All of these memories can't be used in the later
> stage. This patch will report such memory usage in order to making some
> future mistakes can be found in an easier way.
> ...

That's a good summary of how the memory report can be used. Will
include a line about usage in the commit message.

>
> Planning Memory: used=15088 bytes allocated=16384 bytes
>
> Word 'Planning' is kind of a time duration, so the 'used' may be the
> 'used' during the duration or 'used' after the duration. Obviously you
> means the later one but it is not surprising others think it in the other
> way. So I'd like to reword the metrics to:

We report "PLanning Time" hence used "Planning memory". Would
"Planner" be good instead of "Planning"?

>
> Memory Occupied (Now): Parser: 1k Planner: 10k
>
> 'Now' is a cleaner signal that is a time point rather than a time
> duration. 'Parser' and 'Planner' also show a timeline about the
> important time point. At the same time, it cost very little coding
> effort based on patch 01. Different people may have different
> feelings about these words, I just hope I describe the goal clearly.

Parsing happens before planning and that memory is not measured by
this patch. May be separately but it's out of scope of this work.
"used" and "allocated" are MemoryContext terms indicating memory
actually used vs memory allocated.

>
> Personally I am pretty like patch 1, we just need to refactor some words
> to make everything clearer.

Thanks.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Andy Fan <zhihui.fan1213@gmail.com> — 2023-09-25T03:35:17Z

Hi Ashutosh,

On Fri, Sep 22, 2023 at 5:56 PM Ashutosh Bapat <ashutosh.bapat.oss@gmail.com>
wrote:

> Hi Andy,
> Thanks for your feedback.
>
> On Fri, Sep 22, 2023 at 8:22 AM Andy Fan <zhihui.fan1213@gmail.com> wrote:
> >
> > 1). The commit message of patch 1 just says how it does but doesn't
> > say why it does. After reading through the discussion, I suggest making
> > it clearer to others.
> >
> > ...
> > After the planning is done, it may still occupy lots of memory which is
> > allocated but not pfree-d. All of these memories can't be used in the
> later
> > stage. This patch will report such memory usage in order to making some
> > future mistakes can be found in an easier way.
> > ...
>
> That's a good summary of how the memory report can be used. Will
> include a line about usage in the commit message.
>
> >
> > Planning Memory: used=15088 bytes allocated=16384 bytes
> >
> > Word 'Planning' is kind of a time duration, so the 'used' may be the
> > 'used' during the duration or 'used' after the duration. Obviously you
> > means the later one but it is not surprising others think it in the other
> > way. So I'd like to reword the metrics to:
>
> We report "PLanning Time" hence used "Planning memory". Would
> "Planner" be good instead of "Planning"?
>

I agree "Planner" is better than "Planning" personally.

>
> > Memory Occupied (Now): Parser: 1k Planner: 10k
> >
> > 'Now' is a cleaner signal that is a time point rather than a time
> > duration. 'Parser' and 'Planner' also show a timeline about the
> > important time point. At the same time, it cost very little coding
> > effort based on patch 01. Different people may have different
> > feelings about these words, I just hope I describe the goal clearly.
>
> Parsing happens before planning and that memory is not measured by
> this patch. May be separately but it's out of scope of this work.
> "used" and "allocated" are MemoryContext terms indicating memory
> actually used vs memory allocated.


Yes, I understand the terms come from MemoryContext, the complex
thing here is between time duration vs time point case. Since English
is not my native language, so I'm not too confident about insisting on
this.
So I think we can keep it as it is.


>
>
> > Personally I am pretty like patch 1, we just need to refactor some words
> > to make everything clearer.
>
> Thanks.
>

David challenged something at the begining,  but IIUC he also agree the
value of patch 01 as the previous statement after discussion. Since the
patch
is mild itself, so I will mark this commitfest entry as "Ready for
committer".
Please  correct me if anything is wrong.

-- 
Best Regards
Andy Fan

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-10-30T14:43:30Z

>
>
> David challenged something at the begining,  but IIUC he also agree the
> value of patch 01 as the previous statement after discussion. Since the patch
> is mild itself, so I will mark this commitfest entry as "Ready for committer".
> Please  correct me if anything is wrong.
>
Thanks Andy.

Here's rebased patches. A conflict in explain.out resolved.


-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2023-11-21T18:24:58Z

I gave this a quick look.  I think the usefulness aspect is already
established in general terms; the bit I'm not so sure about is whether
we want it enabled by default.  For many cases it'd just be noise.
Perhaps we want it hidden behind something like "EXPLAIN (MEMORY)" or
such, particularly since things like "allocated" (which, per David,
seems to be the really useful metric) seems too much a PG-developer
value rather than an end-user value.

If EXPLAIN (MEMORY) is added, then probably auto_explain needs a
corresponding flag, and doc updates.

Some code looks to be in weird places.  Why is calc_mem_usage, which
operates on MemoryContextCounters, in explain.c instead of mcxt.c?
why is MemUsage in explain.h instead of memnodes.h?  I moved both.  I
also renamed them, to MemoryContextSizeDifference() and MemoryUsage
respectively; fixup patch attached.

I see no reason for this to be three separate patches anymore.

The EXPLAIN docs (explain.sgml) need an update to mention the new flag
and the new output, too.

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-11-30T11:05:11Z

Hi Alvaro,
Thanks for the review and the edits. Sorry for replying late.

On Tue, Nov 21, 2023 at 11:56 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
>
> I gave this a quick look.  I think the usefulness aspect is already
> established in general terms; the bit I'm not so sure about is whether
> we want it enabled by default.  For many cases it'd just be noise.
> Perhaps we want it hidden behind something like "EXPLAIN (MEMORY)" or
> such, particularly since things like "allocated" (which, per David,
> seems to be the really useful metric) seems too much a PG-developer
> value rather than an end-user value.

It is not default but hidden behind "SUMMARY".Do you still think it
requires another sub-flag MEMORY?

>
> If EXPLAIN (MEMORY) is added, then probably auto_explain needs a
> corresponding flag, and doc updates.
>
> Some code looks to be in weird places.  Why is calc_mem_usage, which
> operates on MemoryContextCounters, in explain.c instead of mcxt.c?
> why is MemUsage in explain.h instead of memnodes.h?  I moved both.  I
> also renamed them, to MemoryContextSizeDifference() and MemoryUsage
> respectively; fixup patch attached.

That looks better. The functions are now available outside explain.

>
> I see no reason for this to be three separate patches anymore.

Squashed into one along with your changes.

>
> The EXPLAIN docs (explain.sgml) need an update to mention the new flag
> and the new output, too.

Updated section describing  "SUMMARY" flag.

PFA updated patch.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2023-11-30T11:40:28Z

On 2023-Nov-30, Ashutosh Bapat wrote:

> Hi Alvaro,
> Thanks for the review and the edits. Sorry for replying late.
> 
> On Tue, Nov 21, 2023 at 11:56 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> >
> > I gave this a quick look.  I think the usefulness aspect is already
> > established in general terms; the bit I'm not so sure about is whether
> > we want it enabled by default.  For many cases it'd just be noise.
> > Perhaps we want it hidden behind something like "EXPLAIN (MEMORY)" or
> > such, particularly since things like "allocated" (which, per David,
> > seems to be the really useful metric) seems too much a PG-developer
> > value rather than an end-user value.
> 
> It is not default but hidden behind "SUMMARY".Do you still think it
> requires another sub-flag MEMORY?

Well, SUMMARY is enabled by default with ANALYZE, and I'd rather not
have planner memory consumption displayed by default with all EXPLAIN
ANALYZEs.  So yeah, I still think this deserves its own option.

But let's hear others' opinions on this point.  I'm only one vote here.

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"All rings of power are equal,
But some rings of power are more equal than others."
                                 (George Orwell's The Lord of the Rings)

Re: Report planning memory in EXPLAIN ANALYZE

Andrei Lepikhov <a.lepikhov@postgrespro.ru> — 2023-12-01T02:57:13Z

On 30/11/2023 18:40, Alvaro Herrera wrote:
> Well, SUMMARY is enabled by default with ANALYZE, and I'd rather not
> have planner memory consumption displayed by default with all EXPLAIN
> ANALYZEs.  So yeah, I still think this deserves its own option.
> 
> But let's hear others' opinions on this point.  I'm only one vote here.

I agree; it should be disabled by default. The fact that memory 
consumption outputs with byte precision (very uncomfortable for 
perception) is a sign that the primary audience is developers and for 
debugging purposes.

-- 
regards,
Andrei Lepikhov
Postgres Professional

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-12-04T07:24:25Z

On Fri, Dec 1, 2023 at 8:27 AM Andrei Lepikhov
<a.lepikhov@postgrespro.ru> wrote:
>
> On 30/11/2023 18:40, Alvaro Herrera wrote:
> > Well, SUMMARY is enabled by default with ANALYZE, and I'd rather not
> > have planner memory consumption displayed by default with all EXPLAIN
> > ANALYZEs.  So yeah, I still think this deserves its own option.
> >
> > But let's hear others' opinions on this point.  I'm only one vote here.
>
> I agree; it should be disabled by default. The fact that memory
> consumption outputs with byte precision (very uncomfortable for
> perception) is a sign that the primary audience is developers and for
> debugging purposes.

That's 2 vs 1. Here's patch with MEMORY option added. Replying to
Alvaro's earlier relevant comments.

> If EXPLAIN (MEMORY) is added, then probably auto_explain needs a
> corresponding flag, and doc updates.

auto_explain does not implement planner_hook and hence can not gather
information about planner's memory usage. So no new flag and doc
update to auto_explain. I have added a comment auto_explain.c but
probably even that's not needed. We are considering this option only
for developers and auto_explain is largely for users. So I didn't feel
like adding an implementation of planner_hook in auto_explain and use
MEMORY option. If we feel that planner's memory usage report is useful
in auto_explain, it should easy to do that in future.

> The EXPLAIN docs (explain.sgml) need an update to mention the new flag
> and the new output, too.

Done.

0001 is as is except explain.out and explain.sgml changes reverted.

0002 following changes. It's a separate patch for ease of review.
a. implements MEMORY option, adds tests in explain.sql and also
updates explain.sgml.
b. show_planning_memory renamed to show_planner_memory to be in sync
with the output
c. small indentation change by pgindent.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

jian he <jian.universality@gmail.com> — 2023-12-11T08:36:11Z

On Mon, Dec 4, 2023 at 3:24 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
>
> On Fri, Dec 1, 2023 at 8:27 AM Andrei Lepikhov
> <a.lepikhov@postgrespro.ru> wrote:
> >
> > On 30/11/2023 18:40, Alvaro Herrera wrote:
> > > Well, SUMMARY is enabled by default with ANALYZE, and I'd rather not
> > > have planner memory consumption displayed by default with all EXPLAIN
> > > ANALYZEs.  So yeah, I still think this deserves its own option.
> > >
> > > But let's hear others' opinions on this point.  I'm only one vote here.
> >
> > I agree; it should be disabled by default. The fact that memory
> > consumption outputs with byte precision (very uncomfortable for
> > perception) is a sign that the primary audience is developers and for
> > debugging purposes.
>
> That's 2 vs 1. Here's patch with MEMORY option added. Replying to
> Alvaro's earlier relevant comments.
>

"Include information on planner's memory consumption. Specially,
include the total memory allocated by the planner and net memory that
remains used at the end of the planning. It defaults to
<literal>FALSE</literal>.
"
doc/src/sgml/ref/explain.sgml
I can view MemoryContextSizeDifference, figure out the meaning.

But I am not sure "net memory that remains used at the end of the
planning" is the correct description.
(I am not native english speaker).

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-12-11T13:35:32Z

On Mon, Dec 11, 2023 at 2:06 PM jian he <jian.universality@gmail.com> wrote:
>
> On Mon, Dec 4, 2023 at 3:24 PM Ashutosh Bapat
> <ashutosh.bapat.oss@gmail.com> wrote:
> >
> > On Fri, Dec 1, 2023 at 8:27 AM Andrei Lepikhov
> > <a.lepikhov@postgrespro.ru> wrote:
> > >
> > > On 30/11/2023 18:40, Alvaro Herrera wrote:
> > > > Well, SUMMARY is enabled by default with ANALYZE, and I'd rather not
> > > > have planner memory consumption displayed by default with all EXPLAIN
> > > > ANALYZEs.  So yeah, I still think this deserves its own option.
> > > >
> > > > But let's hear others' opinions on this point.  I'm only one vote here.
> > >
> > > I agree; it should be disabled by default. The fact that memory
> > > consumption outputs with byte precision (very uncomfortable for
> > > perception) is a sign that the primary audience is developers and for
> > > debugging purposes.
> >
> > That's 2 vs 1. Here's patch with MEMORY option added. Replying to
> > Alvaro's earlier relevant comments.
> >
>
> "Include information on planner's memory consumption. Specially,
> include the total memory allocated by the planner and net memory that
> remains used at the end of the planning. It defaults to
> <literal>FALSE</literal>.
> "
> doc/src/sgml/ref/explain.sgml
> I can view MemoryContextSizeDifference, figure out the meaning.
>
> But I am not sure "net memory that remains used at the end of the
> planning" is the correct description.
> (I am not native english speaker).

The word "net" is used as an adjective, see [1]

[1] https://www.merriam-webster.com/dictionary/net (as an adjective)

Does that help? Do you have any other wording proposal?

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2023-12-12T20:11:31Z

I would replace the text in explain.sgml with this:

+      Include information on memory consumption by the query planning phase.
+      This includes the precise amount of storage used by planner in-memory
+      structures, as well as overall total consumption of planner memory,
+      including allocation overhead.
+      This parameter defaults to </literal>FALSE</literal>.

and remove the new example you're adding; it's not really necessary.

In struct ExplainState, I'd put the new member just below summary.

If we're creating a new memory context for planner, we don't need the
"mem_counts_start" thing, and we don't need the
MemoryContextSizeDifference thing.  Just add the
MemoryContextMemConsumed() function (which ISTM should be just below
MemoryContextMemAllocated() instead of in the middle of the
MemoryContextStats implementation), and
just report the values we get there.  I think the SizeDifference stuff
increases surface damage for no good reason.

ExplainOnePlan() is given a MemoryUsage object (or, if we do as above
and no longer have a MemoryUsage struct at all in the first place, a
MemoryContextCounters object) even when the MEMORY option is false.
This means we waste computing memory usage when not needed.  Let's avoid
that useless overhead.

I'd also do away with the comment you added in explain_ExecutorEnd() and
do just this, below setting of es->summary:

+           /* No support for MEMORY option */
+           /* es->memory = false; */

We don't need to elaborate more at present.

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"Doing what he did amounts to sticking his fingers under the hood of the
implementation; if he gets his fingers burnt, it's his problem."  (Tom Lane)

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2023-12-12T20:20:24Z

On 2023-Dec-12, Alvaro Herrera wrote:

> I would replace the text in explain.sgml with this:
> 
> +      Include information on memory consumption by the query planning phase.
> +      This includes the precise amount of storage used by planner in-memory
> +      structures, as well as overall total consumption of planner memory,
> +      including allocation overhead.
> +      This parameter defaults to </literal>FALSE</literal>.

(This can still use a lot more wordsmithing of course, such as avoiding
repeated use of "include/ing", ugh)

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"The Gord often wonders why people threaten never to come back after they've
been told never to return" (www.actsofgord.com)

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-12-13T10:51:30Z

On Wed, Dec 13, 2023 at 1:41 AM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
>
> I would replace the text in explain.sgml with this:
>
> +      Include information on memory consumption by the query planning phase.
> +      This includes the precise amount of storage used by planner in-memory
> +      structures, as well as overall total consumption of planner memory,
> +      including allocation overhead.
> +      This parameter defaults to </literal>FALSE</literal>.

To me consumption in the "... total consumption ..." part is same as
allocation and that includes allocation overhead as well as any memory
that was allocated but remained unused (see discussion [1] if you
haven't already) ultimately. Mentioning "total consumption" and
"allocation overhead" seems more confusing.

How about
+      Include information on memory consumption by the query planning phase.
+      Report the precise amount of storage used by planner in-memory
+      structures, and total memory considering allocation overhead.
+      The parameter defaults to <literal>FALSE</literal>.

Takes care of your complaint about multiple include/ing as well.

>
> and remove the new example you're adding; it's not really necessary.

Done.

>
> In struct ExplainState, I'd put the new member just below summary.

Done

>
> If we're creating a new memory context for planner, we don't need the
> "mem_counts_start" thing, and we don't need the
> MemoryContextSizeDifference thing.  Just add the
> MemoryContextMemConsumed() function (which ISTM should be just below
> MemoryContextMemAllocated() instead of in the middle of the
> MemoryContextStats implementation), and
> just report the values we get there.  I think the SizeDifference stuff
> increases surface damage for no good reason.

240 bytes are used right after creating a memory context i.e.
mem_counts_start.totalspace = 8192 and mem_counts_start.freespace =
7952. To account for that I used two counters and calculated the
difference. If no planning is involved in EXECUTE <prepared statement>
it will show 240 bytes used instead of 0. Barring that for all
practical purposes 240 bytes negligible. E.g. 240 bytes is 4% of the
amount of memory used for planning a simple query " select 'x' ". But
your suggestion simplifies the code a lot. An error of 240 bytes seems
worth the code simplification. So did that way.

>
> ExplainOnePlan() is given a MemoryUsage object (or, if we do as above
> and no longer have a MemoryUsage struct at all in the first place, a
> MemoryContextCounters object) even when the MEMORY option is false.
> This means we waste computing memory usage when not needed.  Let's avoid
> that useless overhead.

Done.

Also avoided creating a memory context and switching to it when
es->memory = false.

>
> I'd also do away with the comment you added in explain_ExecutorEnd() and
> do just this, below setting of es->summary:
>
> +           /* No support for MEMORY option */
> +           /* es->memory = false; */

Done.

I ended up rewriting most of the code, so squashed everything into a
single patch as attached.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2023-12-17T16:27:47Z

OK, I propose the following further minor tweaks.  (I modified the docs
following the wording we have for COSTS and BUFFERS).

There are two things that still trouble me a bit.  First, we assume that
the planner is using an AllocSet context, which I guess is true, but if
somebody runs the planner in a context of a different memcxt type, it's
going to be a problem.  So far we don't have infrastructure for creating
a context of the same type as another context.  Maybe it's too fine a
point to worry about, for sure.

The other question is about trying to support the EXPLAIN EXECUTE case.
Do you find that case really useful?  In a majority of cases planning is
not going to happen because it was already done by PREPARE (where we
_don't_ report memory, because we don't have EXPLAIN there), so it seems
a bit weird.  I suppose you could make it useful if you instructed the
user to set plan_cache_mode to custom, assuming that does actually work
(I didn't try).

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"El hombre nunca sabe de lo que es capaz hasta que lo intenta" (C. Dickens)

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-12-18T07:25:24Z

On Sun, Dec 17, 2023 at 10:31 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
>
> OK, I propose the following further minor tweaks.  (I modified the docs
> following the wording we have for COSTS and BUFFERS).

LGTM. Included in the attached patch.

>
> There are two things that still trouble me a bit.  First, we assume that
> the planner is using an AllocSet context, which I guess is true, but if
> somebody runs the planner in a context of a different memcxt type, it's
> going to be a problem.  So far we don't have infrastructure for creating
> a context of the same type as another context.  Maybe it's too fine a
> point to worry about, for sure.

I had considered this point. Different contexts take different
arguments for creation, so some jugglery is required to create a
context based on type. It looked more than necessary for the limited
scope of this patch. That's why I settled on the assertion. If we see
the need in future we can always add that support.

>
> The other question is about trying to support the EXPLAIN EXECUTE case.
> Do you find that case really useful?  In a majority of cases planning is
> not going to happen because it was already done by PREPARE (where we
> _don't_ report memory, because we don't have EXPLAIN there), so it seems
> a bit weird.  I suppose you could make it useful if you instructed the
> user to set plan_cache_mode to custom, assuming that does actually work
> (I didn't try).

If we set plan_cache_mode to force_custom_plan, we always plan the
statement and thus report memory.

You are right that we don't always plan the statement when EXECUTE Is
issued. But it seems we create plan underneath EXECUTE more often that
I expected. And the report looks mildly useful and interesting.

postgres@21258=#prepare stmt as select * from pg_class where oid = $1;
PREPARE
postgres@21258=#explain (memory) execute stmt(1); -- first time
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
rows=1 width=273)
   Index Cond: (oid = '1'::oid)
 Planner Memory: used=40448 bytes allocated=81920 bytes
(3 rows)

postgres@21258=#explain (memory) execute stmt(1);
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
rows=1 width=273)
   Index Cond: (oid = '1'::oid)
 Planner Memory: used=40368 bytes allocated=81920 bytes
(3 rows)

observe that the memory used is slightly different from the first
time. So when the plan is created again something happens that eats
few bytes less. I didn't investigate what.

The same output repeats if the statement is executed 3 more times.
That's as many times a custom plan is created for a statement by
default.

postgres@21258=#explain (memory) execute stmt(1);
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
rows=1 width=273)
   Index Cond: (oid = $1)
 Planner Memory: used=40272 bytes allocated=81920 bytes
(3 rows)

Observe that the memory used is less here again. So when creating the
generic plan something happened which causes the change in memory
consumption. Didn't investigate.

postgres@21258=#explain (memory) execute stmt(1);
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
rows=1 width=273)
   Index Cond: (oid = $1)
 Planner Memory: used=3520 bytes allocated=24576 bytes
(3 rows)

And now the planner is settled on very low value but still non-zero or
240 bytes. I think the parameter evaluation takes that much memory.
Haven't verified.

If we use an non-parameterized statement
postgres@21258=#prepare stmt as select * from pg_class where oid = 2345;
PREPARE
postgres@21258=#explain (memory) execute stmt;
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
rows=1 width=273)
   Index Cond: (oid = '2345'::oid)
 Planner Memory: used=37200 bytes allocated=65536 bytes
(3 rows)

first time memory is consumed by the planner.

postgres@21258=#explain (memory) execute stmt;
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
rows=1 width=273)
   Index Cond: (oid = '2345'::oid)
 Planner Memory: used=240 bytes allocated=8192 bytes
(3 rows)

Next time onwards it has settled on the custom plan.

I think there's something to learn and investigate from memory numbers
here. So not completely meaningless and useless.

I added that support on lines of "planning time".

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2023-12-18T07:27:58Z

Forgot to attach patch. Here it is

On Mon, Dec 18, 2023 at 12:55 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
>
> On Sun, Dec 17, 2023 at 10:31 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> >
> > OK, I propose the following further minor tweaks.  (I modified the docs
> > following the wording we have for COSTS and BUFFERS).
>
> LGTM. Included in the attached patch.
>
> >
> > There are two things that still trouble me a bit.  First, we assume that
> > the planner is using an AllocSet context, which I guess is true, but if
> > somebody runs the planner in a context of a different memcxt type, it's
> > going to be a problem.  So far we don't have infrastructure for creating
> > a context of the same type as another context.  Maybe it's too fine a
> > point to worry about, for sure.
>
> I had considered this point. Different contexts take different
> arguments for creation, so some jugglery is required to create a
> context based on type. It looked more than necessary for the limited
> scope of this patch. That's why I settled on the assertion. If we see
> the need in future we can always add that support.
>
> >
> > The other question is about trying to support the EXPLAIN EXECUTE case.
> > Do you find that case really useful?  In a majority of cases planning is
> > not going to happen because it was already done by PREPARE (where we
> > _don't_ report memory, because we don't have EXPLAIN there), so it seems
> > a bit weird.  I suppose you could make it useful if you instructed the
> > user to set plan_cache_mode to custom, assuming that does actually work
> > (I didn't try).
>
> If we set plan_cache_mode to force_custom_plan, we always plan the
> statement and thus report memory.
>
> You are right that we don't always plan the statement when EXECUTE Is
> issued. But it seems we create plan underneath EXECUTE more often that
> I expected. And the report looks mildly useful and interesting.
>
> postgres@21258=#prepare stmt as select * from pg_class where oid = $1;
> PREPARE
> postgres@21258=#explain (memory) execute stmt(1); -- first time
>                                      QUERY PLAN
> -------------------------------------------------------------------------------------
>  Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
> rows=1 width=273)
>    Index Cond: (oid = '1'::oid)
>  Planner Memory: used=40448 bytes allocated=81920 bytes
> (3 rows)
>
>
> postgres@21258=#explain (memory) execute stmt(1);
>                                      QUERY PLAN
> -------------------------------------------------------------------------------------
>  Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
> rows=1 width=273)
>    Index Cond: (oid = '1'::oid)
>  Planner Memory: used=40368 bytes allocated=81920 bytes
> (3 rows)
>
> observe that the memory used is slightly different from the first
> time. So when the plan is created again something happens that eats
> few bytes less. I didn't investigate what.
>
> The same output repeats if the statement is executed 3 more times.
> That's as many times a custom plan is created for a statement by
> default.
>
> postgres@21258=#explain (memory) execute stmt(1);
>                                      QUERY PLAN
> -------------------------------------------------------------------------------------
>  Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
> rows=1 width=273)
>    Index Cond: (oid = $1)
>  Planner Memory: used=40272 bytes allocated=81920 bytes
> (3 rows)
>
> Observe that the memory used is less here again. So when creating the
> generic plan something happened which causes the change in memory
> consumption. Didn't investigate.
>
>
> postgres@21258=#explain (memory) execute stmt(1);
>                                      QUERY PLAN
> -------------------------------------------------------------------------------------
>  Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
> rows=1 width=273)
>    Index Cond: (oid = $1)
>  Planner Memory: used=3520 bytes allocated=24576 bytes
> (3 rows)
>
> And now the planner is settled on very low value but still non-zero or
> 240 bytes. I think the parameter evaluation takes that much memory.
> Haven't verified.
>
> If we use an non-parameterized statement
> postgres@21258=#prepare stmt as select * from pg_class where oid = 2345;
> PREPARE
> postgres@21258=#explain (memory) execute stmt;
>                                      QUERY PLAN
> -------------------------------------------------------------------------------------
>  Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
> rows=1 width=273)
>    Index Cond: (oid = '2345'::oid)
>  Planner Memory: used=37200 bytes allocated=65536 bytes
> (3 rows)
>
> first time memory is consumed by the planner.
>
> postgres@21258=#explain (memory) execute stmt;
>                                      QUERY PLAN
> -------------------------------------------------------------------------------------
>  Index Scan using pg_class_oid_index on pg_class  (cost=0.27..8.29
> rows=1 width=273)
>    Index Cond: (oid = '2345'::oid)
>  Planner Memory: used=240 bytes allocated=8192 bytes
> (3 rows)
>
> Next time onwards it has settled on the custom plan.
>
> I think there's something to learn and investigate from memory numbers
> here. So not completely meaningless and useless.
>
> I added that support on lines of "planning time".
>
> --
> Best Wishes,
> Ashutosh Bapat



-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2024-01-12T16:52:27Z

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:

 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).

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

Or we could leave it as you have it, but to me that's akin to giving up
on doing it nicely.

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"I think my standards have lowered enough that now I think 'good design'
is when the page doesn't irritate the living f*ck out of me." (JWZ)

Re: Report planning memory in EXPLAIN ANALYZE

Abhijit Menon-Sen <ams@toroid.org> — 2024-01-12T17:23:08Z

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

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

-- Abhijit

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2024-01-16T14:49:14Z

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

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2024-01-18T09:55:17Z

On Tue, Jan 16, 2024 at 8:19 PM Ashutosh Bapat
<ashutosh.bapat.oss@gmail.com> wrote:
>
> Using a boolean return and moving es->indent-- outside of
> show_buffer_usage would be less elegant.
>

I went ahead with this option so as not to break backward
compatibility in any manner. Attached patch 0002 has the code and
expected output changes.

I have continued to use the variable "show_planning" and the new
variable is named accordingly. Other options I could think of, like
open_planning_section ended up being all long and rejected.

I considered adding a test for EXPLAIN(memory, buffers) but
explain.sql filters out Buffers: and Planning: lines, so it's not of
much use.

Returning from show_planning_buffers() is not necessary, but it looks
consistent with show_buffer_usage() in the code block using them
together.

Here's how the output looks now
In Text format
#explain (memory, buffers) select * from pg_class;
                         QUERY PLAN
-------------------------------------------------------------
 Seq Scan on pg_class  (cost=0.00..18.15 rows=415 width=273)
 Planning:
   Buffers: shared hit=134 read=15
   I/O Timings: shared read=0.213
   Memory: used=22928 bytes, allocated=32768 bytes
(5 rows)

with planning time
#explain (analyze, memory, buffers) select * from pg_class;
                                               QUERY PLAN
---------------------------------------------------------------------------------------------------------
 Seq Scan on pg_class  (cost=0.00..18.15 rows=415 width=273) (actual
time=0.020..0.378 rows=415 loops=1)
   Buffers: shared hit=14
 Planning:
   Buffers: shared hit=134 read=15
   I/O Timings: shared read=0.635
   Memory: used=22928 bytes, allocated=32768 bytes
 Planning Time: 4.328 ms
 Execution Time: 1.262 ms
(8 rows)

Just memory option
#explain (memory) select * from pg_class;
                         QUERY PLAN
-------------------------------------------------------------
 Seq Scan on pg_class  (cost=0.00..18.15 rows=415 width=273)
 Planning:
   Memory: used=22928 bytes, allocated=32768 bytes
(3 rows)

In JSON format
#explain (memory, buffers, format json) select * from pg_class;
(Notice Memory Used and Memory Allocated properties.
              QUERY PLAN
---------------------------------------
 [                                    +
   {                                  +
     "Plan": {                        +
... snip ...
     },                               +
     "Planning": {                    +
       "Shared Hit Blocks": 152,      +
       "Shared Read Blocks": 0,       +
       "Shared Dirtied Blocks": 0,    +
       "Shared Written Blocks": 0,    +
       "Local Hit Blocks": 0,         +
       "Local Read Blocks": 0,        +
       "Local Dirtied Blocks": 0,     +
       "Local Written Blocks": 0,     +
       "Temp Read Blocks": 0,         +
       "Temp Written Blocks": 0,      +
       "Shared I/O Read Time": 0.000, +
       "Shared I/O Write Time": 0.000,+
       "Local I/O Read Time": 0.000,  +
       "Local I/O Write Time": 0.000, +
       "Temp I/O Read Time": 0.000,   +
       "Temp I/O Write Time": 0.000,  +
       "Memory Used": 22928,          +
       "Memory Allocated": 32768      +
     }                                +
   }                                  +
 ]
(1 row)

JSON format with planning time
#explain (analyze, memory, buffers, format json) select * from pg_class;
              QUERY PLAN
---------------------------------------
 [                                    +
   {                                  +
     "Plan": {                        +
 ... snip ...
     },                               +
     "Planning": {                    +
       "Shared Hit Blocks": 152,      +
       "Shared Read Blocks": 0,       +
       "Shared Dirtied Blocks": 0,    +
       "Shared Written Blocks": 0,    +
       "Local Hit Blocks": 0,         +
       "Local Read Blocks": 0,        +
       "Local Dirtied Blocks": 0,     +
       "Local Written Blocks": 0,     +
       "Temp Read Blocks": 0,         +
       "Temp Written Blocks": 0,      +
       "Shared I/O Read Time": 0.000, +
       "Shared I/O Write Time": 0.000,+
       "Local I/O Read Time": 0.000,  +
       "Local I/O Write Time": 0.000, +
       "Temp I/O Read Time": 0.000,   +
       "Temp I/O Write Time": 0.000,  +
       "Memory Used": 22928,          +
       "Memory Allocated": 32768      +
     },                               +
     "Planning Time": 3.840,          +
     "Triggers": [                    +
     ],                               +
     "Execution Time": 1.266          +
   }                                  +
 ]
(1 row)

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

did this way.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2024-01-18T11:12:03Z

On 2024-Jan-18, Ashutosh Bapat wrote:

Hmm ... TBH I don't like the "showed_planning" thing very much, but if
we need to conditionalize the printing of "Planning:" on whether we
print either of buffers or memory, maybe there's no way around something
like what you propose.

However, I don't understand this output change, and I think it indicates
a bug in the logic there:

> diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
> index 86bfdfd29e..55694505a7 100644
> --- a/src/test/regress/expected/explain.out
> +++ b/src/test/regress/expected/explain.out
> @@ -331,15 +331,15 @@ select explain_filter('explain (memory) select * from int8_tbl i8');
>                       explain_filter                      
>  ---------------------------------------------------------
>   Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
> - Planner Memory: used=N bytes allocated=N bytes
> +   Memory: used=N bytes, allocated=N bytes
>  (2 rows)

Does this really make sense?

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"Linux transformó mi computadora, de una `máquina para hacer cosas',
en un aparato realmente entretenido, sobre el cual cada día aprendo
algo nuevo" (Jaime Salinas)

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2024-01-18T11:28:49Z

On Thu, Jan 18, 2024 at 4:42 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
>
> On 2024-Jan-18, Ashutosh Bapat wrote:
>
> Hmm ... TBH I don't like the "showed_planning" thing very much, but if
> we need to conditionalize the printing of "Planning:" on whether we
> print either of buffers or memory, maybe there's no way around something
> like what you propose.

right.

>
> However, I don't understand this output change, and I think it indicates
> a bug in the logic there:
>
> > diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
> > index 86bfdfd29e..55694505a7 100644
> > --- a/src/test/regress/expected/explain.out
> > +++ b/src/test/regress/expected/explain.out
> > @@ -331,15 +331,15 @@ select explain_filter('explain (memory) select * from int8_tbl i8');
> >                       explain_filter
> >  ---------------------------------------------------------
> >   Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
> > - Planner Memory: used=N bytes allocated=N bytes
> > +   Memory: used=N bytes, allocated=N bytes
> >  (2 rows)
>
> Does this really make sense?

The EXPLAIN output produces something like below
                       explain_filter
  ---------------------------------------------------------
   Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
  Planning:
    Memory: used=N bytes, allocated=N bytes
 (3 rows)

but function explain_filter(), defined in explain.sql, removes line
containing Planning: and we end up with output
                       explain_filter
  ---------------------------------------------------------
   Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
    Memory: used=N bytes, allocated=N bytes
 (2 rows)

Hence this weird difference.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2024-01-18T11:58:05Z

On 2024-Jan-18, Ashutosh Bapat wrote:

> The EXPLAIN output produces something like below
>                        explain_filter
>   ---------------------------------------------------------
>    Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
>   Planning:
>     Memory: used=N bytes, allocated=N bytes
>  (3 rows)
> 
> but function explain_filter(), defined in explain.sql, removes line
> containing Planning: and we end up with output
>                        explain_filter
>   ---------------------------------------------------------
>    Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
>     Memory: used=N bytes, allocated=N bytes
>  (2 rows)
> 
> Hence this weird difference.

Ah, okay, that makes sense.  (I actually think this is a bit insane, and
I would hope that we can revert commit eabba4a3eb71 eventually, but I
don't think that needs to hold up your proposed patch.)

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"At least to kernel hackers, who really are human, despite occasional
rumors to the contrary" (LWN.net)

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2024-01-23T04:46:49Z

On Thu, Jan 18, 2024 at 5:28 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
>
> On 2024-Jan-18, Ashutosh Bapat wrote:
>
> > The EXPLAIN output produces something like below
> >                        explain_filter
> >   ---------------------------------------------------------
> >    Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
> >   Planning:
> >     Memory: used=N bytes, allocated=N bytes
> >  (3 rows)
> >
> > but function explain_filter(), defined in explain.sql, removes line
> > containing Planning: and we end up with output
> >                        explain_filter
> >   ---------------------------------------------------------
> >    Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
> >     Memory: used=N bytes, allocated=N bytes
> >  (2 rows)
> >
> > Hence this weird difference.
>
> Ah, okay, that makes sense.  (I actually think this is a bit insane, and
> I would hope that we can revert commit eabba4a3eb71 eventually, but I
> don't think that needs to hold up your proposed patch.)
>

Thanks. Attached is rebased and squashed patch.


-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2024-01-29T17:13:35Z

Okay, so I gave this another look and concluded that I definitely didn't
like the whole business of having one level open the explain group and
return outwards whether it had been done so that the other level would
close it.  So I made the code do what I said I thought it should do
(adding a new function peek_buffer_usage to report whether BUFFERS would
print anything), and I have to say that it looks much better to me with
that.

I also added a trivial test for EXPLAIN EXECUTE, which was uncovered,
and some other minor stylistic changes.

And with that I pushed it.

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
#error "Operator lives in the wrong universe"
  ("Use of cookies in real-time system development", M. Gleixner, M. Mc Guire)

Re: Report planning memory in EXPLAIN ANALYZE

Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> — 2024-01-30T06:39:52Z

On Mon, Jan 29, 2024 at 10:43 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
>
> Okay, so I gave this another look and concluded that I definitely didn't
> like the whole business of having one level open the explain group and
> return outwards whether it had been done so that the other level would
> close it.  So I made the code do what I said I thought it should do
> (adding a new function peek_buffer_usage to report whether BUFFERS would
> print anything), and I have to say that it looks much better to me with
> that.

Hmm. ExplainOnePlan certainly looks better with this.

>
> I also added a trivial test for EXPLAIN EXECUTE, which was uncovered,
> and some other minor stylistic changes.
>

Thanks. Looks fine to me.

> And with that I pushed it.

Thanks a lot.

-- 
Best Wishes,
Ashutosh Bapat

Re: Report planning memory in EXPLAIN ANALYZE

Alvaro Herrera <alvherre@alvh.no-ip.org> — 2024-01-30T10:18:32Z

On 2024-Jan-30, Ashutosh Bapat wrote:

> On Mon, Jan 29, 2024 at 10:43 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

> > I also added a trivial test for EXPLAIN EXECUTE, which was uncovered,
> > and some other minor stylistic changes.
> 
> Thanks. Looks fine to me.

Thanks for looking!

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
¡Ay, ay, ay!  Con lo mucho que yo lo quería (bis)
se fue de mi vera ... se fue para siempre, pa toíta ... pa toíta la vida
¡Ay Camarón! ¡Ay Camarón!                                (Paco de Lucía)