Re: Bitmap scan is undercosted?

On 03/12/2017 03:27, Jeff Janes wrote:

Due to that, when I disable bitmapscans and seqscans, I start getting slow index scans on the wrong index, i2 rather than i1.  I don't know why he doesn't see that in his example.

When I increase effective_cache_size to 1024MB, I start getting the plan with the slower index i2, too.

Bitmap Heap Scan on public.aaa  (cost=12600.90..23688.70 rows=9488 width=5) (actual time=107.529..115.902 rows=9976 loops=1)
  ->  BitmapAnd  (cost=12600.90..12600.90 rows=9488 width=0) (actual time=105.133..105.133 rows=0 loops=1)
        ->  Bitmap Index Scan on i1  (cost=0.00..1116.43 rows=96000 width=0) (actual time=16.313..16.313 rows=100508 loops=1)
        ->  Bitmap Index Scan on i2  (cost=0.00..11479.47 rows=988338 width=0) (actual time=77.950..77.950 rows=1000200 loops=1)

Index Scan using i2 on public.aaa  (cost=0.44..48227.31 rows=9488 width=5) (actual time=0.020..285.695 rows=9976 loops=1)

Seq Scan on public.aaa  (cost=0.00..169248.54 rows=9488 width=5) (actual time=0.024..966.469 rows=9976 loops=1)

This way the estimates and the actual time get more sense. But then there's the question - maybe it's i1 runs too fast, and is estimated incorrectly? Why that happens?

I've tried to create a better test case:
- Increase shared_buffers and effective_cache_size to fit whole database, including indexes.
- Use random(), to avoid correlation between the filtered values.
- Make both columns of integer type, to avoid special cases with boolean (like the one happened with CREATE STATISTICS).
- Flush OS disk cache and then try running the query several times, to get both cold-cache results and all-in-ram results.
- There are several tests, with different frequency of the selected values in the two columns: [1/10, 1/10], [1/50, 1/10], [1/100, 1/10].
- There is a split of cost by contribution of each of its components: seq_page_cost, random_page_cost, cpu_tuple_cost, cpu_index_tuple_cost, cpu_operator_cost. The EXPLAIN is run for each component, every time with only one of the components set to non-zero.
- The test was run on a Digitalocean VM: Ubuntu 16.04.3 LTS (GNU/Linux 4.4.0-101-generic x86_64), 2 GB RAM,  2 core CPU, SSD; PostgreSQL 9.5.10.


shared_buffers = 1024MB
effective_cache_size = 1024MB
work_mem = 100MB

create table aaa as select floor(random()*10)::int num, (random()*10 < 1)::int flag from generate_series(1, 10000000) id;
create table aaa as select floor(random()*50)::int num, (random()*10 < 1)::int flag from generate_series(1, 10000000) id;
create table aaa as select floor(random()*100)::int num, (random()*10 < 1)::int flag from generate_series(1, 10000000) id;

create index i1 on aaa  (num);
create index i2 on aaa  (flag);

set enable_bitmapscan = on; set enable_indexscan = off;  set enable_seqscan = off;
set enable_bitmapscan = off; set enable_indexscan = on;  set enable_seqscan = off;
set enable_bitmapscan = off; set enable_indexscan = off;  set enable_seqscan = on;

set seq_page_cost = 1.0; set random_page_cost = 1.0; set cpu_tuple_cost = 0.01; set cpu_index_tuple_cost = 0.005; set cpu_operator_cost = 0.0025;

explain (analyze,verbose,costs,buffers) select * from aaa where num = 1 and flag = 1;


Bitmap Heap Scan on public.aaa  (cost=20687.87..66456.91 rows=101403 width=8) (actual time=345.349..6061.834 rows=99600 loops=1)  read=45091
Bitmap Heap Scan on public.aaa  (cost=20687.87..66456.91 rows=101403 width=8) (actual time=593.915..991.403 rows=99600 loops=1)   hit=45091
Bitmap Heap Scan on public.aaa  (cost=20687.87..66456.91 rows=101403 width=8) (actual time=255.273..355.694 rows=99600 loops=1)   hit=45091
Bitmap Heap Scan on public.aaa  (cost=20687.87..66456.91 rows=101403 width=8) (actual time=284.768..385.505 rows=99600 loops=1)   hit=45091
? +  ? +  1014.03 +  ? +  5595.52 = ?

Bitmap Heap Scan on public.aaa  (cost=12081.43..28452.09 rows=19644 width=8) (actual time=238.566..3115.445 rows=20114 loops=1)   read=19425
Bitmap Heap Scan on public.aaa  (cost=12081.43..28452.09 rows=19644 width=8) (actual time=314.590..382.207 rows=20114 loops=1)    hit=19425
Bitmap Heap Scan on public.aaa  (cost=12081.43..28452.09 rows=19644 width=8) (actual time=265.899..311.064 rows=20114 loops=1)    hit=19425
Bitmap Heap Scan on public.aaa  (cost=12081.43..28452.09 rows=19644 width=8) (actual time=209.470..237.697 rows=20114 loops=1)    hit=19425
9689.92 +  ? +  196.44 +  ? +  ? = ?

Bitmap Heap Scan on public.aaa  (cost=11273.15..20482.50 rows=10090 width=8) (actual time=284.381..2019.717 rows=10114 loops=1)   read=12059
Bitmap Heap Scan on public.aaa  (cost=11273.15..20482.50 rows=10090 width=8) (actual time=153.445..180.770 rows=10114 loops=1)    hit=12059
Bitmap Heap Scan on public.aaa  (cost=11273.15..20482.50 rows=10090 width=8) (actual time=146.275..159.446 rows=10114 loops=1)    hit=12059
Bitmap Heap Scan on public.aaa  (cost=11273.15..20482.50 rows=10090 width=8) (actual time=140.973..153.998 rows=10114 loops=1)    hit=12059
4098.28 +  ? +  100.90 +  ? +  ? = ?


Seq Scan on public.aaa  (cost=0.00..194248.49 rows=101403 width=8) (actual time=0.126..2056.913 rows=99600 loops=1)               read=44248
Seq Scan on public.aaa  (cost=0.00..194248.49 rows=101403 width=8) (actual time=0.045..1595.377 rows=99600 loops=1)               hit=32 read=44216
Seq Scan on public.aaa  (cost=0.00..194248.49 rows=101403 width=8) (actual time=0.066..1392.700 rows=99600 loops=1)               hit=64 read=44184
Seq Scan on public.aaa  (cost=0.00..194248.49 rows=101403 width=8) (actual time=0.069..1378.574 rows=99600 loops=1)               hit=96 read=44152
44248.00 +  0.00 +  100000.33 +  0.00 +  50000.17 = 194248.5

Seq Scan on public.aaa  (cost=0.00..194247.77 rows=19644 width=8) (actual time=0.646..1801.794 rows=20114 loops=1)                read=44248
Seq Scan on public.aaa  (cost=0.00..194247.77 rows=19644 width=8) (actual time=0.385..1518.613 rows=20114 loops=1)                hit=32 read=44216
Seq Scan on public.aaa  (cost=0.00..194247.77 rows=19644 width=8) (actual time=0.346..1369.021 rows=20114 loops=1)                hit=64 read=44184
Seq Scan on public.aaa  (cost=0.00..194247.77 rows=19644 width=8) (actual time=0.597..1792.959 rows=20114 loops=1)                hit=96 read=44152
44248.00 +  0.00 +  99999.85 +  0.00 +  49999.93 = 194247.78

Seq Scan on public.aaa  (cost=0.00..194247.77 rows=10090 width=8) (actual time=0.700..2194.195 rows=10114 loops=1)                read=44248
Seq Scan on public.aaa  (cost=0.00..194247.77 rows=10090 width=8) (actual time=0.145..1401.274 rows=10114 loops=1)                hit=32 read=44216
Seq Scan on public.aaa  (cost=0.00..194247.77 rows=10090 width=8) (actual time=0.185..1602.002 rows=10114 loops=1)                hit=64 read=44184
Seq Scan on public.aaa  (cost=0.00..194247.77 rows=10090 width=8) (actual time=0.184..1353.162 rows=10114 loops=1)                hit=96 read=44152
44248.00 +  0.00 +  99999.85 +  0.00 +  49999.93 = 194247.78


Index Scan using i1 on public.aaa  (cost=0.43..67358.15 rows=101403 width=8) (actual time=0.400..1325.638 rows=99600 loops=1)     read=46983
Index Scan using i1 on public.aaa  (cost=0.43..67358.15 rows=101403 width=8) (actual time=0.020..479.713 rows=99600 loops=1)      hit=46983
Index Scan using i1 on public.aaa  (cost=0.43..67358.15 rows=101403 width=8) (actual time=0.024..642.947 rows=99600 loops=1)      hit=46983
Index Scan using i1 on public.aaa  (cost=0.43..67358.15 rows=101403 width=8) (actual time=0.038..756.045 rows=99600 loops=1)      hit=46983
45.95 +  46638.42 +  10336.67 +  5168.34 +  5168.77 = 67358.15
Rows Removed by Filter: 900156

Index Scan using i1 on public.aaa  (cost=0.43..48809.34 rows=19644 width=8) (actual time=0.600..1059.269 rows=20114 loops=1)      read=44373
Index Scan using i1 on public.aaa  (cost=0.43..48809.34 rows=19644 width=8) (actual time=0.071..208.940 rows=20114 loops=1)       hit=44373
Index Scan using i1 on public.aaa  (cost=0.43..48809.34 rows=19644 width=8) (actual time=0.044..124.437 rows=20114 loops=1)       hit=44373
Index Scan using i1 on public.aaa  (cost=0.43..48809.34 rows=19644 width=8) (actual time=0.044..127.814 rows=20114 loops=1)       hit=44373
0.23 +  44788.68 +  2010.00 +  1005.00 +  1005.43 = 48809.34
Rows Removed by Filter: 179792

Index Scan using i1 on public.aaa  (cost=0.43..46544.80 rows=10090 width=8) (actual time=0.647..1510.482 rows=10114 loops=1)      read=39928
Index Scan using i1 on public.aaa  (cost=0.43..46544.80 rows=10090 width=8) (actual time=0.035..141.847 rows=10114 loops=1)       hit=39928
Index Scan using i1 on public.aaa  (cost=0.43..46544.80 rows=10090 width=8) (actual time=0.032..86.716 rows=10114 loops=1)        hit=39928
Index Scan using i1 on public.aaa  (cost=0.43..46544.80 rows=10090 width=8) (actual time=0.032..79.492 rows=10114 loops=1)        hit=39928
0.01 +  44524.36 +  1010.00 +  505.00 +  505.44 = 46544.81
Rows Removed by Filter: 89762


Index Scan using i2 on public.aaa  (cost=0.43..39166.34 rows=101403 width=8) (actual time=1.337..1543.611 rows=99600 loops=1)     read=46985
Index Scan using i2 on public.aaa  (cost=0.43..39166.34 rows=101403 width=8) (actual time=0.027..410.623 rows=99600 loops=1)      hit=46985
Index Scan using i2 on public.aaa  (cost=0.43..39166.34 rows=101403 width=8) (actual time=0.025..377.529 rows=99600 loops=1)      hit=46985
Index Scan using i2 on public.aaa  (cost=0.43..39166.34 rows=101403 width=8) (actual time=0.025..377.554 rows=99600 loops=1)      hit=46985
2979.08 +  16566.83 +  9810.00 +  4905.00 +  4905.44 = 39166.35
Rows Removed by Filter: 900835

Index Scan using i2 on public.aaa  (cost=0.43..39247.83 rows=19644 width=8) (actual time=0.783..2236.765 rows=20114 loops=1)      read=46985
Index Scan using i2 on public.aaa  (cost=0.43..39247.83 rows=19644 width=8) (actual time=0.198..777.279 rows=20114 loops=1)       hit=46985
Index Scan using i2 on public.aaa  (cost=0.43..39247.83 rows=19644 width=8) (actual time=0.196..437.177 rows=20114 loops=1)       hit=46985
Index Scan using i2 on public.aaa  (cost=0.43..39247.83 rows=19644 width=8) (actual time=0.075..346.481 rows=20114 loops=1)       hit=46985
2949.05 +  16751.68 +  9773.33 +  4886.66 +  4887.10 = 39247.82
Rows Removed by Filter: 980350

Index Scan using i2 on public.aaa  (cost=0.43..40167.34 rows=10090 width=8) (actual time=0.619..1350.886 rows=10114 loops=1)      read=46987
Index Scan using i2 on public.aaa  (cost=0.43..40167.34 rows=10090 width=8) (actual time=0.069..448.975 rows=10114 loops=1)       hit=46987
Index Scan using i2 on public.aaa  (cost=0.43..40167.34 rows=10090 width=8) (actual time=0.048..383.066 rows=10114 loops=1)       hit=46987
Index Scan using i2 on public.aaa  (cost=0.43..40167.34 rows=10090 width=8) (actual time=0.050..387.874 rows=10114 loops=1)       hit=46987
2974.39 +  17212.52 +  9990.00 +  4995.00 +  4995.44 = 40167.35
Rows Removed by Filter: 991389


What seems odd to me is that in different kinds of tests (with different frequency of column values):

i1 Rows Removed by Filter = 900156, 179792, 89762 (decreased a lot)
i1 buffers = 46983, 44373, 39928 (decreased, but not a lot)
i1 best case time = 756.045, 127.814, 79.492 (decreased a lot, as well as probably average case too)
i1 cost estimates = 67358.15, 48809.34, 46544.80 (did not decrease a lot)

i2 Rows Removed by Filter = 900835, 980350, 991389
i2 buffers = 46985, 46985, 46987
i2 best case time = 377.554, 346.481, 387.874
i2 cost estimates = 39166.34, 39247.83, 40167.34

It's odd that increase in actual execution time for "i1" was not reflected enough in cost estimates. The cost even didn't go below "i2" costs.

Details about the test are attached.

Regards,
Vitaliy