Re: Surprising no use of indexes - low performance - Mailing list pgsql-performance

W dniu 2013-02-14 16:35, Nicolas Charles pisze:
> I'm crunching the data by looking for each nodeid/ruleid/directiveid/serial with an
> executiontimestamp in an interval:
>
> explain analyze select executiondate, nodeid, ruleid, directiveid, serial, component, keyValue,
> executionTimeStamp, eventtype, policy, msg from RudderSysEvents where 1=1  and nodeId =
> '31264061-5ecb-4891-9aa4-83824178f43d'  and ruleId = '61713ff1-aa6f-4c86-b3cb-7012bee707dd' and
> serial = 10 and executiontimestamp between to_timestamp('2012-11-22 16:00:16.005', 'YYYY-MM-DD
> HH24:MI:SS.MS') and to_timestamp('2013-01-25 18:53:52.467', 'YYYY-MM-DD HH24:MI:SS.MS') ORDER BY
> executionTimeStamp asc;
>  Sort  (cost=293125.41..293135.03 rows=3848 width=252) (actual time=28628.922..28647.952
> rows=62403 loops=1)
>    Sort Key: executiontimestamp
>    Sort Method:  external merge  Disk: 17480kB
>    ->  Bitmap Heap Scan on ruddersysevents (cost=74359.66..292896.27 rows=3848 width=252) (actual
> time=1243.150..28338.927 rows=62403 loops=1)
>          Recheck Cond: ((nodeid = '31264061-5ecb-4891-9aa4-83824178f43d'::text) AND (ruleid =
> '61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text))
>          Filter: ((serial = 10) AND (executiontimestamp >= to_timestamp('2012-11-22
> 16:00:16.005'::text, 'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND (executiontimestamp <=
> to_timestamp('2013-01-25 18:53:52.467'::text, 'YYYY-MM-DD HH24:MI:SS.MS'::text)))
>          ->  BitmapAnd  (cost=74359.66..74359.66 rows=90079 width=0) (actual
> time=1228.610..1228.610 rows=0 loops=1)
>                ->  Bitmap Index Scan on nodeid_idx (cost=0.00..25795.17 rows=716237 width=0)
> (actual time=421.365..421.365 rows=690503 loops=1)
>                      Index Cond: (nodeid = '31264061-5ecb-4891-9aa4-83824178f43d'::text)
>                ->  Bitmap Index Scan on configurationruleid_idx  (cost=0.00..48562.32 rows=1386538
> width=0) (actual time=794.490..794.490 rows=1381391 loops=1)
>                      Index Cond: (ruleid = '61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text)
>  Total runtime: 28657.352 ms
>
>
>
> I'm surprised that the executiontimestamp index is not used, since it seems to be where most of
> the query time is spent.

this use pattern is quite similar to the one I used to have problem with. The key problem here is
that planner wants to bitmapand on indexes that are spread on all the table, on all timestamp
values, regardless you are interested in only a narrow timestamp window, and is quite aggressive on
using bitmapscan feature. So the planner needs to be directed more precisely.

You could try the above again with:

SET enable_bitmapscan TO off ?

It helped in my case.

You may also try close the timestamp condition in a "preselecting" CTE, and doing the rest of finer
filtering outside of it, like:

with
p as (select * from RudderSysEvents where executiontimestamp between '2012-11-22 16:00:16.005' and
'2013-01-25 18:53:52.467')
select executiondate, nodeid, ruleid, directiveid, serial, component, keyValue, executionTimeStamp,
eventtype, policy, msg
from p
where nodeId = '31264061-5ecb-4891-9aa4-83824178f43d'  and ruleId =
'61713ff1-aa6f-4c86-b3cb-7012bee707dd' and serial = 10

As a side note, I think that all your indexes, except the timestamp one, are unnecessary, because of
low distribution or their values, and, as you see, the confuse they make to the planner.

Eventually, you may use one of the columns as a second one to a two column index together with
timestamp, the one which may always be used for filtering and add its filtering inside the CTE part.

HTH,
Irek.