BUG #10404: auto_explain for EXPLAIN ANLYZE. - Mailing list pgsql-bugs

The following bug has been logged on the website:

Bug reference:      10404
Logged by:          Tomonari Katsumata
Email address:      katsumata.tomonari@po.ntts.co.jp
PostgreSQL version: 9.3.4
Operating system:   CentOS 6.4 x86_64
Description:

Hi,

I'm testing auto_explain.
And I noticed that auto_explain has a strange behavior.

The settings for auto_explain are like below.

-------------------------------
testdb=# select name, setting from pg_settings where name like
'%auto_explain%';
                name                | setting
------------------------------------+---------
 auto_explain.log_analyze           | on
 auto_explain.log_buffers           | on
 auto_explain.log_format            | text
 auto_explain.log_min_duration      | 0
 auto_explain.log_nested_statements | off
 auto_explain.log_timing            | on
 auto_explain.log_verbose           | on
(7 rows)
-------------------------------

And then, I tested five cases.

-------------------------------
a.EXPLAIN ONLY
b.EXPLAIN ANALYZE
c.EXPLAIN ANALYZE BUFFERS
d.EXPLAIN ANALYZE BUFFERS-OFF
e.EXPLAIN ANALYZE TIMING
f.EXPLAIN ANALYZE TIMING-OFF
-------------------------------

The results of a to e are good, but the result of f is not good.
I thought "actual time" would be omitted from the result of EXPLAIN,
but it is there.
Is this an intentional thing? or bug?


The test results are below.

===============
a.EXPLAIN ONLY
===============
testdb=# explain select * from hoge where i = 3;
                      QUERY PLAN
------------------------------------------------------
 Seq Scan on hoge  (cost=0.00..40.00 rows=12 width=4)
   Filter: (i = 3)
(2 rows)

****************************************************************
LOG:  duration: 0.000 ms  plan:
    Query Text: explain select * from hoge where i = 3;
    Seq Scan on public.hoge  (cost=0.00..40.00 rows=12 width=4)
      Output: i
      Filter: (hoge.i = 3)
****************************************************************


=================
b.EXPLAIN ANALYZE
=================
testdb=# explain analyze select * from hoge where i = 3;
                                            QUERY PLAN

--------------------------------------------------------------------------------------------------
 Seq Scan on hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=23.484..23.484 rows=0 loops=1)
   Filter: (i = 3)
   Rows Removed by Filter: 1
 Total runtime: 25.275 ms
(4 rows)

****************************************************************
LOG:  duration: 23.488 ms  plan:
    Query Text: explain analyze select * from hoge where i = 3;
    Seq Scan on public.hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=23.484..23.484 rows=0 loops=1)
      Output: i
      Filter: (hoge.i = 3)
      Rows Removed by Filter: 1
      Buffers: shared hit=1
****************************************************************


=========================
c.EXPLAIN ANALYZE BUFFERS
=========================
testdb=# explain (analyze, buffers) select * from hoge where i = 3;
                                           QUERY PLAN

------------------------------------------------------------------------------------------------
 Seq Scan on hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.152..0.152 rows=0 loops=1)
   Filter: (i = 3)
   Rows Removed by Filter: 1
   Buffers: shared hit=1
 Total runtime: 0.326 ms
(5 rows)

****************************************************************
LOG:  duration: 0.155 ms  plan:
    Query Text: explain (analyze, buffers) select * from hoge where i = 3;
    Seq Scan on public.hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.152..0.152 rows=0 loops=1)
      Output: i
      Filter: (hoge.i = 3)
      Rows Removed by Filter: 1
      Buffers: shared hit=1
****************************************************************


=============================
d.EXPLAIN ANALYZE BUFFERS-OFF
=============================
testdb=# explain (analyze, buffers off) select * from hoge where i = 3;
                                           QUERY PLAN

------------------------------------------------------------------------------------------------
 Seq Scan on hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.024..0.024 rows=0 loops=1)
   Filter: (i = 3)
   Rows Removed by Filter: 1
 Total runtime: 1.407 ms
(4 rows)

****************************************************************
LOG:  duration: 0.026 ms  plan:
    Query Text: explain (analyze, buffers off) select * from hoge where i = 3;
    Seq Scan on public.hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.024..0.024 rows=0 loops=1)
      Output: i
      Filter: (hoge.i = 3)
      Rows Removed by Filter: 1
      Buffers: shared hit=1
****************************************************************


========================
e.EXPLAIN ANALYZE TIMING
========================
testdb=# explain (analyze, timing) select * from hoge where i = 3;
                                           QUERY PLAN

------------------------------------------------------------------------------------------------
 Seq Scan on hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.024..0.024 rows=0 loops=1)
   Filter: (i = 3)
   Rows Removed by Filter: 1
 Total runtime: 0.207 ms
(4 rows)

****************************************************************
LOG:  duration: 0.026 ms  plan:
    Query Text: explain (analyze, timing) select * from hoge where i = 3;
    Seq Scan on public.hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.024..0.024 rows=0 loops=1)
      Output: i
      Filter: (hoge.i = 3)
      Rows Removed by Filter: 1
      Buffers: shared hit=1
****************************************************************


============================
f.EXPLAIN ANALYZE TIMING-OFF
============================
testdb=# explain (analyze, timing off) select * from hoge where i = 3;
                                           QUERY PLAN

------------------------------------------------------------------------------------------------
 Seq Scan on hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.023..0.023 rows=0 loops=1)
   Filter: (i = 3)
   Rows Removed by Filter: 1
 Total runtime: 0.194 ms
(4 rows)

****************************************************************
LOG:  duration: 0.026 ms  plan:
    Query Text: explain (analyze, timing off) select * from hoge where i = 3;
    Seq Scan on public.hoge  (cost=0.00..40.00 rows=12 width=4) (actual
time=0.023..0.023 rows=0 loops=1)
      Output: i
      Filter: (hoge.i = 3)
      Rows Removed by Filter: 1
      Buffers: shared hit=1
****************************************************************


regards,
----------------------
Tomonari Katsumata