Re: Buffer pool statistics in Explain Analyze - Mailing list pgsql-hackers

From Vladimir Sitnikov
Subject Re: Buffer pool statistics in Explain Analyze
Date
Msg-id 1d709ecc0811011143mb918dai378c7585c7a1711@mail.gmail.com
Whole thread Raw
In response to Re: Buffer pool statistics in Explain Analyze  (ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp>)
Responses Re: Buffer pool statistics in Explain Analyze
List pgsql-hackers
Hi all,

Here is a patch that adds "buffer pool statistics" to the explain analyze output revealing the number of buffer pages hit at each and every execution step.

It uses counters from storage/buffer/bufmgr.c (I believe all that counters are relevant for investigation of query performance).


Here is the sample output:

create table test as
   select i/10 as a, round(random()*10000) as b
     from generate_series(1,100000) as x(i)
    order by 1;

create index ix_a on test(a);
create index ix_b on test(b);

vacuum analyze test;

explain analyze
select count(*) from test x, test y
 where a.b = 5
   and y.b = x.b;

 Aggregate  (cost=413.88..413.89 rows=1 width=0) (actual time=1.380..1.382 rows=1 loops=1 read_shared=119(111) read_local=0(0) flush=0 local_flush=0 file_read=0 file_write=0)
   ->  Nested Loop  (cost=4.35..413.59 rows=118 width=0) (actual time=0.088..1.230 rows=96 loops=1 read_shared=119(111) read_local=0(0) flush=0 local_flush=0 file_read=0 file_write=0)
         ->  Index Scan using ix_a on test x  (cost=0.00..8.44 rows=10 width=8) (actual time=0.010..0.028 rows=10 loops=1 read_shared=3(3) read_local=0(0) flush=0 local_flush=0 file_read=0 file_write=0)
               Index Cond: (a = 5)
         ->  Bitmap Heap Scan on test y  (cost=4.35..40.38 rows=11 width=8) (actual time=0.034..0.080 rows=10 loops=10 read_shared=116(108) read_local=0(0) flush=0 local_flush=0 file_read=0 file_write=0)
               Recheck Cond: (y.b = x.b)
               ->  Bitmap Index Scan on ix_b  (cost=0.00..4.34 rows=11 width=0) (actual time=0.028..0.028 rows=10 loops=10 read_shared=20(12) read_local=0(0) flush=0 local_flush=0 file_read=0 file_write=0)
                     Index Cond: (y.b = x.b)
 Total runtime: 1.438 ms

read_shared=116(108)  for "Bitmap Heap Scan" means the operation fetched 116 pages into shared buffers and 108 of those 116 were buffer hits.


Sincerely yours,
Vladimir Sitnikov
Attachment

pgsql-hackers by date:

Previous
From: Josh Berkus
Date:
Subject: Re: Please make sure your patches are on the wiki page
Next
From: Simon Riggs
Date:
Subject: Re: Well done, Hackers