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

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

> On Tue, Apr 14, 2020 at 10:36 AM Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com>
> wrote:
> >
> > út 14. 4. 2020 v 10:27 odesílatel Julien Rouhaud <rjuju123(at)gmail(dot)com>
> napsal:
> >>
> >> Hi,
> >>
> >> On Tue, Apr 14, 2020 at 10:18 AM Pavel Stehule <pavel(dot)stehule(at)gmail(dot)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.
> >
> >
> > One time Tom Lane mentioned using index in planning time for getting
> minimum and maximum. I expected so these values are not cached. But I
> cannot to reproduce it, and then I am little bit surprised so I don't see
> any hit in second, and other executions.
>
> Isn't that get_actual_variable_range() purpose? If you use a plan
> that hit this function you'll definitely see consistent buffer usage
> during planning:
>
> rjuju=# explain (buffers, analyze) select * from pg_class c join
> pg_attribute a on a.attrelid = c.oid;
> QUERY PLAN
>
> -----------------------------------------------------------------------------------------------------------------------
> Hash Join (cost=21.68..110.91 rows=2863 width=504) (actual
> time=0.393..5.989 rows=2863 loops=1)
> Hash Cond: (a.attrelid = c.oid)
> Buffers: shared hit=40 read=29
> -> Seq Scan on pg_attribute a (cost=0.00..81.63 rows=2863
> width=239) (actual time=0.010..0.773 rows=2863 loops=1)
> Buffers: shared hit=28 read=25
> -> Hash (cost=16.86..16.86 rows=386 width=265) (actual
> time=0.333..0.334 rows=386 loops=1)
> Buckets: 1024 Batches: 1 Memory Usage: 85kB
> Buffers: shared hit=9 read=4
> -> Seq Scan on pg_class c (cost=0.00..16.86 rows=386
> width=265) (actual time=0.004..0.123 rows=386 loops=1)
> Buffers: shared hit=9 read=4
> Planning Time: 2.709 ms
> Buffers: shared hit=225 read=33
> Execution Time: 6.529 ms
> (13 rows)
>
> rjuju=# explain (buffers, analyze) select * from pg_class c join
> pg_attribute a on a.attrelid = c.oid;
> QUERY PLAN
>
> -----------------------------------------------------------------------------------------------------------------------
> Hash Join (cost=21.68..110.91 rows=2863 width=504) (actual
> time=0.385..5.613 rows=2863 loops=1)
> Hash Cond: (a.attrelid = c.oid)
> Buffers: shared hit=66
> -> Seq Scan on pg_attribute a (cost=0.00..81.63 rows=2863
> width=239) (actual time=0.012..0.541 rows=2863 loops=1)
> Buffers: shared hit=53
> -> Hash (cost=16.86..16.86 rows=386 width=265) (actual
> time=0.352..0.352 rows=386 loops=1)
> Buckets: 1024 Batches: 1 Memory Usage: 85kB
> Buffers: shared hit=13
> -> Seq Scan on pg_class c (cost=0.00..16.86 rows=386
> width=265) (actual time=0.003..0.092 rows=386 loops=1)
> Buffers: shared hit=13
> Planning Time: 0.575 ms
> Buffers: shared hit=12
> Execution Time: 5.985 ms
> (13 rows)
>
> rjuju=# explain (buffers, analyze) select * from pg_class c join
> pg_attribute a on a.attrelid = c.oid;
> QUERY PLAN
>
> -----------------------------------------------------------------------------------------------------------------------
> Hash Join (cost=21.68..110.91 rows=2863 width=504) (actual
> time=0.287..5.612 rows=2863 loops=1)
> Hash Cond: (a.attrelid = c.oid)
> Buffers: shared hit=66
> -> Seq Scan on pg_attribute a (cost=0.00..81.63 rows=2863
> width=239) (actual time=0.008..0.553 rows=2863 loops=1)
> Buffers: shared hit=53
> -> Hash (cost=16.86..16.86 rows=386 width=265) (actual
> time=0.261..0.262 rows=386 loops=1)
> Buckets: 1024 Batches: 1 Memory Usage: 85kB
> Buffers: shared hit=13
> -> Seq Scan on pg_class c (cost=0.00..16.86 rows=386
> width=265) (actual time=0.003..0.075 rows=386 loops=1)
> Buffers: shared hit=13
> Planning Time: 0.483 ms
> Buffers: shared hit=12
> Execution Time: 5.971 ms
> (13 rows)
>

this example is working on my comp

Thank you

Pavel