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

út 14. 4. 2020 v 11:35 odesílatel Julien Rouhaud <rjuju123(at)gmail(dot)com>
napsal:

> On Tue, Apr 14, 2020 at 11:25 AM Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com>
> wrote:
> >
> > út 14. 4. 2020 v 10:40 odesílatel Amit Langote <amitlangote09(at)gmail(dot)com>
> napsal:
> >>
> >> On Tue, Apr 14, 2020 at 5:27 PM Julien Rouhaud <rjuju123(at)gmail(dot)com>
> wrote:
> >> > On Tue, Apr 14, 2020 at 10:18 AM Pavel Stehule <
> pavel(dot)stehule(at)gmail(dot)com> wrote:
> >> > > 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.
> >>
> >> By the way, even with all catcaches served from local memory, one may
> >> still see shared buffers being hit during planning. For example:
> >>
> >> explain (buffers, analyze) select * from foo where a = 1;
> >> QUERY PLAN
> >>
> -------------------------------------------------------------------------------------------------------------------
> >> Index Only Scan using foo_pkey on foo (cost=0.15..8.17 rows=1
> >> width=4) (actual time=0.010..0.011 rows=0 loops=1)
> >> Index Cond: (a = 1)
> >> Heap Fetches: 0
> >> Buffers: shared hit=2
> >> Planning Time: 0.775 ms
> >> Buffers: shared hit=72
> >> Execution Time: 0.086 ms
> >> (7 rows)
> >>
> >> Time: 2.477 ms
> >> postgres=# explain (buffers, analyze) select * from foo where a = 1;
> >> QUERY PLAN
> >>
> -------------------------------------------------------------------------------------------------------------------
> >> Index Only Scan using foo_pkey on foo (cost=0.15..8.17 rows=1
> >> width=4) (actual time=0.012..0.012 rows=0 loops=1)
> >> Index Cond: (a = 1)
> >> Heap Fetches: 0
> >> Buffers: shared hit=2
> >> Planning Time: 0.102 ms
> >> Buffers: shared hit=1
> >> Execution Time: 0.047 ms
> >> (7 rows)
> >>
> >> It seems that 1 Buffer hit comes from get_relation_info() doing
> >> _bt_getrootheight() for that index on foo.
> >
> >
> > unfortunatelly, I cannot to repeat it.
> >
> > create table foo(a int);
> > create index on foo(a);
> > insert into foo values(1);
> > analyze foo;
> >
> > for this case any second EXPLAIN is without buffer on my comp
>
> _bt_getrootheight() won't cache any value if the index is totally
> empty. Removing the INSERT in your example should lead to Amit's
> behavior.
>

aha. good to know it.

Thank you

Pavel