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
