Re: [HACKERS] Reporting planning time with EXPLAIN - Mailing list pgsql-hackers

Here are patches for follwing
1. pg_explain_plan_time_v3 adds SUMMARY option which behaves as:
SUMMARY when ON prints planning time. With ANALYZE ON, it also prints
execution time. When user explicitly uses SUMMARY OFF, it does not
print planning and execution time (even when ANALYZE is ON). By
default SUMMARY is ON when ANALYZE is ON, otherwise SUMMARY defaults
to OFF. Attached explain_summary_examples.out.txt shows examples.

2. explain_exec_timing adds support to print planning time in EXPLAIN
EXECUTE output with SUMMARY option. In this case, planning time
includes time required to fetch the plan from cache and plan the query
if necessary (i.e. after invalidation or the first time it's
executed.) E.g.
prepare somestmt as select count(*) from t1 where a > 100;
PREPARE
postgres=# explain (summary on) execute somestmt;
                        QUERY PLAN
-----------------------------------------------------------
 Aggregate  (cost=40.13..40.14 rows=1 width=8)
   ->  Seq Scan on t1  (cost=0.00..38.25 rows=753 width=0)
         Filter: (a > 100)
 Planning time: 0.245 ms
(4 rows)

postgres=# explain (summary on) execute somestmt;
                        QUERY PLAN
-----------------------------------------------------------
 Aggregate  (cost=40.13..40.14 rows=1 width=8)
   ->  Seq Scan on t1  (cost=0.00..38.25 rows=753 width=0)
         Filter: (a > 100)
 Planning time: 0.012 ms
(4 rows)

Notice the difference in planning time.
explain_summary_examples.out.txt has examples.


On Thu, Dec 29, 2016 at 10:26 AM, Ashutosh Bapat
<ashutosh.bapat@enterprisedb.com> wrote:
> On Wed, Dec 28, 2016 at 10:55 PM, Stephen Frost <sfrost@snowman.net> wrote:
>> Tom,
>>
>> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>>> Stephen Frost <sfrost@snowman.net> writes:
>>> > * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>>> >> I think it's an awful choice of name; it has nothing to do with either
>>> >> the functionality or the printed name of the field.
>>>
>>> > As an example, we might some day wish to include a summary of buffer
>>> > information at the bottom too when 'buffers' is used.  The proposed
>>> > 'summary' option would cover that nicely, but 'timing' wouldn't.  That's
>>> > actually why I was thinking summary might be a good option to have.
>>>
>>> What, would this option then turn off the total-time displays by default?
>>
>> To retain our current mixed behavior with explain vs. explain-analyze,
>> we'd have to say it defaults to off for explain and on with analyze.  I
>> don't particularly like that, and would rather we just default it to on,
>> but that would mean adjusting the regression tests.
>>
>>> I do not see that being a reasonable thing to do.  Basically, you're
>>> taking what seems like a very general-purpose option name and nailing
>>> it down to mean "print planning time".  You aren't going to be able
>>> to change that later.
>>
>> No, that's not what I was suggesting to do and I disagree that we
>> couldn't ever change it later.  If we want it to mean "print planning
>> time" and only ever that then I agree that calling it "summary" isn't a
>> good option.
>
> No, that wasn't my intention either. I have clarified it in my mail.
>
>>
>>> > No, but consider how the docs for the current 'timing' option would have
>>> > to be rewritten.
>>>
>>> Well, sure, they'd have to be rewritten, but I think this definition
>>> would actually be more orthogonal.
>>
>> This definition would have two completely different meanings- one for
>> when analyze is used, and one for when it isn't.
>>
>>> > We would also have to say something like "the default when not using
>>> > 'analyze' is off, but with 'analyze' the default is on" which seems
>>> > pretty grotty to me.
>>>
>>> But the default for TIMING already does depend on ANALYZE.
>>
>> I would argue that timing can only actually be used with analyze today,
>> which makes sense when you consider that timing is about enabling or
>> disabling per-node timing information.  Redefining it to mean something
>> else isn't particularly different from redefining 'summary' later to
>> mean something else.
>>
>>> > Then again, from a *user's* perspective, it should just be included by
>>> > default.
>>>
>>> Actually, the reason it hasn't gotten included is probably that the
>>> use-case for it is very small.  If you just do psql \timing on an
>>> EXPLAIN, you get something close enough to the planning time.  I don't
>>> mind adding this as an option, but claiming that it's so essential
>>> that it should be there by default is silly.  People would have asked
>>> for it years ago if it were all that important.
>>
>> I don't buy this argument.  Planning time is (hopefully, anyway...) a
>> rather small amount of time which means that the actual results from
>> \timing (or, worse, the timing info from other tools like pgAdmin) is
>> quite far off.  On a local instance with a simple plan, you can get an
>> order-of-magnitude difference between psql's \timing output and the
>> actual planning time, throw in a few or even 10s of ms of network
>> latency and you might as well forget about trying to figure out what
>> the planning time actually is.
>
> +1. On my machine
>
> regression=# \timing
> Timing is on.
> regression=# explain select * from pg_class c, pg_type t where
> c.reltype = t.oid;
>
> [...] clipped plan
>
> Time: 1.202 ms
> regression=# \timing
> Timing is off.
> regression=# explain analyze select * from pg_class c, pg_type t where
> c.reltype = t.oid;
>
> [...] clipped plan
>
>  Planning time: 0.332 ms
>  Execution time: 1.670 ms
> (8 rows)
>
> \timing output is way off than the actual planning time.
>
> Take another example
>
> regression=# explain analyze select * from pg_class c, pg_type t,
> pg_inherits i where c.reltype = t.oid and i.inhparent = c.oid;
>                                                             QUERY PLAN
> [ ... ] clipped plan
>
>  Planning time: 0.592 ms
>  Execution time: 2.294 ms
> (13 rows)
>
> regression=# \timing
> Timing is on.
> regression=# explain select * from pg_class c, pg_type t, pg_inherits
> i where c.reltype = t.oid and i.inhparent = c.oid;
> [...] clipped plan
>
> Time: 1.831 ms
>
> The planning time has almost doubled, but what \timing reported has
> only grown by approximately 50%.
>
> --
> Best Wishes,
> Ashutosh Bapat
> EnterpriseDB Corporation
> The Postgres Database Company



-- 
Best Wishes,
Ashutosh Bapat
EnterpriseDB Corporation
The Postgres Database Company

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers