From: Vitaliy Garnashevich <vgarnashevich@gmail.com>
To: Jeff Janes <jeff.janes@gmail.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Justin Pryzby <pryzby@telsasoft.com>
Cc: pgsql-performance@lists.postgresql.org
Subject: Re: Bitmap scan is undercosted?
Date: Wed, 6 Dec 2017 09:06:52 +0200
Message-ID: <cde064b2-9600-8d47-ddb6-a239cacefc5d@gmail.com> (raw)
In-Reply-To: <0a0bfd5f-06cc-918b-da75-4e45c4e8ea27@gmail.com>
References: <73a4936d-2814-dc08-ed0c-978f76f435b0@gmail.com>
<20171201183427.GK18413@telsasoft.com>
<20171201231104.GN18413@telsasoft.com>
<d2b6a335-8c62-4983-3b5b-c8a75cf37d6f@gmail.com>
<CAMkU=1wkjV3CjWE=Cksp_qSZhNbxTOcyc=dDuwhnDzVxGMu6qQ@mail.gmail.com>
<f8edc163-7ebe-cdb8-d068-685355045f24@gmail.com>
<CAMkU=1zGL7UZpaycNH1Zs=K-TuaJx4P5EmP2mZM3DHzy9JinHg@mail.gmail.com>
<18188.1512258290@sss.pgh.pa.us>
<CAMkU=1yKK0M4W+bNc31PZhH15dzPakSmpr6TH9exT8OUZvmg_w@mail.gmail.com>
<0a0bfd5f-06cc-918b-da75-4e45c4e8ea27@gmail.com>
On 04/12/2017 00:11, Vitaliy Garnashevich wrote:
> 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
Attachments:
[application/octet-stream] test.zip (14.8K, ../cde064b2-9600-8d47-ddb6-a239cacefc5d@gmail.com/3-test.zip)
download
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: vgarnashevich@gmail.com, jeff.janes@gmail.com, tgl@sss.pgh.pa.us, pryzby@telsasoft.com, pgsql-performance@lists.postgresql.org
Subject: Re: Bitmap scan is undercosted?
In-Reply-To: <cde064b2-9600-8d47-ddb6-a239cacefc5d@gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox