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

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=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.

On Tue, Apr 14, 2020 at 5:27 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
> On Tue, Apr 14, 2020 at 10:18 AM Pavel Stehule <pavel.stehule@gmail.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=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.

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.

-- 

Amit Langote
EnterpriseDB: http://www.enterprisedb.com

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)

On Tue, Apr 14, 2020 at 10:40 AM Amit Langote <amitlangote09@gmail.com> wrote:
>
> On Tue, Apr 14, 2020 at 5:27 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
> > On Tue, Apr 14, 2020 at 10:18 AM Pavel Stehule <pavel.stehule@gmail.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=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.
>
> 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.

Indeed.  Having received some relcache invalidation should also lead
to similar effect.  Having those counters can help to quantify all of
those interactions.

On Tue, Apr 14, 2020 at 11:25 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> út 14. 4. 2020 v 10:40 odesílatel Amit Langote <amitlangote09@gmail.com> napsal:
>>
>> On Tue, Apr 14, 2020 at 5:27 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
>> > On Tue, Apr 14, 2020 at 10:18 AM Pavel Stehule <pavel.stehule@gmail.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=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
sessionmemory?
 
>> >
>> > 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.