BUG #10404: auto_explain for EXPLAIN ANLYZE.

The following bug has been logged on the website:

Bug reference: 10404
Logged by: Tomonari Katsumata
Email address: katsumata(dot)tomonari(at)po(dot)ntts(dot)co(dot)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