Re: pgsql: Include planning time in EXPLAIN ANALYZE output.

Include planning time in EXPLAIN ANALYZE output.

This doesn't work for prepared queries, but it's not too easy to get
the information in that case and there's some debate as to exactly
what the right thing to measure is, so just do this for now.

Andreas Karlsson, with slight doc changes by me.

Branch
------
master

Details
-------
http://git.postgresql.org/pg/commitdiff/9347baa5bbc70368f2f01438bbb8116863dac1ec

Modified Files
--------------
doc/src/sgml/perform.sgml | 27 +++++++++++++++++++++++++++
doc/src/sgml/ref/explain.sgml | 17 ++++++++++++-----
src/backend/commands/explain.c | 24 +++++++++++++++++++++---
src/backend/commands/prepare.c | 2 +-
src/include/commands/explain.h | 4 ++--
5 files changed, 63 insertions(+), 11 deletions(-)

On Wed, Jan 29, 2014 at 1:10 PM, Robert Haas <rhaas(at)postgresql(dot)org> wrote:
> Include planning time in EXPLAIN ANALYZE output.

Isn't it perhaps a little confusing that "Planning time" may well
exceed "Total runtime"? I'm aware that we aren't super clear on the
accounting here generally, as with pg_stat_statements, which doesn't
include planning time in total_time, while we aren't even explicit
about that in the documentation. But even still, seeing the two
side-by-side, with planning time > total runtime did give me pause.

--
Peter Geoghegan

Peter Geoghegan <pg(at)heroku(dot)com> writes:
> On Wed, Jan 29, 2014 at 1:10 PM, Robert Haas <rhaas(at)postgresql(dot)org> wrote:
>> Include planning time in EXPLAIN ANALYZE output.

> Isn't it perhaps a little confusing that "Planning time" may well
> exceed "Total runtime"?

Perhaps s/Total runtime/Execution time/ ?

regards, tom lane

On Sun, Feb 2, 2014 at 8:13 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Perhaps s/Total runtime/Execution time/ ?

+1

--
Peter Geoghegan

On 03/02/14 09:44, Peter Geoghegan wrote:
> On Sun, Feb 2, 2014 at 8:13 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Perhaps s/Total runtime/Execution time/ ?
> +1
>
>
If the planning was ever made into a parallel process, then 'elapsed
time' would be less than the 'processor time'. So what does 'Execution
time' mean?

Can I assume:
'Total runtime' is 'elapsed time'
and
'Execution time' is 'processor time'.

In a parallel implementation, one would likely want both.

Possible this is not an issue now, and I'm thinking to far ahead!

Cheers,
Gavin

Gavin Flower <GavinFlower(at)archidevsys(dot)co(dot)nz> writes:
> Can I assume:
> 'Total runtime' is 'elapsed time'
> and
> 'Execution time' is 'processor time'.

No. It's going to be elapsed time, either way.

> In a parallel implementation, one would likely want both.

When and if we have that, we can argue about what to measure.

regards, tom lane

On Sun, Feb 2, 2014 at 11:13 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Peter Geoghegan <pg(at)heroku(dot)com> writes:
>> On Wed, Jan 29, 2014 at 1:10 PM, Robert Haas <rhaas(at)postgresql(dot)org> wrote:
>>> Include planning time in EXPLAIN ANALYZE output.
>
>> Isn't it perhaps a little confusing that "Planning time" may well
>> exceed "Total runtime"?
>
> Perhaps s/Total runtime/Execution time/ ?

I'm not really feeling a compelling need to change that. We've been
displaying total runtime - described exactly that way - for many
releases and it's surely is confusing to the novice that the time
reported can be much less than the time reported by psql's \timing
option, usually because of planning time. But adding the planning
time to the output seems to me to make that better, not worse. If the
user can't figure out that runtime != planning time, I'm not sure
they'll be able to figure out execution time != planning time, either.

One of the reasons it's called "Total runtime", or so I've always
assumed, is because it's more inclusive than the time shown for the
root node of the plan tree. Specifically, it includes the time
required to fire triggers.

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

On Mon, Feb 3, 2014 at 4:15 AM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
> I'm not really feeling a compelling need to change that. We've been
> displaying total runtime - described exactly that way - for many
> releases and it's surely is confusing to the novice that the time
> reported can be much less than the time reported by psql's \timing
> option, usually because of planning time.

I think that has a lot more to do with network roundtrip time and
protocol/serialization overhead.

--
Peter Geoghegan

Peter Geoghegan <pg(at)heroku(dot)com> writes:
> On Mon, Feb 3, 2014 at 4:15 AM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>> I'm not really feeling a compelling need to change that. We've been
>> displaying total runtime - described exactly that way - for many
>> releases and it's surely is confusing to the novice that the time
>> reported can be much less than the time reported by psql's \timing
>> option, usually because of planning time.

> I think that has a lot more to do with network roundtrip time and
> protocol/serialization overhead.

The problem I'm having with the way it stands now is that one would
reasonably expect that "Total time" is the total of all times counted
by EXPLAIN, including main plan execution time, trigger firing time,
and now planning time. Since it is not, any longer, a total, I think
renaming it would be a good idea. I'm not wedded to "execution time"
in particular, but I don't like "total".

regards, tom lane

* Tom Lane (tgl(at)sss(dot)pgh(dot)pa(dot)us) wrote:
> The problem I'm having with the way it stands now is that one would
> reasonably expect that "Total time" is the total of all times counted
> by EXPLAIN, including main plan execution time, trigger firing time,
> and now planning time. Since it is not, any longer, a total, I think
> renaming it would be a good idea. I'm not wedded to "execution time"
> in particular, but I don't like "total".

Agreed.

Thanks,

Stephen

On Mon, Feb 3, 2014 at 07:13:46PM -0500, Stephen Frost wrote:
> * Tom Lane (tgl(at)sss(dot)pgh(dot)pa(dot)us) wrote:
> > The problem I'm having with the way it stands now is that one would
> > reasonably expect that "Total time" is the total of all times counted
> > by EXPLAIN, including main plan execution time, trigger firing time,
> > and now planning time. Since it is not, any longer, a total, I think
> > renaming it would be a good idea. I'm not wedded to "execution time"
> > in particular, but I don't like "total".
>
> Agreed.

Where are we on this? I still see:

test=> EXPLAIN ANALYZE SELECT 1;
QUERY PLAN
------------------------------------------------------------------------------------
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.001..0.001 rows=1 loops=1)
Planning time: 0.009 ms
--> Total runtime: 0.009 ms
(3 rows)

--
Bruce Momjian <bruce(at)momjian(dot)us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ Everyone has their own god. +

Bruce Momjian <bruce(at)momjian(dot)us> writes:
> Where are we on this? I still see:

> test=> EXPLAIN ANALYZE SELECT 1;
> QUERY PLAN
> ------------------------------------------------------------------------------------
> Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.001..0.001 rows=1 loops=1)
> Planning time: 0.009 ms
> --> Total runtime: 0.009 ms
> (3 rows)

There seemed to be a clear majority of votes in favor of changing it to
say "Execution time". Robert was arguing for no change, but I don't think
that's tenable in view of the fact that the addition of the "Planning
time" line is already a change, and one that makes the old wording
confusing.

I'll go change it.

regards, tom lane

I found a bit confusing, when planning time is greater total time, so
+1 for execution time.

On Thu, Apr 17, 2014 at 3:35 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Bruce Momjian <bruce(at)momjian(dot)us> writes:
>> Where are we on this? I still see:
>
>> test=> EXPLAIN ANALYZE SELECT 1;
>> QUERY PLAN
>> ------------------------------------------------------------------------------------
>> Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.001..0.001 rows=1 loops=1)
>> Planning time: 0.009 ms
>> --> Total runtime: 0.009 ms
>> (3 rows)
>
> There seemed to be a clear majority of votes in favor of changing it to
> say "Execution time". Robert was arguing for no change, but I don't think
> that's tenable in view of the fact that the addition of the "Planning
> time" line is already a change, and one that makes the old wording
> confusing.
>
> I'll go change it.
>
> regards, tom lane
>
>
> --
> Sent via pgsql-hackers mailing list (pgsql-hackers(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-hackers

On 04/17/2014 01:35 AM, Tom Lane wrote:
> I'll go change it.

Thanks for fixing this. The new name "Execution time" is much clearer.

--
Andreas Karlsson