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