Re: Reporting planning time with EXPLAIN

On Wed, Dec 28, 2016 at 10:55 PM, Stephen Frost <sfrost(at)snowman(dot)net> wrote:
> Tom,
>
> * Tom Lane (tgl(at)sss(dot)pgh(dot)pa(dot)us) wrote:
>> Stephen Frost <sfrost(at)snowman(dot)net> writes:
>> > * Tom Lane (tgl(at)sss(dot)pgh(dot)pa(dot)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