út 14. 4. 2020 v 10:49 odesílatel Julien Rouhaud <rjuju...@gmail.com> napsal:
> On Tue, Apr 14, 2020 at 10:36 AM Pavel Stehule <pavel.steh...@gmail.com> > wrote: > > > > út 14. 4. 2020 v 10:27 odesílatel Julien Rouhaud <rjuju...@gmail.com> > napsal: > >> > >> 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. > > > > > > 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
