Message-ID: <511D0430.1090603@normation.com>
Date: Thu, 14 Feb 2013 16:35:12 +0100
From: Nicolas Charles <nicolas.charles@normation.com>
User-Agent: Mozilla/5.0 (X11; Linux i686;
	rv:11.0) Gecko/20120329 Thunderbird/11.0.1
MIME-Version: 1.0
To: pgsql-performance@postgresql.org
Subject: Surprising no use of indexes - low performance
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: quoted-printable
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Hello,

I've been struggling to understand what's happening on my=20
databases/query for several days, and I'm turning to higher mind for a=20
logical answer.

I'm dealing with a fairly large database, containing logs informations,=20
that I crunch to get data out of it, with several indexes on them that I=20
hoped were logical

\d ruddersysevents
                                  Table =AB public.ruddersysevents =BB
       Colonne       |           Type           |=20=20=20=20=20=20=20=20=
=20=20=20=20=20=20=20=20=20=20
Modificateurs
--------------------+--------------------------+---------------------------=
-----------------------
  id                 | integer                  | non NULL Par d=E9faut,=20
nextval('serial'::regclass)
  executiondate      | timestamp with time zone | non NULL
  nodeid             | text                     | non NULL
  directiveid        | text                     | non NULL
  ruleid             | text                     | non NULL
  serial             | integer                  | non NULL
  component          | text                     | non NULL
  keyvalue           | text                     |
  executiontimestamp | timestamp with time zone | non NULL
  eventtype          | character varying(64)    |
  policy             | text                     |
  msg                | text                     |
Index :
     "ruddersysevents_pkey" PRIMARY KEY, btree (id)
     "component_idx" btree (component)
     "configurationruleid_idx" btree (ruleid)
     "executiontimestamp_idx" btree (executiontimestamp)
     "keyvalue_idx" btree (keyvalue)
     "nodeid_idx" btree (nodeid)
Contraintes de v=E9rification :
     "ruddersysevents_component_check" CHECK (component <> ''::text)
     "ruddersysevents_configurationruleid_check" CHECK (ruleid <> ''::text)
     "ruddersysevents_nodeid_check" CHECK (nodeid <> ''::text)
     "ruddersysevents_policyinstanceid_check" CHECK (directiveid <>=20
''::text)


It contains 11018592 entries, with the followinf patterns :
108492 distinct executiontimestamp
14 distinct nodeid
59 distinct directiveid
26 distinct ruleid
35 distinct serial

Related table/index size are
                 relation                |  size
----------------------------------------+---------
  public.ruddersysevents                 | 3190 MB
  public.nodeid_idx                      | 614 MB
  public.configurationruleid_idx         | 592 MB
  public.ruddersysevents_pkey            | 236 MB
  public.executiontimestamp_idx          | 236 MB


I'm crunching the data by looking for each=20
nodeid/ruleid/directiveid/serial with an executiontimestamp in an interval:

explain analyze select executiondate, nodeid, ruleid, directiveid,=20
serial, component, keyValue, executionTimeStamp, eventtype, policy, msg=20
from RudderSysEvents where 1=3D1  and nodeId =3D=20
'31264061-5ecb-4891-9aa4-83824178f43d'  and ruleId =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd' and serial =3D 10 and=20
executiontimestamp between to_timestamp('2012-11-22 16:00:16.005',=20
'YYYY-MM-DD HH24:MI:SS.MS') and to_timestamp('2013-01-25 18:53:52.467',=20
'YYYY-MM-DD HH24:MI:SS.MS') ORDER BY executionTimeStamp asc;
  Sort  (cost=3D293125.41..293135.03 rows=3D3848 width=3D252) (actual=20
time=3D28628.922..28647.952 rows=3D62403 loops=3D1)
    Sort Key: executiontimestamp
    Sort Method:  external merge  Disk: 17480kB
    ->  Bitmap Heap Scan on ruddersysevents  (cost=3D74359.66..292896.27=20
rows=3D3848 width=3D252) (actual time=3D1243.150..28338.927 rows=3D62403 lo=
ops=3D1)
          Recheck Cond: ((nodeid =3D=20
'31264061-5ecb-4891-9aa4-83824178f43d'::text) AND (ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text))
          Filter: ((serial =3D 10) AND (executiontimestamp >=3D=20
to_timestamp('2012-11-22 16:00:16.005'::text, 'YYYY-MM-DD=20
HH24:MI:SS.MS'::text)) AND (executiontimestamp <=3D=20
to_timestamp('2013-01-25 18:53:52.467'::text, 'YYYY-MM-DD=20
HH24:MI:SS.MS'::text)))
          ->  BitmapAnd  (cost=3D74359.66..74359.66 rows=3D90079 width=3D0)=
=20
(actual time=3D1228.610..1228.610 rows=3D0 loops=3D1)
                ->  Bitmap Index Scan on nodeid_idx=20=20
(cost=3D0.00..25795.17 rows=3D716237 width=3D0) (actual time=3D421.365..421=
.365=20
rows=3D690503 loops=3D1)
                      Index Cond: (nodeid =3D=20
'31264061-5ecb-4891-9aa4-83824178f43d'::text)
                ->  Bitmap Index Scan on configurationruleid_idx=20=20
(cost=3D0.00..48562.32 rows=3D1386538 width=3D0) (actual time=3D794.490..79=
4.490=20
rows=3D1381391 loops=3D1)
                      Index Cond: (ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text)
  Total runtime: 28657.352 ms


I'm surprised that the executiontimestamp index is not used, since it=20
seems to be where most of the query time is spent.

For all my tests, I removed all the incoming logs, so that this table=20
has only selects and no writes

I'm using Postgres 8.4, on a quite smallish VM, with some process=20
runnings, with the following non default configuration
shared_buffers =3D 112MB
work_mem =3D 8MB
maintenance_work_mem =3D 48MB
max_stack_depth =3D 3MB
wal_buffers =3D 1MB
effective_cache_size =3D 128MB
checkpoint_segments =3D 6

Increasing the shared_buffers to 384, 1GB or 1500MB didn't improve the=20
performances (less than 10%). I would have expected it to improve, since=20
the indexes would all fit in RAM
Every explain analyze made after modification of configuration and=20
indexes where done after a complete batch of crunch of logs by our apps,=20
to be sure the stats were corrects

I tested further with the indexes, and reached these results :
1/ dropping the unique index  "configurationruleid_idx" btree (ruleid),=20
"executiontimestamp_idx" btree (executiontimestamp),  "keyvalue_idx"=20
btree (keyvalue),  "nodeid_idx" btree (nodeid) to replace them by a=20
unique index did lower the perfs :

create index composite_idx on ruddersysevents (executiontimestamp,=20
ruleid, serial, nodeid);

Index Scan using composite_idx on ruddersysevents  (cost=3D0.01..497350.22=
=20
rows=3D3729 width=3D252) (actual time=3D7.989..83717.901 rows=3D62403 loops=
=3D1)
    Index Cond: ((executiontimestamp >=3D to_timestamp('2012-11-22=20
16:00:16.005'::text, 'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND=20
(executiontimestamp <=3D to_timestamp('2013-01-25 18:53:52.467'::text,=20
'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND (ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text) AND (serial =3D 10) AND=20
(nodeid =3D '31264061-5ecb-4891-9aa4-83824178f43d'::text))


2/ Removing nodeid from the index did lower again the perf

create index composite2_idx on ruddersysevents (executiontimestamp,=20
ruleid, serial);

  Index Scan using composite2_idx on ruddersysevents=20=20
(cost=3D0.01..449948.98 rows=3D3729 width=3D252) (actual=20
time=3D23.507..84888.349 rows=3D62403 loops=3D1)
    Index Cond: ((executiontimestamp >=3D to_timestamp('2012-11-22=20
16:00:16.005'::text, 'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND=20
(executiontimestamp <=3D to_timestamp('2013-01-25 18:53:52.467'::text,=20
'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND (ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text) AND (serial =3D 10))
    Filter: (nodeid =3D '31264061-5ecb-4891-9aa4-83824178f43d'::text)

3/ Removing executiontimestamp from the composite index makes the query=20
performs better at the begining of its uses (around 17 secondes), but=20
over time it degrades (I'm logging query longer than 20 secondes, and=20
there are very rare in the first half of the batch, and getting more and=20
more common at the end) to what is below

create index composite3_idx on ruddersysevents (ruleid, serial, nodeid);
   Sort  (cost=3D24683.44..24693.07 rows=3D3849 width=3D252) (actual=20
time=3D60454.558..60474.013 rows=3D62403 loops=3D1)
    Sort Key: executiontimestamp
    Sort Method:  external merge  Disk: 17480kB
    ->  Bitmap Heap Scan on ruddersysevents  (cost=3D450.12..24454.23=20
rows=3D3849 width=3D252) (actual time=3D146.065..60249.143 rows=3D62403 loo=
ps=3D1)
          Recheck Cond: ((ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text) AND (serial =3D 10) AND=20
(nodeid =3D '31264061-5ecb-4891-9aa4-83824178f43d'::text))
          Filter: ((executiontimestamp >=3D to_timestamp('2012-11-22=20
16:00:16.005'::text, 'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND=20
(executiontimestamp <=3D to_timestamp('2013-01-25 18:53:52.467'::text,=20
'YYYY-MM-DD HH24:MI:SS.MS'::text)))
          ->  Bitmap Index Scan on composite3_idx  (cost=3D0.00..449.15=20
rows=3D6635 width=3D0) (actual time=3D129.102..129.102 rows=3D62403 loops=
=3D1)
                Index Cond: ((ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text) AND (serial =3D 10) AND=20
(nodeid =3D '31264061-5ecb-4891-9aa4-83824178f43d'::text))
  Total runtime: 60484.022 ms


And with all these tests, the difference of the whole database=20
processing with each index time is within 10% error margin (2h10 to=20
2h25), even if most of the time is spent on the SQL query.

So my question is :
"Why *not* indexing the column which is not used makes the query slower=20
over time, while not slowing the application?"

If you have some clues, I'm really interested.

Best regards
Nicolas


--=20
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance