Re: Planning time in explain/explain analyze

Hi,

A user asked in -performance[1] if there is a way to measure the
planning time. Other than measuring it in the client I do not think
there is so I quickly hacked a patched which adds "Planning time" to the
outputs of EXPLAIN and EXPLAIN ANALYZE.

Is this something useful? I think it is, since plan time can become an
issue for complex queries.

A couple of questions about the path: Should the planning time be added
to both EXPLAIN and EXPLAIN ANALYZE? And is the output obvious enough?

The patch does not include any changes to documentation or tests. I will
fix that if people think this patch is useful.

$ EXPLAIN SELECT * FROM pg_stat_activity;
QUERY PLAN

--------------------------------------------------------------------------------------------------
Nested Loop (cost=1.15..2.69 rows=1 width=337)
-> Hash Join (cost=1.02..2.41 rows=1 width=273)
Hash Cond: (s.usesysid = u.oid)
-> Function Scan on pg_stat_get_activity s (cost=0.00..1.00
rows=100 width=209)
-> Hash (cost=1.01..1.01 rows=1 width=68)
-> Seq Scan on pg_authid u (cost=0.00..1.01 rows=1
width=68)
-> Index Scan using pg_database_oid_index on pg_database d
(cost=0.13..0.27 rows=1 width=68)
Index Cond: (oid = s.datid)
Planning time: 0.258 ms
(9 rows)

$ EXPLAIN ANALYZE SELECT * FROM pg_stat_activity;
QUERY
PLAN
--------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=1.15..2.69 rows=1 width=337) (actual
time=0.094..0.096 rows=1 loops=1)
-> Hash Join (cost=1.02..2.41 rows=1 width=273) (actual
time=0.078..0.079 rows=1 loops=1)
Hash Cond: (s.usesysid = u.oid)
-> Function Scan on pg_stat_get_activity s (cost=0.00..1.00
rows=100 width=209) (actual time=0.053..0.053 rows=1 loops=1)
-> Hash (cost=1.01..1.01 rows=1 width=68) (actual
time=0.014..0.014 rows=1 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> Seq Scan on pg_authid u (cost=0.00..1.01 rows=1
width=68) (actual time=0.007..0.009 rows=1 loops=1)
-> Index Scan using pg_database_oid_index on pg_database d
(cost=0.13..0.27 rows=1 width=68) (actual time=0.009..0.010 rows=1 loops=1)
Index Cond: (oid = s.datid)
Planning time: 0.264 ms
Total runtime: 0.158 ms
(11 rows)

Links

1.
http://www.postgresql.org/message-id/CACfv+pKNEmbQyJPCqRGsVmc_HvRGAi3d_Ge893N8qbX+ymhodA@mail.gmail.com

--
Andreas Karlsson

Andreas Karlsson <andreas(at)proxel(dot)se> writes:
> The patch does not include any changes to documentation or tests. I will
> fix that if people think this patch is useful.

I take it you've not tried the regression tests with this.

regards, tom lane

On 23-12-2013 22:12, Andreas Karlsson wrote:
> A user asked in -performance[1] if there is a way to measure the
> planning time. Other than measuring it in the client I do not think
> there is so I quickly hacked a patched which adds "Planning time" to the
> outputs of EXPLAIN and EXPLAIN ANALYZE.
>
> Is this something useful? I think it is, since plan time can become an
> issue for complex queries.
>
Yes, but a couple of years ago, this same feature was proposed as a
module [1][2]. I'm not sure if it is worth including as an additional
module or not. Opinions?

[1]
http://www.postgresql.org/message-id/BANLkTi=sxKTCTcv9hsACu38eaj=fW_4OMA@mail.gmail.com
[2] https://github.com/umitanuki/planinstr

--
Euler Taveira Timbira - http://www.timbira.com.br/
PostgreSQL: Consultoria, Desenvolvimento, Suporte 24x7 e Treinamento

On 12/24/2013 03:33 AM, Tom Lane wrote:
> Andreas Karlsson <andreas(at)proxel(dot)se> writes:
>> The patch does not include any changes to documentation or tests. I will
>> fix that if people think this patch is useful.
>
> I take it you've not tried the regression tests with this.

Yeah, forgot to mention that we need some way to disable it in the
tests. Either by not having it included in EXPLAIN or by adding an
option to turn it off. Any suggestion on which would be preferable?

--
Andreas Karlsson

On Mon, Dec 23, 2013 at 9:54 PM, Andreas Karlsson <andreas(at)proxel(dot)se> wrote:
> On 12/24/2013 03:33 AM, Tom Lane wrote:
>>
>> Andreas Karlsson <andreas(at)proxel(dot)se> writes:
>>>
>>> The patch does not include any changes to documentation or tests. I will
>>> fix that if people think this patch is useful.
>>
>>
>> I take it you've not tried the regression tests with this.
>
>
> Yeah, forgot to mention that we need some way to disable it in the tests.
> Either by not having it included in EXPLAIN or by adding an option to turn
> it off. Any suggestion on which would be preferable?

I would be tempted to display it only if (COSTS OFF) is not given. As
far as I can tell, the major use case for (COSTS OFF) is when you want
the output to be stable so you can include it in a regression test.
Technically speaking, planning time is not a cost, but I'm not sure I
could live with myself if we forced everyone to write (COSTS OFF,
PLANNING_TIME OFF). And I don't think much of the idea of only
including planning time when ANALYZE is used, because you don't have
to want to run the query to want to know how long it took to plan.

Also, +1 for this general concept. Great idea.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Mon, Dec 23, 2013 at 9:54 PM, Andreas Karlsson <andreas(at)proxel(dot)se> wrote:
>> Yeah, forgot to mention that we need some way to disable it in the tests.
>> Either by not having it included in EXPLAIN or by adding an option to turn
>> it off. Any suggestion on which would be preferable?

> I would be tempted to display it only if (COSTS OFF) is not given.

Yeah. The alternatives seem to be:

1. Change a lot of regression tests. This would be a serious PITA,
not so much for the one-time cost as for every time we needed to
back-patch a regression test that includes explain output. -1.

2. Don't display the planning time by default, necessitating a new
PLANNING_TIME ON option. This has backwards compatibility to
recommend it, but not much else.

3. Let COSTS OFF suppress it.

regards, tom lane

On Mon, Dec 23, 2013 at 10:47 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> On Mon, Dec 23, 2013 at 9:54 PM, Andreas Karlsson <andreas(at)proxel(dot)se> wrote:
>>> Yeah, forgot to mention that we need some way to disable it in the tests.
>>> Either by not having it included in EXPLAIN or by adding an option to turn
>>> it off. Any suggestion on which would be preferable?
>
>> I would be tempted to display it only if (COSTS OFF) is not given.
>
> Yeah. The alternatives seem to be:
>
> 1. Change a lot of regression tests. This would be a serious PITA,
> not so much for the one-time cost as for every time we needed to
> back-patch a regression test that includes explain output. -1.
>
> 2. Don't display the planning time by default, necessitating a new
> PLANNING_TIME ON option. This has backwards compatibility to
> recommend it, but not much else.
>
> 3. Let COSTS OFF suppress it.

Another option would be to not display it by default, but make VERBOSE
show it. However, I think making it controlled by COSTS is a better
fit.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 12/23/13, 8:12 PM, Andreas Karlsson wrote:
> A user asked in -performance[1] if there is a way to measure the
> planning time.

log_planner_stats

On 12/24/2013 02:31 PM, Peter Eisentraut wrote:
> On 12/23/13, 8:12 PM, Andreas Karlsson wrote:
>> A user asked in -performance[1] if there is a way to measure the
>> planning time.
>
> log_planner_stats

Thanks for the suggestion, I will use that if I need to know the plan
times. But I do not think this is as useful as having it in the EXPLAIN
output.

--
Andreas Karlsson

On 12/24/2013 05:09 AM, Robert Haas wrote:
>> Yeah. The alternatives seem to be:
>>
>> 1. Change a lot of regression tests. This would be a serious PITA,
>> not so much for the one-time cost as for every time we needed to
>> back-patch a regression test that includes explain output. -1.
>>
>> 2. Don't display the planning time by default, necessitating a new
>> PLANNING_TIME ON option. This has backwards compatibility to
>> recommend it, but not much else.
>>
>> 3. Let COSTS OFF suppress it.
>
> Another option would be to not display it by default, but make VERBOSE
> show it. However, I think making it controlled by COSTS is a better
> fit.

After some thinking COSTS OFF really seems to be the best option. I have
changed this in the patch and will submit a patch with updated
documentation as soon as I get the time. Adding "Planning time" to all
explain outputs (only 37 of them) in the documentation should not
clutter anything too much.

--
Andreas Karlsson

New version of the patch with updated documentation and which does not
display the planning time when the COSTS are off.

I will add it to the next commitfest.

--
Andreas Karlsson

On Sat, Dec 28, 2013 at 11:32 PM, Andreas Karlsson <andreas(at)proxel(dot)se> wrote:
> New version of the patch with updated documentation and which does not
> display the planning time when the COSTS are off.
>
> I will add it to the next commitfest.

I'm wondering whether the time should be stored inside the PlannedStmt
node instead of passing it around separately. One possible problem
with the way you've done things here is that, in the case of a
prepared statement, EXPLAIN ANALYZE will emit the time needed to call
GetCachedPlan(), even if that function didn't do any replanning. Now
you could argue that this is the correct behavior, but I think there's
a decent argument that what we ought to show there is the amount of
time that was required to create the plan that we're displaying at the
time it was created, rather than the amount of time that was required
to figure out that we didn't need to replan.

A minor side benefit of this approach is that you wouldn't need to
change the signature for ExplainOnePlan(), which would avoid breaking
extensions that may call it.

Also, I am inclined to think we ought to update the examples, rather
than say this:

+ rewriting and parsing. We will not include this line in later examples in
+ this section.
+ </para>

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 01/02/2014 04:08 AM, Robert Haas wrote:
> I'm wondering whether the time should be stored inside the PlannedStmt
> node instead of passing it around separately. One possible problem
> with the way you've done things here is that, in the case of a
> prepared statement, EXPLAIN ANALYZE will emit the time needed to call
> GetCachedPlan(), even if that function didn't do any replanning. Now
> you could argue that this is the correct behavior, but I think there's
> a decent argument that what we ought to show there is the amount of
> time that was required to create the plan that we're displaying at the
> time it was created, rather than the amount of time that was required
> to figure out that we didn't need to replan.

Since we support re-planning of prepared statements I would argue the
most useful thing is to print the time it took to fetch the old plan or
the create a new one as the planning time, but I am not a heavy user of
prepared statements.

> Also, I am inclined to think we ought to update the examples, rather
> than say this:
>
> + rewriting and parsing. We will not include this line in later examples in
> + this section.
> + </para>

Ok, I will fix this in the next version of the patch.

--
Andreas Karlsson

A patch with updated documentation is attached.

On 01/02/2014 04:08 AM, Robert Haas wrote:
> I'm wondering whether the time should be stored inside the PlannedStmt
> node instead of passing it around separately. One possible problem
> with the way you've done things here is that, in the case of a
> prepared statement, EXPLAIN ANALYZE will emit the time needed to call
> GetCachedPlan(), even if that function didn't do any replanning. Now
> you could argue that this is the correct behavior, but I think there's
> a decent argument that what we ought to show there is the amount of
> time that was required to create the plan that we're displaying at the
> time it was created, rather than the amount of time that was required
> to figure out that we didn't need to replan.
>
> A minor side benefit of this approach is that you wouldn't need to
> change the signature for ExplainOnePlan(), which would avoid breaking
> extensions that may call it.

A possible argument against printing the time to create the plan is that
unless it was created when running EXPLAIN we will not know it. I do not
think we want to always measure the time it took to generate a plan due
to slow clocks on some architectures. Also I feel that such a patch
would be more invasive.

Just my reasoning for the current solution. I welcome any opinions about
how to print planning time for prepared statements since I am not a
heavy user of them.

--
Andreas Karlsson

Andreas, Robert,

* Andreas Karlsson (andreas(at)proxel(dot)se) wrote:
> A patch with updated documentation is attached.

Thanks for working on this!

> On 01/02/2014 04:08 AM, Robert Haas wrote:
> >I'm wondering whether the time should be stored inside the PlannedStmt
> >node instead of passing it around separately. One possible problem
> >with the way you've done things here is that, in the case of a
> >prepared statement, EXPLAIN ANALYZE will emit the time needed to call
> >GetCachedPlan(), even if that function didn't do any replanning. Now
> >you could argue that this is the correct behavior, but I think there's
> >a decent argument that what we ought to show there is the amount of
> >time that was required to create the plan that we're displaying at the
> >time it was created, rather than the amount of time that was required
> >to figure out that we didn't need to replan.

Agreed, and really, it'd be nice to know *both*. If we're worried about
the timing cost when going through a no-op GetCachedPlan(), then perhaps
we don't add that, but if we actually *do* re-plan, it'd be handy to
know that and to know the timing it took.

> >A minor side benefit of this approach is that you wouldn't need to
> >change the signature for ExplainOnePlan(), which would avoid breaking
> >extensions that may call it.

Agreed.

> A possible argument against printing the time to create the plan is
> that unless it was created when running EXPLAIN we will not know it.

This is perhaps the biggest point against- if we keep it this way...

> I do not think we want to always measure the time it took to
> generate a plan due to slow clocks on some architectures. Also I
> feel that such a patch would be more invasive.

The slow-clock argument is really quite frustrating for those of us who
are looking to add more and more metrics to PG. We're nowhere near the
level that we need to be and it shows (particularly for users coming
from $OTHER-RDBMS). Perhaps we should try and come up with a solution
to address those cases (turn off metrics ala turning off stats?) while
not preventing us from gathering metrics on more reasonable systems.

Thanks,

Stephen

On Thu, Jan 9, 2014 at 1:50 PM, Stephen Frost <sfrost(at)snowman(dot)net> wrote:
>> I do not think we want to always measure the time it took to
>> generate a plan due to slow clocks on some architectures. Also I
>> feel that such a patch would be more invasive.
>
> The slow-clock argument is really quite frustrating for those of us who
> are looking to add more and more metrics to PG.

Especially since implementing gettimeofday quickly is a solved problem
on most architectures.

However I don't see the issue here. Two gettimeofday calls per query
plan is not really going to hurt even on systems where it's slow. The
problems we run into are explain analyze which runs getimeofday twice
for every node for every tuple processed. For cpu-bound queries that's
can become the dominant cost.

The only way two gettimeofday calls per query plan becomes an issue is
if you're executing non-cached queries repeatedly on data that's
entirely in ram. That means the query processing is entirely cpu-bound
and adding two syscalls could actually be noticeable. The mitigation
strategy would be to prepare and cache the query handle to execute it
again.

> We're nowhere near the
> level that we need to be and it shows (particularly for users coming
> from $OTHER-RDBMS). Perhaps we should try and come up with a solution
> to address those cases (turn off metrics ala turning off stats?) while
> not preventing us from gathering metrics on more reasonable systems.

--
greg

Greg Stark <stark(at)mit(dot)edu> writes:
> However I don't see the issue here. Two gettimeofday calls per query
> plan is not really going to hurt even on systems where it's slow.

I tend to agree with this, especially if the calls only occur when the
user asks for the information (ie, does an EXPLAIN rather than just
executing the query).

> The only way two gettimeofday calls per query plan becomes an issue is
> if you're executing non-cached queries repeatedly on data that's
> entirely in ram. That means the query processing is entirely cpu-bound
> and adding two syscalls could actually be noticeable. The mitigation
> strategy would be to prepare and cache the query handle to execute it
> again.

This point weighs against the proposal that we time the work to fetch
a previously-prepared query plan; if we do that then the "mitigation
strategy" doesn't mitigate anything.

In short then, I think we should just add this to EXPLAIN and be done.
-1 for sticking the info into PlannedStmt or anything like that.

regards, tom lane

On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> In short then, I think we should just add this to EXPLAIN and be done.
> -1 for sticking the info into PlannedStmt or anything like that.

I'm confused. I thought I was arguing to support your suggestion that
the initial planning store the time in the cached plan and explain
should output the time the original planning took.

--
greg

Greg Stark <stark(at)mit(dot)edu> writes:
> On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> In short then, I think we should just add this to EXPLAIN and be done.
>> -1 for sticking the info into PlannedStmt or anything like that.

> I'm confused. I thought I was arguing to support your suggestion that
> the initial planning store the time in the cached plan and explain
> should output the time the original planning took.

Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
planning cycle, explain or no? I was thinking more of just putting the
timing calls into explain.c.

regards, tom lane

On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Greg Stark <stark(at)mit(dot)edu> writes:
>> On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>>> In short then, I think we should just add this to EXPLAIN and be done.
>>> -1 for sticking the info into PlannedStmt or anything like that.
>
>> I'm confused. I thought I was arguing to support your suggestion that
>> the initial planning store the time in the cached plan and explain
>> should output the time the original planning took.
>
> Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
> planning cycle, explain or no? I was thinking more of just putting the
> timing calls into explain.c.

Currently the patch includes changes to prepare.c which is what seems
odd to me. I think it'd be fine to say, hey, I can't give you the
planning time in this EXPLAIN ANALYZE because I just used a cached
plan and did not re-plan. But saying, hey, the planning time is
$TINYVALUE, when what we really mean is that looking up the
previously-cached plan took only that long, seems actively misleading
to me.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

* Robert Haas (robertmhaas(at)gmail(dot)com) wrote:
> Currently the patch includes changes to prepare.c which is what seems
> odd to me. I think it'd be fine to say, hey, I can't give you the
> planning time in this EXPLAIN ANALYZE because I just used a cached
> plan and did not re-plan. But saying, hey, the planning time is
> $TINYVALUE, when what we really mean is that looking up the
> previously-cached plan took only that long, seems actively misleading
> to me.

My thought, at least, was to always grab the planning time and then
provide it for explain and/or explain analyze, and then for re-plan
cases, indicate if a cached plan was returned, if a replan happened, and
if a replan happened, what the old plan time and the new plan time was.

I don't think it makes any sense to report on the time returned from
pulling a previously-cached plan.

I understand that it's not completely free to track the plan time for
every query but I'm in the camp that says "we need better metrics and
information for 99% of what we do" and I'd like to see us eventually
able to track average plan time (maybe on a per-query basis..), average
run-time, how many times we do a hashjoin, mergejoin, the number of
records in/out of each, memory usage, etc, etc.. I don't think we need
per-tuple timing information. I certainly wouldn't want to try and
collect all of this through shared memory or our existing stats
collector.

Thanks,

Stephen

On 01/13/2014 09:06 PM, Stephen Frost wrote:
> My thought, at least, was to always grab the planning time and then
> provide it for explain and/or explain analyze, and then for re-plan
> cases, indicate if a cached plan was returned, if a replan happened, and
> if a replan happened, what the old plan time and the new plan time was.

I like this solution due it is correctness and that all information is
included. But I also think my original path was fine in how it in its
simplicity solved the problem without adding any overhead in the
non-EXPLAIN case. Either solution would be fine by me. If the consensus
is that we want to always measure it I will look at implementing that
instead.

--
Andreas Karlsson

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
>> planning cycle, explain or no? I was thinking more of just putting the
>> timing calls into explain.c.

> Currently the patch includes changes to prepare.c which is what seems
> odd to me. I think it'd be fine to say, hey, I can't give you the
> planning time in this EXPLAIN ANALYZE because I just used a cached
> plan and did not re-plan. But saying, hey, the planning time is
> $TINYVALUE, when what we really mean is that looking up the
> previously-cached plan took only that long, seems actively misleading
> to me.

Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
I don't think users would be surprised to see a report of minimal planning
time for that. In fact, it might be a good thing, as it would make it
easier to tell the difference between whether you were seeing a generic
plan or a custom plan for the prepared statement.

regards, tom lane

On Mon, Jan 13, 2014 at 3:23 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>>> Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
>>> planning cycle, explain or no? I was thinking more of just putting the
>>> timing calls into explain.c.
>
>> Currently the patch includes changes to prepare.c which is what seems
>> odd to me. I think it'd be fine to say, hey, I can't give you the
>> planning time in this EXPLAIN ANALYZE because I just used a cached
>> plan and did not re-plan. But saying, hey, the planning time is
>> $TINYVALUE, when what we really mean is that looking up the
>> previously-cached plan took only that long, seems actively misleading
>> to me.
>
> Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
> I don't think users would be surprised to see a report of minimal planning
> time for that. In fact, it might be a good thing, as it would make it
> easier to tell the difference between whether you were seeing a generic
> plan or a custom plan for the prepared statement.

It would also make it easier to be wrong. If you want to display that
information explicitly, fine. But asking the user to use the elapsed
time to guess whether or not we really planned anything is just going
to confuse people who don't have enough experience with the system to
know what the boundary is between the largest time that could be a
cache lookup and the smallest time that could be real planning
activity. And that means virtually everyone, me included.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Mon, Jan 13, 2014 at 3:23 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
>> I don't think users would be surprised to see a report of minimal planning
>> time for that. In fact, it might be a good thing, as it would make it
>> easier to tell the difference between whether you were seeing a generic
>> plan or a custom plan for the prepared statement.

> It would also make it easier to be wrong. If you want to display that
> information explicitly, fine. But asking the user to use the elapsed
> time to guess whether or not we really planned anything is just going
> to confuse people who don't have enough experience with the system to
> know what the boundary is between the largest time that could be a
> cache lookup and the smallest time that could be real planning
> activity. And that means virtually everyone, me included.

If you're saying that you'd like EXPLAIN to explicitly mention whether
the plan was cached or custom, I don't have any great complaint about
that. I'm just not seeing how you arrive at the conclusion that we
mustn't report the amount of time EXPLAIN spent to get the plan.
If we do what you're proposing we'll just have a different set of confused
users, who will be wondering how EXPLAIN could have managed to spend
100 msec planning something when the EXPLAIN only took 10 msec in toto
according to psql.

regards, tom lane

On Mon, Jan 13, 2014 at 3:40 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> On Mon, Jan 13, 2014 at 3:23 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>>> Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
>>> I don't think users would be surprised to see a report of minimal planning
>>> time for that. In fact, it might be a good thing, as it would make it
>>> easier to tell the difference between whether you were seeing a generic
>>> plan or a custom plan for the prepared statement.
>
>> It would also make it easier to be wrong. If you want to display that
>> information explicitly, fine. But asking the user to use the elapsed
>> time to guess whether or not we really planned anything is just going
>> to confuse people who don't have enough experience with the system to
>> know what the boundary is between the largest time that could be a
>> cache lookup and the smallest time that could be real planning
>> activity. And that means virtually everyone, me included.
>
> If you're saying that you'd like EXPLAIN to explicitly mention whether
> the plan was cached or custom, I don't have any great complaint about
> that. I'm just not seeing how you arrive at the conclusion that we
> mustn't report the amount of time EXPLAIN spent to get the plan.
> If we do what you're proposing we'll just have a different set of confused
> users, who will be wondering how EXPLAIN could have managed to spend
> 100 msec planning something when the EXPLAIN only took 10 msec in toto
> according to psql.

What I'm saying is that if EXPLAIN reports something that's labelled
"Planning Time", it should *be* the planning time, and not anything
else. When we retrieve a plan from cache, it would be sensible not to
report the planning time at all, and IMHO it would also be sensible to
report the time it actually took to plan whenever we originally did
it. But reporting a value that is not the planning time and calling
it the planning time does not seem like a good idea to me.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 01/13/2014 09:48 PM, Robert Haas wrote:
> What I'm saying is that if EXPLAIN reports something that's labelled
> "Planning Time", it should *be* the planning time, and not anything
> else. When we retrieve a plan from cache, it would be sensible not to
> report the planning time at all, and IMHO it would also be sensible to
> report the time it actually took to plan whenever we originally did
> it. But reporting a value that is not the planning time and calling
> it the planning time does not seem like a good idea to me.

Here is a patch which only prints when "Planning time" when a prepared
statment actually planned a query. I do not really like how I check for
if it was replanned, but I tried to avoid making changes in plancache.c.

Does this idea look ok?

--
Andreas Karlsson

On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Greg Stark <stark(at)mit(dot)edu> writes:
>> On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>>> In short then, I think we should just add this to EXPLAIN and be done.
>>> -1 for sticking the info into PlannedStmt or anything like that.
>
>> I'm confused. I thought I was arguing to support your suggestion that
>> the initial planning store the time in the cached plan and explain
>> should output the time the original planning took.
>
> Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
> planning cycle, explain or no? I was thinking more of just putting the
> timing calls into explain.c.

The problem is that you really can't do it that way.
ExplainOneQuery() is a good place to add the timing calls in general,
but ExplainExecuteQuery() in prepare.c never calls it; it does
GetCachedPlan(), which ultimately calls pg_plan_query() after about
four levels of indirection, and then passes the resulting plan
directly to ExplainOnePlan(). So if you only add timing calls to
explain.c, you can't handle anything that goes through
ExplainExecuteQuery(), which is confusingly in prepare.c rather than
explain.c.

One reasonably principled solution is to just give up on showing the
plan time for prepared queries altogether. If we don't want to adopt
that approach, then I think the right way to do this is to add a "bool
timing" argument to pg_plan_query(). When set, pg_plan_query()
measures the time before and after calling planner() and stores it in
the PlannedStmt. It could alternatively return it via an out
parameter, but that's not very convenient for prepare.c, which is
planning a *list* of queries and therefore presumably needs planning
time for each one.

I'm not bent on this design; I just don't see another way to do this
that has any conceptual integrity. Having the normal path measure the
time required to call pg_plan_query() and the prepared path measure
the time required to call GetCachedPlan() which may or may not
eventually call pg_plan_query() one or more times doesn't seem like a
good design, particularly if it's motivated solely by a desire to
minimize the code footprint of what's never going to be a very large
patch. The most recent version of the patch tries to finesse this
issue by determining whether GetCachedPlan() actually did anything; I
think the way it does that is likely an abstraction violation that we
don't want to countenance. But even if we're OK with that, it still
munges the planning times of multiple queries into a single number,
while the normal case separates them. It just seems like we're going
to a lot of trouble here to avoid the obvious design, and I'm not sure
why.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
>> planning cycle, explain or no? I was thinking more of just putting the
>> timing calls into explain.c.

> The problem is that you really can't do it that way.
> ExplainOneQuery() is a good place to add the timing calls in general,
> but ExplainExecuteQuery() in prepare.c never calls it; it does
> GetCachedPlan(), which ultimately calls pg_plan_query() after about
> four levels of indirection, and then passes the resulting plan
> directly to ExplainOnePlan(). So if you only add timing calls to
> explain.c, you can't handle anything that goes through
> ExplainExecuteQuery(), which is confusingly in prepare.c rather than
> explain.c.

Yeah, the factoring between explain.c and prepare.c has never been very
nice. I'm not sure what would be a cleaner design offhand, but I suspect
there is one.

> One reasonably principled solution is to just give up on showing the
> plan time for prepared queries altogether.

That would work for me, especially given the lack of clarity about what
ought to be measured in that case.

> If we don't want to adopt
> that approach, then I think the right way to do this is to add a "bool
> timing" argument to pg_plan_query(). When set, pg_plan_query()
> measures the time before and after calling planner() and stores it in
> the PlannedStmt.

I don't find that to be exactly a "low footprint" change; it's dumping
an EXPLAIN concern all over a public API *and* a public data structure.
It might be roughly comparable in terms of number of lines in the patch,
but in terms of modularity and abstraction it's not comparable in the
least.

I'm for doing the measurement in ExplainOneQuery() and not printing
anything in code paths that don't go through there.

regards, tom lane

On 01/28/2014 09:39 PM, Tom Lane wrote:
> I'm for doing the measurement in ExplainOneQuery() and not printing
> anything in code paths that don't go through there.

Reading the discussion here and realizing that my last patch was wrong I
am now in agreement with this. I have attached a patch which no longer
tries to measure planning time for prepared statements.

/Andreas

On Wed, Jan 29, 2014 at 2:21 PM, Andreas Karlsson <andreas(at)proxel(dot)se> wrote:
> On 01/28/2014 09:39 PM, Tom Lane wrote:
>>
>> I'm for doing the measurement in ExplainOneQuery() and not printing
>> anything in code paths that don't go through there.
>
> Reading the discussion here and realizing that my last patch was wrong I am
> now in agreement with this. I have attached a patch which no longer tries to
> measure planning time for prepared statements.

Cool. I propose adding one parameter rather than two to
ExplainOnePlan() and making it of type instr_time * rather than
passing an instr_time and a bool. If you don't want to include the
planning time, pass NULL; if you do, pass a pointer to the instr_time
you want to print. I think that would come out slightly neater than
what you have here.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 01/29/2014 09:01 PM, Robert Haas wrote:
> Cool. I propose adding one parameter rather than two to
> ExplainOnePlan() and making it of type instr_time * rather than
> passing an instr_time and a bool. If you don't want to include the
> planning time, pass NULL; if you do, pass a pointer to the instr_time
> you want to print. I think that would come out slightly neater than
> what you have here.

Excellent suggestion, thanks! New patch attached.

/Andreas

On Wed, Jan 29, 2014 at 3:13 PM, Andreas Karlsson <andreas(at)proxel(dot)se> wrote:
> On 01/29/2014 09:01 PM, Robert Haas wrote:
>> Cool. I propose adding one parameter rather than two to
>> ExplainOnePlan() and making it of type instr_time * rather than
>> passing an instr_time and a bool. If you don't want to include the
>> planning time, pass NULL; if you do, pass a pointer to the instr_time
>> you want to print. I think that would come out slightly neater than
>> what you have here.
>
> Excellent suggestion, thanks! New patch attached.

Committed with minor doc changes.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 01/29/2014 10:10 PM, Robert Haas wrote:
> Committed with minor doc changes.

Thanks!

/Andreas