Subject: Re: Bitmap scan is undercosted?
From: Vitaliy Garnashevich <vgarnashevich@gmail.com>
To: Jeff Janes <jeff.janes@gmail.com>, Tom Lane <tgl@sss.pgh.pa.us>
Cc: Justin Pryzby <pryzby@telsasoft.com>,
 pgsql-performance@lists.postgresql.org
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>
 <cde064b2-9600-8d47-ddb6-a239cacefc5d@gmail.com>
Message-ID: <d06c555e-6710-2dd7-d019-4d7bc40750b4@gmail.com>
Date: Thu, 7 Dec 2017 02:17:13 +0200
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:52.0) Gecko/20100101
 Thunderbird/52.5.0
MIME-Version: 1.0
In-Reply-To: <cde064b2-9600-8d47-ddb6-a239cacefc5d@gmail.com>
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 8bit
Content-Language: en-US
Precedence: bulk


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

I've added some logging, in order to get the actual numbers which were 
used for estimation.

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

--set enable_bitmapscan = off; set enable_indexscan = on;  set 
enable_seqscan = off;
--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;

--create index i1 on aaa  (num);
--drop index if exists i2;
--explain (analyze,verbose,costs,buffers) select * from aaa where num = 
1 and flag = 1;

Index Scan using i1 on public.aaa  (cost=0.43..46697.59 rows=10641 
width=8) (actual time=0.047..153.521 rows=9826 loops=1)
   Rows Removed by Filter: 89948

--drop index if exists i1;
--create index i2 on aaa  (flag);
--explain (analyze,verbose,costs,buffers) select * from aaa where num = 
1 and flag = 1;

Index Scan using i2 on public.aaa  (cost=0.43..39583.11 rows=10641 
width=8) (actual time=0.098..351.454 rows=9826 loops=1)
   Rows Removed by Filter: 990249


LOG:  cost_index:
         seq_page_cost=1.00, random_page_cost=1.00, 
cpu_tuple_cost=0.0100, cpu_index_tuple_cost=0.0050, 
cpu_operator_cost=0.0025, effective_cache_size=131072
         indexStartupCost=0.43, indexTotalCost=1103.94, 
indexSelectivity=0.01076667, indexCorrelation=0.00208220
         baserel->tuples=10000033.00, baserel->pages=44248.00, 
baserel->allvisfrac=0.00000000
         tuples_fetched=107667.00, pages_fetched=477.00
         max_IO_cost=44248.0000, min_IO_cost=477.0000, csquared=0.0000
         qpqual_cost.startup=0.0000, qpqual_cost.per_tuple=0.0025, 
cpu_per_tuple=0.0125
         spc_seq_page_cost=1.00, spc_random_page_cost=1.00
         startup_cost=0.43, total_cost=46697.59

LOG:  cost_index:
         seq_page_cost=1.00, random_page_cost=1.00, 
cpu_tuple_cost=0.0100, cpu_index_tuple_cost=0.0050, 
cpu_operator_cost=0.0025, effective_cache_size=131072
         indexStartupCost=0.43, indexTotalCost=10123.93, 
indexSelectivity=0.09883333, indexCorrelation=0.82505685
         baserel->tuples=10000000.00, baserel->pages=44248.00, 
baserel->allvisfrac=0.00000000
         tuples_fetched=988333.00, pages_fetched=4374.00
         max_IO_cost=44248.0000, min_IO_cost=4374.0000, csquared=0.6807
         qpqual_cost.startup=0.0000, qpqual_cost.per_tuple=0.0025, 
cpu_per_tuple=0.0125
         spc_seq_page_cost=1.00, spc_random_page_cost=1.00
         startup_cost=0.43, total_cost=39583.11


Here is a break down of the total_cost into components, for i1 query and 
for i2 query (some rounding was removed from the formula for brevity):

path->path.total_cost =
   (indexTotalCost + qpqual_cost.startup) +
   (max_IO_cost + csquared * (min_IO_cost - max_IO_cost)) +
   (cpu_tuple_cost + qpqual_cost.per_tuple) * (indexSelectivity * 
baserel->tuples);
path->path.total_cost =
   1103.94 + 0.0000 +                                // 1103.94 +
   44248.0000 + 0.0000 * (477.0000 - 44248.0000) +   // 44248.00 +
   (0.0100 + 0.0025) * (0.01076667 * 10000033.00)    // 1345.84
   = 46697.78;                                       // = 46697.78;

path->path.total_cost =
   (indexTotalCost + qpqual_cost.startup) +
   (max_IO_cost + csquared * (min_IO_cost - max_IO_cost)) +
   (cpu_tuple_cost + qpqual_cost.per_tuple) * (indexSelectivity * 
baserel->tuples);
path->path.total_cost =
   10123.93 + 0.0000 +                               // 10123.93 +
   44248.0000 + 0.6807 * (4374.0000 - 44248.0000) +  // 17105.77 +
   (0.0100 + 0.0025) * (0.09883333 * 10000000.00)    // 12354.17
   = 39583.86;                                       // = 39583.86;


PS.
The code used for logging:
/postgresql-9.3.1/src/backend/optimizer/path/costsize.c : cost_index()

     ereport(LOG,
             (errmsg("cost_index: \n"
                     "seq_page_cost=%.2f, random_page_cost=%.2f, 
cpu_tuple_cost=%.4f, cpu_index_tuple_cost=%.4f, cpu_operator_cost=%.4f, 
effective_cache_size=%.0f\n"
                     "indexStartupCost=%.2f, indexTotalCost=%.2f, 
indexSelectivity=%.8f, indexCorrelation=%.8f\n"
                     "baserel->tuples=%.2f, baserel->pages=%.2f, 
baserel->allvisfrac=%.8f\n"
                     "tuples_fetched=%.2f, pages_fetched=%.2f\n"
                     "max_IO_cost=%.4f, min_IO_cost=%.4f, csquared=%.4f\n"
                     "qpqual_cost.startup=%.4f, 
qpqual_cost.per_tuple=%.4f, cpu_per_tuple=%.4f\n"
                     "spc_seq_page_cost=%.2f, spc_random_page_cost=%.2f\n"
                     "startup_cost=%.2f, total_cost=%.2f\n",

                     seq_page_cost, random_page_cost, cpu_tuple_cost, 
cpu_index_tuple_cost, cpu_operator_cost, (double)effective_cache_size,
                     indexStartupCost, indexTotalCost, indexSelectivity, 
indexCorrelation,
                     baserel->tuples, (double) baserel->pages, 
baserel->allvisfrac,
                     tuples_fetched, pages_fetched,
                     max_IO_cost, min_IO_cost, csquared,
                     qpqual_cost.startup, qpqual_cost.per_tuple, 
cpu_per_tuple,
                     spc_seq_page_cost, spc_random_page_cost,
                     startup_cost, startup_cost + run_cost
                     )));

Regards,
Vitaliy