February 1st, 2014 by depesz | Tags: , , , , | Comments Off on Waiting for 9.4 – Include planning time in EXPLAIN ANALYZE output.
Did it help? If yes - maybe you can help me?

On 29th of January, Robert Haas committed patch:

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.

Planning is the part of query processing that happens before PostgreSQL will even touch data. It is actually what creates the plans that EXPLAIN ANALYZE shows.

For trivial queries – it's fast. For more complicated queries – it can be longer.

Now, with this new patch from Andreas, we can actually see the planning time.

Let's consider simple example:

$ explain analyze select relkind, count(*) from pg_class group by 1 order by 2 desc;
                                                    QUERY PLAN
-------------------------------------------------------------------------------------------------------------------
 Sort  (cost=14.49..14.50 rows=4 width=1) (actual time=0.267..0.267 rows=4 loops=1)
   Sort Key: (count(*))
   Sort Method: quicksort  Memory: 25kB
   ->  HashAggregate  (cost=14.41..14.45 rows=4 width=1) (actual time=0.258..0.259 rows=4 loops=1)
         ->  Seq Scan on pg_class  (cost=0.00..12.94 rows=294 width=1) (actual time=0.008..0.064 rows=297 loops=1)
 Total runtime: 0.320 ms
(6 rows)

And now, the same query on another server, with pg 9.4:

$ explain analyze select relkind, count(*) from pg_class group by 1 order by 2 desc;
                                                    QUERY PLAN                                                     
-------------------------------------------------------------------------------------------------------------------
 Sort  (cost=14.04..14.05 rows=4 width=1) (actual time=0.272..0.272 rows=5 loops=1)
   Sort Key: (count(*))
   Sort Method: quicksort  Memory: 25kB
   ->  HashAggregate  (cost=13.97..14.01 rows=4 width=1) (actual time=0.263..0.264 rows=5 loops=1)
         Group Key: relkind
         ->  Seq Scan on pg_class  (cost=0.00..12.31 rows=331 width=1) (actual time=0.007..0.062 rows=322 loops=1)
 Planning time: 0.100 ms
 Total runtime: 0.323 ms
(8 rows)

Now we see that for this particular query, 0.1ms is used to plan it. Unfortunately, I don't have any real databases on 9.4, so I can't show you longer times, but generally – the more joins/subselects – the longer it will take to plan the query.

This effect is actually the reason we have GEQO.

All in all – it's really nice to have – especially if you have some multi-table join queries. Thanks Andreas and Robert.

Sorry, comments for this post are disabled.