Re: Display of buffers for planning time show nothing for second run - Mailing list pgsql-hackers

On Tue, Apr 14, 2020 at 10:36 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> út 14. 4. 2020 v 10:27 odesílatel Julien Rouhaud <rjuju123@gmail.com> napsal:
>>
>> Hi,
>>
>> On Tue, Apr 14, 2020 at 10:18 AM Pavel Stehule <pavel.stehule@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=114loops=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=114loops=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
arenot cached. But I cannot to reproduce it, and then I am little bit surprised so I don't see any hit in second, and
otherexecutions.
 

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)