[Bizgres-general] Bitmap indexes - some profiles

[Mark Kirkwood]

I did a few profiles for some of my test queries on the (patched) 15-01 
patch(!). Hopefully the results will be useful for you guys. The 
complete gprof processed files, with queries, times and plans are here:

http://homepages.paradise.net.nz/markir/download/bizgres-profiles.tar.gz

However, thought I would make a few comments:

1) Test cases with 3 columns in predicate (profile 0 and 4)

SELECT count(*)
FROM bitmaptest
WHERE val0 = 1
AND   val1 = 4
AND   val2 = 79

  Aggregate  (cost=11462.82..11462.82 rows=1 width=0)
    ->  Bitmap Heap Scan on bitmaptest  (cost=9042.34..11461.21 rows=644 
width=0)
          Recheck Cond: ((val2 = 79) AND (val1 = 4) AND (val0 = 1))
          ->  BitmapAnd  (cost=9042.34..9042.34 rows=644 width=0)
                ->  Bitmap Index Scan on bitmaptest_val2 
(cost=0.00..192.50 rows=51001 width=0)
                      Index Cond: (val2 = 79)
                ->  Bitmap Index Scan on bitmaptest_val1 
(cost=0.00..2712.33 rows=746668 width=0)
                      Index Cond: (val1 = 4)
                ->  Bitmap Index Scan on bitmaptest_val0 
(cost=0.00..6137.00 rows=1690002 width=0)
                      Index Cond: (val0 = 1)

  count
-------
    340
(1 row)


Time: 8623.303 ms

The first few lines of the flat graph are:

granularity: each sample hit covers 4 byte(s) for 0.02% of 6.12 seconds

   %   cumulative   self              self     total
  time   seconds   seconds    calls  ms/call  ms/call  name
  59.1       3.62     3.62                             .mcount (1241)
   8.2       4.12     0.50  2481145     0.00     0.00  _bitmap_next [21]
   5.7       4.47     0.35  2533252     0.00     0.00  hash_search [24]
   5.6       4.81     0.34  4962288     0.00     0.00  __udivdi3 [25]
   2.6       4.97     0.16  2481146     0.00     0.00  __umoddi3 [31]
   2.5       5.13     0.15  2320486     0.00     0.00  memcmp [32]
   2.4       5.27     0.14     1361     0.11     0.11  __sys_read [33]
   2.3       5.41     0.14    16248     0.01     0.01  memset [34]
   2.3       5.55     0.14  2533321     0.00     0.00  hash_any [35]
   2.1       5.68     0.13     2425     0.05     0.39  tbm_add_tuples [22]
   1.1       5.75     0.07  2481142     0.00     0.00  tbm_get_pageentry 
[23]

So, in this case _bitmap_next() would seem to be the guy to look at.
Now this query uses 3 indexes in a bitmap AND to get the resuts, if we 
create a single index on (val2, val1, val0) and repeat we get:

  Aggregate  (cost=2504.13..2504.13 rows=1 width=0)
    ->  Bitmap Heap Scan on bitmaptest  (cost=7.64..2502.46 rows=665 
width=0)
          Recheck Cond: ((val2 = 79) AND (val1 = 4) AND (val0 = 1))
          ->  Bitmap Index Scan on bitmaptest_val2_val1_val0 
(cost=0.00..7.64 rows=665 width=0)
                Index Cond: ((val2 = 79) AND (val1 = 4) AND (val0 = 1))

  count
-------
    340
(1 row)

Time: 3999.204 ms

granularity: each sample hit covers 4 byte(s) for 0.24% of 0.63 seconds

   %   cumulative   self              self     total
  time   seconds   seconds    calls  ms/call  ms/call  name
  21.8       0.14     0.14    16563     0.01     0.01  memset [20]
  17.0       0.24     0.11                             .mcount (1226)
  15.8       0.34     0.10     1360     0.07     0.07  __sys_read [27]
  14.4       0.43     0.09      341     0.26     0.34  _bitmap_next [26]
   7.2       0.48     0.05      608     0.07     0.07  stat [34]
   2.9       0.50     0.02    11687     0.00     0.00  __sys_close [41]
   2.4       0.51     0.02    11090     0.00     0.00  dup [45]
   1.9       0.52     0.01        1    12.01    12.15 
StrategyInitialize [52]
   1.4       0.53     0.01      648     0.01     0.01  __sys_open [65]
   1.4       0.54     0.01      357     0.03     0.03  imalloc <cycle 9> 
[67]
   1.4       0.55     0.01       27     0.33     0.33  element_alloc [61]


We now have memset() and __sys_read() as the major time users - but note 
that the cpu time is only 0.63 seconds, so all the rest is (probably) IO 
wait. This can be confirmed by re-executing the query.

So it looks like the interaction between the bitmap index scan and 
tidscan code is worth investigating.... as it would be nice to get the 3 
index case as good as this!


2) Test case with 1 column in predicate (profile 2)

SELECT count(*)
FROM bitmaptest
WHERE val0 = 5

  Aggregate  (cost=105569.02..105569.02 rows=1 width=0)
    ->  Bitmap Heap Scan on bitmaptest  (cost=2361.00..103944.01 
rows=650001 width=0)
          Recheck Cond: (val0 = 5)
          ->  Bitmap Index Scan on bitmaptest_val0  (cost=0.00..2361.00 
rows=650001 width=0)
                Index Cond: (val0 = 5)

  count
--------
  642280
(1 row)

Time: 17060.697 ms

granularity: each sample hit covers 4 byte(s) for 0.01% of 14.34 seconds

   %   cumulative   self              self     total
  time   seconds   seconds    calls  ms/call  ms/call  name
  43.0       6.17     6.17                             .mcount (1227)
  35.2      11.22     5.05    94039     0.05     0.05  __sys_read [18]
   1.7      11.46     0.24   924721     0.00     0.00  hash_search [24]
   1.0      11.60     0.14   642281     0.00     0.00  _bitmap_next [32]
   1.0      11.74     0.14  1625747     0.00     0.00  tbm_comparator [40]
   1.0      11.88     0.14    16205     0.01     0.01  memset [41]
   0.8      12.00     0.12   924499     0.00     0.00  LWLockAcquire [45]
   0.8      12.11     0.11  1284564     0.00     0.00  AllocSetReset [50]
   0.7      12.21     0.10   924788     0.00     0.00  hash_any [51]
   0.7      12.31     0.10  1291125     0.00     0.00  AllocSetAlloc [52]
   0.6      12.40     0.09    93394     0.00     0.00  tbm_iterate [56]
   0.6      12.48     0.09   924499     0.00     0.00  LWLockRelease [57]

Most of the time is used by __sys_read(). I suspect this is where we are 
reading the 640000 heap rows corresponding to the bitmap entries, 
probably not a lot of scope to improve this. As an aside, the fact that 
most of the time is (probably) involved in reading the heap rows is why 
the bitmap index size decrease improved this query so little.

regards

Mark