Re: Display of buffers for planning time show nothing for second run

[Julien Rouhaud]

Hi,

On Tue, Apr 14, 2020 at 10:18 AM Pavel Stehule <pavel.steh...@gmail.com> wrote:
>
> Hi
>
> I am testing some features from Postgres 13, and I am not sure if I  
> understand well to behave of EXPLAIN(ANALYZE, BUFFERS)
>
> When I run following statement first time in session I get
>
> postgres=# EXPLAIN (BUFFERS, ANALYZE) SELECT * FROM obce WHERE okres_id = 
> 'CZ0201';
> ┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
> │                                                          QUERY PLAN         
>                                                  │
> ╞══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
> │ Index Scan using obce_okres_id_idx on obce  (cost=0.28..14.49 rows=114 
> width=41) (actual time=0.072..0.168 rows=114 loops=1) │
> │   Index Cond: ((okres_id)::text = 'CZ0201'::text)                           
>                                                  │
> │   Buffers: shared hit=4                                                     
>                                                  │
> │ Planning Time: 0.539 ms                                                     
>                                                  │
> │   Buffers: shared hit=13                                                    
>                                                  │
> │ Execution Time: 0.287 ms                                                    
>                                                  │
> └──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
> (6 rows)
>
> And I see share hit 13 in planning time.
>
> For second run I get
>
> postgres=# EXPLAIN (BUFFERS, ANALYZE) SELECT * FROM obce WHERE okres_id = 
> 'CZ0201';
> ┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
> │                                                          QUERY PLAN         
>                                                  │
> ╞══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
> │ Index Scan using obce_okres_id_idx on obce  (cost=0.28..14.49 rows=114 
> width=41) (actual time=0.044..0.101 rows=114 loops=1) │
> │   Index Cond: ((okres_id)::text = 'CZ0201'::text)                           
>                                                  │
> │   Buffers: shared hit=4                                                     
>                                                  │
> │ Planning Time: 0.159 ms                                                     
>                                                  │
> │ Execution Time: 0.155 ms                                                    
>                                                  │
> └──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
> (5 rows)
>
> Now, there is not any touch in planning time. Does it mean so this all these 
> data are cached somewhere in session memory?

The planning time is definitely shorter the 2nd time.  And yes, what
you see are all the catcache accesses that are initially performed on
a fresh new backend.