Thread: BUG #15387: explain analyze timing on bug?

BUG #15387: explain analyze timing on bug?

From
PG Bug reporting form
Date:
The following bug has been logged on the website:

Bug reference:      15387
Logged by:          Zhou Digoal
Email address:      digoal@126.com
PostgreSQL version: 11beta3
Operating system:   CentOS 7.x x64
Description:

when turn on timing for explain analyze:

```
postgres=# explain (analyze on,verbose on,timing on,costs on,buffers
on,summary on) select count(*) from item1;
                                                       QUERY PLAN
                                           

------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=254.75..254.75 rows=1 width=8) (actual time=26.938..26.938
rows=1 loops=1)
   Output: count(*)
   Buffers: shared hit=1334
   ->  Seq Scan on public.item1  (cost=0.00..38.00 rows=100000 width=0)
(actual time=0.011..15.674 rows=100000 loops=1)
         Output: i_id, i_im_id, i_name, i_price, i_data
         Buffers: shared hit=1334
 Planning Time: 0.065 ms
 Execution Time: 26.967 ms
(8 rows)

Time: 27.291 ms
```

when turn off timing:

```
postgres=# explain (analyze on,verbose on,timing off,costs on,buffers
on,summary on) select count(*) from item1;
                                             QUERY PLAN
                        
-----------------------------------------------------------------------------------------------------
 Aggregate  (cost=254.75..254.75 rows=1 width=8) (actual rows=1 loops=1)
   Output: count(*)
   Buffers: shared hit=1334
   ->  Seq Scan on public.item1  (cost=0.00..38.00 rows=100000 width=0)
(actual rows=100000 loops=1)
         Output: i_id, i_im_id, i_name, i_price, i_data
         Buffers: shared hit=1334
 Planning Time: 0.062 ms
 Execution Time: 11.050 ms
(8 rows)

Time: 11.394 ms
```

why turn timing on increment about 26ms ?


Re: BUG #15387: explain analyze timing on bug?

From
Tom Lane
Date:
=?utf-8?q?PG_Bug_reporting_form?= <noreply@postgresql.org> writes:
> why turn timing on increment about 26ms ?

That's the cost of reading the system clock 200000 times (once per
entry and exit to the SeqScan node).  So apparently that takes about
130ns on your hardware, which is not great, but not awful either.

See

https://www.postgresql.org/message-id/flat/31856.1400021891%40sss.pgh.pa.us

for some more context.

            regards, tom lane