Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1cGuRH-0005pR-JN for pgsql-performance@arkaria.postgresql.org; Tue, 13 Dec 2016 21:16:43 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1cGuRG-0001Dv-P8 for pgsql-performance@arkaria.postgresql.org; Tue, 13 Dec 2016 21:16:42 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1cGuPZ-0007jl-Q8 for pgsql-performance@postgresql.org; Tue, 13 Dec 2016 21:14:58 +0000 Received: from mail-wj0-x241.google.com ([2a00:1450:400c:c01::241]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1cGuPR-0001ww-FX for pgsql-performance@postgresql.org; Tue, 13 Dec 2016 21:14:56 +0000 Received: by mail-wj0-x241.google.com with SMTP id j10so18636356wjb.3 for ; Tue, 13 Dec 2016 13:14:48 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=from:message-id:mime-version:subject:date:in-reply-to:cc:to :references; bh=Uzgrfd6gqABNSrqcgcZQ+3bbQdyjc4wg9HRxPtzGlCM=; b=YvN1j+3Xcjw9ExDZTpOPDcxKpSuGA/MHlC0Ft6n93i95se09EF89Mu4izfexxfXH8r s8zp23eeA0MAqNtIIiwoT6THgnZ1Ox3EuW99hwjRyAKZbJX75kt27oen5Pe71790+fTh IsUt0/9kjAnvK8bSTwCBLkDEhAVwodovMpMqo5Myxa7uq8fJoN4QzIjOwX9U2hEcJ/+l ulpRH+hvPqPUUkYdqT6fucgpcIcHscTStDuOiIspptQt6tqvjRyYeIQuChFSRiRCzaUp BrZB02O7uTzLLKQTQkJXv3SMkdKlSD3IsOSh4uMeXtXcw1ICFa8eJriWbydHkAkMc6tu r2JA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:message-id:mime-version:subject:date :in-reply-to:cc:to:references; bh=Uzgrfd6gqABNSrqcgcZQ+3bbQdyjc4wg9HRxPtzGlCM=; b=FocTwZv80gc3sfQ/4OwpO42Y8lFHKv85l/ulR9IY/OArXXTL3dPMlmKpLX7ipZBQaE 4LVJKlRxBJkJlUG0Ya5YUY/bUGPIGKGZbIXf8fp/G0AQTboZqXO1nDJPLMQkB7s72TWM ZPBoGyG37AUNyO3fYiQQHqGzuhtz1jpEK4hpCgpZSNp2uKzBA6oVCu4nb8joQ5MNqeYT RW3q2yRXE3C4fEa4OyAsiF2Q+6BltyyWN/Is9Yi/nPzMxC/iH912vBKmQghWGwQHvjeN AYlLDK7pkRdC2Bn7/EvpEcvuRVZwa4MfFrWBqRcNe3WhGDF03h4/v50EJpvrqc6b2iNg VfKw== X-Gm-Message-State: AKaTC03b6IlETCqUmCvrfbH6qOIGQZpxuq6cScSisTe/n3tvz8vqJc/EKs3qs1T/u2jB+A== X-Received: by 10.194.58.198 with SMTP id t6mr82756474wjq.44.1481663686851; Tue, 13 Dec 2016 13:14:46 -0800 (PST) Received: from [192.168.1.110] ([90.77.173.136]) by smtp.gmail.com with ESMTPSA id f3sm4397484wmf.10.2016.12.13.13.14.45 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 13 Dec 2016 13:14:46 -0800 (PST) From: Daniel Blanch Bataller Message-Id: <6D56C5BA-AC04-49BD-B289-1AA8C006A161@gmail.com> Content-Type: multipart/alternative; boundary="Apple-Mail=_7896F8AE-B4F3-47A2-AB4B-3218038FF64C" Mime-Version: 1.0 (Mac OS X Mail 10.1 \(3251\)) Subject: Re: Querying with multicolumn index Date: Tue, 13 Dec 2016 22:14:44 +0100 In-Reply-To: <36867AC4-DDD8-464E-A0F7-066B4C88300C@gmail.com> Cc: Tom Lane , pgsql-performance@postgresql.org, Eric Clark , Tomas Vondra To: Eric Jiang References: <5353.1481327501@sss.pgh.pa.us> <36867AC4-DDD8-464E-A0F7-066B4C88300C@gmail.com> X-Mailer: Apple Mail (2.3251) X-Pg-Spam-Score: -2.0 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --Apple-Mail=_7896F8AE-B4F3-47A2-AB4B-3218038FF64C Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Hi all, If anyone still interested in the issue I think I have a very plausible = explanation of Eric=E2=80=99s postgresql bad index choice that is: = bloated updates_driver_id_time_idx index. Though it=E2=80=99s possible to fool postgresql planner, as I=E2=80=99ve = shown in previous tests, this happens with a very concrete data = distribution ~ 100 evenly distributed keys over 15M records and ~ 6M = records under one single key, if you play a bit with figures it = doesn=E2=80=99t happen anymore. Eric=E2=80=99s data distribution wasn=E2=80=99t that extreme, as far as = I know he had ~ 100K vs 500K distributions =E2=80=A6 Well, I=E2=80=99ve = been able to reproduce the problem with a close data distribution to = Erik=E2=80=99s. I made it creating a =E2=80=98bloated index=E2=80=99. If = optimal index is too big, postgres tries with another suboptimal index, = in this case index =E2=80=99time=E2=80=99.=20 See this excerpt of my tests results: (..) -- populate table with 99 homogeneus distributed values INSERT INTO updates SELECT q, q % 99, q, q, to_timestamp(q), q % 99 FROM = generate_series(1, 15000000) q; INSERT 0 15000000 Time: 65686,547 ms -- populate table with 1 value with 500K rows, simmilar distribution you = posted. INSERT INTO updates SELECT q + 15000000, 100, q, q, to_timestamp(q), -- = timestamp will start at 1 at end at 6M 100 FROM generate_series(1, 500000) q; INSERT 0 500000 Time: 2463,073 ms -- add constraints and indexes (=E2=80=A6) -- create 'bloated' driver_id, time index. CREATE INDEX ON updates (driver_id, "time") WITH (fillfactor =3D 10); CREATE INDEX Time: 41234,091 ms -- check index sizes, updates_driver_id_idx is huge. SELECT relname, relpages FROM pg_class WHERE relname LIKE 'updates%'; relname | relpages=20 -----------------------------+---------- updates | 129167 updates_driver_id_time_idx | 576919 =20 updates_id_seq | 1 updates_pkey | 42502 updates_time_idx | 42502 updates_vehicle_id_time_idx | 59684 (6 rows) Time: 16,810 ms -- check behavior with bloated index ANALYZE updates; ANALYZE Time: 254,917 ms (..) Time: 4,635 ms EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id =3D 100 = ORDER BY "time" DESC LIMIT 1; = QUERY PLAN = =20 = --------------------------------------------------------------------------= --------------------------------------------------------------------------= -------- Limit (cost=3D0.43..1.91 rows=3D1 width=3D36) (actual = time=3D21486.015..21486.015 rows=3D1 loops=3D1) Buffers: shared hit=3D39618 read=3D160454 written=3D592 -> Index Scan Backward using updates_time_idx on updates = (cost=3D0.43..691283.45 rows=3D469134 width=3D36) (actual = time=3D21486.014..21486.014 rows=3D1 loops=3D1) Filter: (driver_id =3D 100) Rows Removed by Filter: 14500000 Buffers: shared hit=3D39618 read=3D160454 written=3D592 Planning time: 0.171 ms Execution time: 21486.068 ms (8 rows) Time: 21486,905 ms -- rebuild index with default fillfactor ALTER INDEX updates_driver_id_time_idx SET (fillfactor =3D 90); ALTER INDEX Time: 0,682 ms REINDEX INDEX updates_driver_id_time_idx; REINDEX Time: 23559,530 ms -- recheck index sizes, updates_driver_id_idx should look pretty = simmilar to others. SELECT relname, relpages FROM pg_class WHERE relname LIKE 'updates%'; relname | relpages=20 -----------------------------+---------- updates | 129167 updates_driver_id_time_idx | 59684 updates_id_seq | 1 updates_pkey | 42502 updates_time_idx | 42502 updates_vehicle_id_time_idx | 59684 (6 rows) Time: 0,452 ms -- check behavior with regular sized index EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id =3D 100 = ORDER BY "time" DESC LIMIT 1; = QUERY PLAN = =20 = --------------------------------------------------------------------------= --------------------------------------------------------------------------= ---------- Limit (cost=3D0.56..1.69 rows=3D1 width=3D36) (actual = time=3D0.032..0.033 rows=3D1 loops=3D1) Buffers: shared hit=3D2 read=3D3 -> Index Scan Backward using updates_driver_id_time_idx on updates = (cost=3D0.56..529197.34 rows=3D469133 width=3D36) (actual = time=3D0.032..0.032 rows=3D1 loops=3D1) Index Cond: (driver_id =3D 100) Buffers: shared hit=3D2 read=3D3 Planning time: 0.074 ms Execution time: 0.046 ms (7 rows) Time: 0,312 ms @Eric How to solve the problem: First of all check if this is the case, check indexes sizes, if you have = this problem updates_driver_id_time_idx should be significantly bigger = than others. SELECT relname, relpages FROM pg_class WHERE relname LIKE 'updates%=E2=80=99= ; Check index configuration to see if you have different fillfactor = configuration \d+ updates_driver_id_time_idx If you have setup a different fillfactor, turn it to normal, that is = 90%. I don=E2=80=99t see why you should have a low fillfactor, your data = doesn=E2=80=99t seem to have frecuent updates, by the contrary, it seems = only write and read data. ALTER INDEX updates_driver_id_time_idx SET (fillfactor =3D 90) If your index fillfactor is normal, there is a chance it got bloated, = but this is rare.=20 Reindex your data. REINDEX INDEX updates_driver_id_time_idx; Run tests again. Regards, Daniel Blanch. P.S. Here you have my full tests and output, you might find them useful. = Don=E2=80=99t forget to show us index sizes and index configuration, = please. > El 11 dic 2016, a las 7:04, Daniel Blanch Bataller = escribi=C3=B3: >=20 > Hi all, >=20 > Thomas is absolutely right, the distribution I synthetically made, had = 6M records but very old, 9M old, as you can see it had to skip 9M = records before finding a suitable record using time index.=20 >=20 > EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id =3D = 100 ORDER BY "time" DESC LIMIT 1; > = QUERY PLAN > = --------------------------------------------------------------------------= --------------------------------------------------------------------------= -------- > Limit (cost=3D0.44..0.65 rows=3D1 width=3D36) (actual = time=3D3827.807..3827.807 rows=3D1 loops=3D1) > Buffers: shared hit=3D24592 read=3D99594 written=3D659 > -> Index Scan Backward using updates_time_idx on updates = (cost=3D0.44..1284780.53 rows=3D6064800 width=3D36) (actual = time=3D3827.805..3827.805 rows=3D1 loops=3D1) > Filter: (driver_id =3D 100) > Rows Removed by Filter: 9000000 > Buffers: shared hit=3D24592 read=3D99594 written=3D659 > Planning time: 0.159 ms > Execution time: 3827.846 ms > (8 rows) >=20 >=20 > Here you have my tests where I was able to reproduce the problem using = default settings on 9.6, 9.5 and 9.3. 9.6 and 9.5 choose the wrong = index, while 9.3 didn=E2=80=99t. (update: 9.5 didn=E2=80=99t fail last = time)=20 >=20 > = >=20 > However when I tried to add more than one value with this strange = distribution ~ 30% of distribution to one value the index bad choice = problem didn=E2=80=99t happen again in none of the different versions. >=20 > I Hope this helps. Regards, >=20 > Daniel Blanch. >=20 >=20 >> El 10 dic 2016, a las 21:34, Tomas Vondra = escribi=C3=B3: >>=20 >> Hi, >>=20 >> On 12/10/2016 12:51 AM, Tom Lane wrote: >>> Eric Jiang writes: >>>> I have a query that I *think* should use a multicolumn index, but >>>> sometimes isn't, resulting in slow queries. >>>=20 >>> I tried to duplicate this behavior, without success. Are you = running >>> with nondefault planner parameters? >>>=20 >>=20 >> My guess is this is a case of LIMIT the matching rows are uniformly = distributed in the input data. The planner likely concludes that for a = driver with a lot of data we'll find the first row using ix_updates_time = very quickly, and that it will be cheaper than inspecting the larger = multi-column index. But imagine a driver with a lots of data long time = ago. That breaks the LIMIT fairly quickly. >>=20 >> regards >>=20 >> --=20 >> Tomas Vondra http://www.2ndQuadrant.com >> PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services >>=20 >>=20 >> --=20 >> Sent via pgsql-performance mailing list = (pgsql-performance@postgresql.org) >> To make changes to your subscription: >> http://www.postgresql.org/mailpref/pgsql-performance >=20 --Apple-Mail=_7896F8AE-B4F3-47A2-AB4B-3218038FF64C Content-Type: multipart/mixed; boundary="Apple-Mail=_BD637ACD-26FE-4307-9F70-F42C158BD872" --Apple-Mail=_BD637ACD-26FE-4307-9F70-F42C158BD872 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8
Hi all,

If anyone still interested in the issue = I think I have a very plausible explanation of Eric=E2=80=99s postgresql = bad index choice that is: bloated updates_driver_id_time_idx = index.

Though = it=E2=80=99s possible to fool postgresql planner, as I=E2=80=99ve shown = in previous tests, this happens with a very concrete data distribution ~ = 100 evenly distributed keys over 15M records and ~ 6M records under one = single key, if you play a bit with figures it doesn=E2=80=99t happen = anymore.

Eric=E2=80=99s data distribution wasn=E2=80=99t that extreme, = as far as I know he had ~ 100K vs 500K distributions =E2=80=A6 Well, = I=E2=80=99ve been able to reproduce the problem with a close data = distribution to Erik=E2=80=99s. I made it creating a =E2=80=98bloated = index=E2=80=99. If optimal index is too big, postgres tries with another = suboptimal index, in this case index =E2=80=99time=E2=80=99. 

See this excerpt of = my tests results:

(..)
-- populate = table with 99 homogeneus distributed values
INSERT INTO updates SELECT = q, q % 99, q, q, to_timestamp(q), q % 99 FROM generate_series(1, = 15000000) q;
INSERT 0 15000000
Time: 65686,547 ms
-- populate table with 1 = value with 500K rows, simmilar distribution you posted.
INSERT INTO updates SELECT = q + 15000000, 100, q, q, to_timestamp(q), -- timestamp will start at 1 = at end at 6M
= 100 FROM generate_series(1, 500000) q;
INSERT 0 = 500000
Time:= 2463,073 ms
-- add constraints and indexes

(=E2=80=A6)

-- create 'bloated' = driver_id, time index.
CREATE INDEX ON updates (driver_id, "time") WITH (fillfactor = =3D 10);
CREATE INDEX
Time: 41234,091 ms
-- check index sizes, updates_driver_id_idx = is huge.
SELECT relname, relpages FROM pg_class WHERE relname LIKE = 'updates%';
           relname   =         | relpages 
-----------------------------+----------
 updates     =                 |   = 129167
 updates_driver_id_time_idx  |   576919 =  
 updates_id_seq           =    |        1
 updates_pkey   =              |   =  42502
 updates_time_idx           =  |    42502
 updates_vehicle_id_time_idx |   =  59684
(6 rows)

Time: 16,810 ms
-- check behavior with = bloated index
ANALYZE updates;
ANALYZE
Time: 254,917 ms

(..)

Time: 4,635 ms
EXPLAIN (ANALYZE, BUFFERS) = SELECT * FROM updates WHERE driver_id =3D 100 ORDER BY "time" DESC LIMIT = 1;
  =                     =                     =                     =            QUERY PLAN       =                     =                     =                     =       
---------------------------------------------------------------= --------------------------------------------------------------------------= -------------------
 Limit  (cost=3D0.43..1.91 rows=3D1 width=3D36) = (actual time=3D21486.015..21486.015 rows=3D1 loops=3D1)
   Buffers: = shared hit=3D39618 read=3D160454 written=3D592
   -> =  Index Scan Backward using updates_time_idx on updates =  (cost=3D0.43..691283.45 rows=3D469134 width=3D36) (actual = time=3D21486.014..21486.014 rows=3D1 loops=3D1)
        =  Filter: (driver_id =3D 100)
         Rows = Removed by Filter: 14500000
         Buffers: = shared hit=3D39618 read=3D160454 written=3D592
 Planning time: 0.171 = ms
 Execution time: 21486.068 ms
(8 rows)

Time: 21486,905 ms
-- rebuild index with default = fillfactor
ALTER INDEX updates_driver_id_time_idx SET (fillfactor =3D = 90);
ALTER = INDEX
Time: = 0,682 ms
REINDEX INDEX updates_driver_id_time_idx;
REINDEX
Time: 23559,530 = ms
-- = recheck index sizes, updates_driver_id_idx should look pretty simmilar = to others.
SELECT relname, relpages FROM pg_class WHERE relname LIKE = 'updates%';
           relname   =         | relpages 
-----------------------------+----------
 updates     =                 |   = 129167
 updates_driver_id_time_idx  |   =  59684
 updates_id_seq           =    |        1
 updates_pkey   =              |   =  42502
 updates_time_idx           =  |    42502
 updates_vehicle_id_time_idx |   =  59684
(6 rows)

Time: 0,452 ms
-- check behavior with = regular sized index
EXPLAIN (ANALYZE, BUFFERS) = SELECT * FROM updates WHERE driver_id =3D 100 ORDER BY "time" DESC LIMIT = 1;
  =                     =                     =                     =             QUERY PLAN     =                     =                     =                     =          
---------------------------------------------------------------= --------------------------------------------------------------------------= ---------------------
 Limit  (cost=3D0.56..1.69 rows=3D1 width=3D36) = (actual time=3D0.032..0.033 rows=3D1 loops=3D1)
   Buffers: = shared hit=3D2 read=3D3
   ->  Index Scan Backward using = updates_driver_id_time_idx on updates  (cost=3D0.56..529197.34 = rows=3D469133 width=3D36) (actual time=3D0.032..0.032 rows=3D1 = loops=3D1)
         Index Cond: (driver_id =3D = 100)
  =        Buffers: shared hit=3D2 = read=3D3
 Planning time: 0.074 ms
 Execution time: 0.046 = ms
(7 = rows)

Time: 0,312 ms


@Eric

How to solve the = problem:

First = of all check if this is the case, check indexes sizes, if you have this = problem updates_driver_id_time_idx should be significantly bigger than = others.

SELECT relname, relpages FROM pg_class WHERE = relname LIKE 'updates%=E2=80=99;

Check index configuration to see if you = have different fillfactor configuration

\d+ = updates_driver_id_time_idx

If you have setup a different = fillfactor, turn it to normal, that is 90%. I don=E2=80=99t see why you = should have a low fillfactor, your data doesn=E2=80=99t seem to have = frecuent updates, by the contrary, it seems only write and read = data.

ALTER INDEX updates_driver_id_time_idx SET = (fillfactor =3D 90)

If your index fillfactor is normal, there is a chance it got = bloated, but this is rare. 

Reindex your data.

REINDEX INDEX = updates_driver_id_time_idx;

Run tests again.


Regards,

Daniel Blanch.

P.S. Here you have my full tests and output, you might find = them useful. Don=E2=80=99t forget to show us index sizes and index = configuration, please.


= --Apple-Mail=_BD637ACD-26FE-4307-9F70-F42C158BD872 Content-Disposition: attachment; filename=test_bad_index_choice_bloated_index.sql Content-Type: application/octet-stream; x-unix-mode=0644; name="test_bad_index_choice_bloated_index.sql" Content-Transfer-Encoding: 7bit -- create database CREATE DATABASE test; \c test -- set timing \timing on -- create table CREATE TABLE updates ( id serial, driver_id int not null, latitude double precision not null, longitude double precision not null, "time" timestamp with time zone not null default now(), vehicle_id integer); -- populate table with 99 homogeneus distributed values INSERT INTO updates SELECT q, q % 99, q, q, to_timestamp(q), q % 99 FROM generate_series(1, 15000000) q; -- populate table with 1 value with 500K rows, simmilar distribution you posted. INSERT INTO updates SELECT q + 15000000, 100, q, q, to_timestamp(q), -- timestamp will start at 1 at end at 6M 100 FROM generate_series(1, 500000) q; -- add constraints and indexes ALTER TABLE updates ADD PRIMARY KEY (id); CREATE INDEX ON updates ("time"); CREATE INDEX ON updates (vehicle_id, "time"); -- create 'bloated' driver_id, time index. CREATE INDEX ON updates (driver_id, "time") WITH (fillfactor = 10); -- check index sizes, updates_driver_id_idx is huge. SELECT relname, relpages FROM pg_class WHERE relname LIKE 'updates%'; -- check behavior with bloated index ANALYZE updates; EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 50 ORDER BY "time" DESC LIMIT 1; EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 100 ORDER BY "time" DESC LIMIT 1; -- rebuild index with default fillfactor ALTER INDEX updates_driver_id_time_idx SET (fillfactor = 90); REINDEX INDEX updates_driver_id_time_idx; -- recheck index sizes, updates_driver_id_idx should look pretty simmilar to others. SELECT relname, relpages FROM pg_class WHERE relname LIKE 'updates%'; -- check behavior with regular sized index EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 50 ORDER BY "time" DESC LIMIT 1; EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 100 ORDER BY "time" DESC LIMIT 1; --Apple-Mail=_BD637ACD-26FE-4307-9F70-F42C158BD872 Content-Transfer-Encoding: 7bit Content-Type: text/html; charset=us-ascii
--Apple-Mail=_BD637ACD-26FE-4307-9F70-F42C158BD872 Content-Disposition: attachment; filename=test_bad_index_choice_bloated_index.out Content-Type: application/octet-stream; x-unix-mode=0644; name="test_bad_index_choice_bloated_index.out" Content-Transfer-Encoding: 7bit -- create database CREATE DATABASE test; CREATE DATABASE \c test You are now connected to database "test" as user "postgres". -- set timing \timing on Timing is on. -- create table CREATE TABLE updates ( id serial, driver_id int not null, latitude double precision not null, longitude double precision not null, "time" timestamp with time zone not null default now(), vehicle_id integer); CREATE TABLE Time: 4,317 ms -- populate table with 99 homogeneus distributed values INSERT INTO updates SELECT q, q % 99, q, q, to_timestamp(q), q % 99 FROM generate_series(1, 15000000) q; INSERT 0 15000000 Time: 65686,547 ms -- populate table with 1 value with 500K rows, simmilar distribution you posted. INSERT INTO updates SELECT q + 15000000, 100, q, q, to_timestamp(q), -- timestamp will start at 1 at end at 6M 100 FROM generate_series(1, 500000) q; INSERT 0 500000 Time: 2463,073 ms -- add constraints and indexes ALTER TABLE updates ADD PRIMARY KEY (id); ALTER TABLE Time: 10812,596 ms CREATE INDEX ON updates ("time"); CREATE INDEX Time: 9247,027 ms CREATE INDEX ON updates (vehicle_id, "time"); CREATE INDEX Time: 23180,725 ms -- create 'bloated' driver_id, time index. CREATE INDEX ON updates (driver_id, "time") WITH (fillfactor = 10); CREATE INDEX Time: 41234,091 ms -- check index sizes, updates_driver_id_idx is huge. SELECT relname, relpages FROM pg_class WHERE relname LIKE 'updates%'; relname | relpages -----------------------------+---------- updates | 129167 updates_driver_id_time_idx | 576919 updates_id_seq | 1 updates_pkey | 42502 updates_time_idx | 42502 updates_vehicle_id_time_idx | 59684 (6 rows) Time: 16,810 ms -- check behavior with bloated index ANALYZE updates; ANALYZE Time: 254,917 ms EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 50 ORDER BY "time" DESC LIMIT 1; QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.56..3.38 rows=1 width=36) (actual time=0.814..0.814 rows=1 loops=1) Buffers: shared read=5 -> Index Scan Backward using updates_driver_id_time_idx on updates (cost=0.56..362993.08 rows=128650 width=36) (actual time=0.812..0.812 rows=1 loops=1) Index Cond: (driver_id = 50) Buffers: shared read=5 Planning time: 1.785 ms Execution time: 0.882 ms (7 rows) Time: 4,635 ms EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 100 ORDER BY "time" DESC LIMIT 1; QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------ Limit (cost=0.43..1.91 rows=1 width=36) (actual time=21486.015..21486.015 rows=1 loops=1) Buffers: shared hit=39618 read=160454 written=592 -> Index Scan Backward using updates_time_idx on updates (cost=0.43..691283.45 rows=469134 width=36) (actual time=21486.014..21486.014 rows=1 loops=1) Filter: (driver_id = 100) Rows Removed by Filter: 14500000 Buffers: shared hit=39618 read=160454 written=592 Planning time: 0.171 ms Execution time: 21486.068 ms (8 rows) Time: 21486,905 ms -- rebuild index with default fillfactor ALTER INDEX updates_driver_id_time_idx SET (fillfactor = 90); ALTER INDEX Time: 0,682 ms REINDEX INDEX updates_driver_id_time_idx; REINDEX Time: 23559,530 ms -- recheck index sizes, updates_driver_id_idx should look pretty simmilar to others. SELECT relname, relpages FROM pg_class WHERE relname LIKE 'updates%'; relname | relpages -----------------------------+---------- updates | 129167 updates_driver_id_time_idx | 59684 updates_id_seq | 1 updates_pkey | 42502 updates_time_idx | 42502 updates_vehicle_id_time_idx | 59684 (6 rows) Time: 0,452 ms -- check behavior with regular sized index EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 50 ORDER BY "time" DESC LIMIT 1; QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.56..3.25 rows=1 width=36) (actual time=0.037..0.037 rows=1 loops=1) Buffers: shared read=5 -> Index Scan Backward using updates_driver_id_time_idx on updates (cost=0.56..345821.08 rows=128650 width=36) (actual time=0.037..0.037 rows=1 loops=1) Index Cond: (driver_id = 50) Buffers: shared read=5 Planning time: 0.205 ms Execution time: 0.052 ms (7 rows) Time: 0,562 ms EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM updates WHERE driver_id = 100 ORDER BY "time" DESC LIMIT 1; QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.56..1.69 rows=1 width=36) (actual time=0.032..0.033 rows=1 loops=1) Buffers: shared hit=2 read=3 -> Index Scan Backward using updates_driver_id_time_idx on updates (cost=0.56..529197.34 rows=469133 width=36) (actual time=0.032..0.032 rows=1 loops=1) Index Cond: (driver_id = 100) Buffers: shared hit=2 read=3 Planning time: 0.074 ms Execution time: 0.046 ms (7 rows) Time: 0,312 ms --Apple-Mail=_BD637ACD-26FE-4307-9F70-F42C158BD872 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8


El = 11 dic 2016, a las 7:04, Daniel Blanch Bataller <daniel.blanch.bataller@gmail.com> escribi=C3=B3:
Hi = all,

Thomas is absolutely right, the = distribution I synthetically made, had 6M records but very old, 9M old, = as you can see it had to skip 9M records before finding a suitable = record using time index.

EXPLAIN (ANALYZE, = BUFFERS) SELECT * FROM updates WHERE driver_id =3D 100 ORDER BY "time" = DESC LIMIT 1;
=             &n= bsp;           &nbs= p;            =             &n= bsp;           &nbs= p;          QUERY = PLAN
---------------------------------------------------------------= --------------------------------------------------------------------------= -------------------
Limit  (cost=3D0.44..0.65 rows=3D1= width=3D36) (actual time=3D3827.807..3827.807 rows=3D1 loops=3D1)
  Buffers: shared hit=3D24592 read=3D99594 = written=3D659
  ->  Index Scan Backward = using updates_time_idx on updates  (cost=3D0.44..1284780.53 = rows=3D6064800 width=3D36) (actual time=3D3827.805..3827.805 rows=3D1 = loops=3D1)
=         Filter: (driver_id =3D = 100)
        Rows = Removed by Filter: 9000000
=         Buffers: shared = hit=3D24592 read=3D99594 written=3D659
Planning time: = 0.159 ms
Execution time: 3827.846 ms
(8 = rows)


Here you have my tests = where I was able to reproduce the problem using default settings on 9.6, = 9.5 and 9.3. 9.6 and 9.5 choose the wrong index, while 9.3 didn=E2=80=99t.= (update: 9.5 didn=E2=80=99t fail last time)

<test_bad_index_choice.= sql><bad_idx_choice.9.6.out= ><bad_idx_choice.9.5.out= ><bad_idx_choice.9.3.out= >

However when I tried to add = more than one value with this strange distribution ~ 30% of distribution = to one value the index bad choice problem didn=E2=80=99t happen again in = none of the different versions.

I Hope this = helps. Regards,

Daniel Blanch.


El 10 dic 2016, a las 21:34, Tomas Vondra <tomas.vondra@2ndquadrant.com> escribi=C3=B3:

Hi,

On 12/10/2016 = 12:51 AM, Tom Lane wrote:
Eric Jiang <eric@doublemap.com> writes:
I have a query that I *think* should use a = multicolumn index, but
sometimes isn't, resulting in slow = queries.

I tried to duplicate = this behavior, without success.  Are you running
with = nondefault planner parameters?


My guess is this is a case of = LIMIT the matching rows are uniformly distributed in the input data. The = planner likely concludes that for a driver with a lot of data we'll find = the first row using ix_updates_time very quickly, and that it will be = cheaper than inspecting the larger multi-column index. But imagine a = driver with a lots of data long time ago. That breaks the LIMIT fairly = quickly.

regards

--
Tomas Vondra =             &n= bsp;    http://www.2ndQuadrant.com
PostgreSQL = Development, 24x7 Support, Remote DBA, Training & Services


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


= --Apple-Mail=_BD637ACD-26FE-4307-9F70-F42C158BD872-- --Apple-Mail=_7896F8AE-B4F3-47A2-AB4B-3218038FF64C--