Message-Id: <1416093844.656860.191454497.0A5F975F@webmail.messagingengine.com>
From: Yuri Kunde Schlesner <yuriks+lists@yuriks.net>
To: pgsql-performance@postgresql.org
MIME-Version: 1.0
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain; charset="ISO-8859-1"
Subject: Re: Plan uses wrong index,
 preferring to scan pkey index instead
Date: Sat, 15 Nov 2014 21:24:04 -0200
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Looks like my client mangled (reflowed) the command outputs, so I
requoted them in this message sent as plain text. In case it happens
again I also posted them to a pastebin here:
https://gist.github.com/yuriks/e86fb0c3cefb8d348c34

--yuriks


On Sat, Nov 15, 2014, at 09:16 PM, Yuri Kunde Schlesner wrote:
> Hi all,
>=20
> Excuse me if I made any mistakes, as this is my first time posting to a m=
ailing list.
>=20
> I'm a user of Quassel, a IRC client that uses postgres a backing store fo=
r IRC logs and am running into heavy intermittent performance problems. I'v=
e tracked it down to a query that takes a very long time (around 4 minutes)=
 to complete when its data isn't cached.
>=20
> This is the layout of the table being queried and EXPLAIN ANALYZE result =
for the problematic query:
>=20
> quassel=3D> \d backlog
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Table "public.backlog"
> =A0 Column=A0=A0 |=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Type=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0 |=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0=A0 Modifiers
> -----------+-----------------------------+-------------------------------=
------------------------------
> =A0messageid | integer=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0 | not null default nextval('backlog_messageid_seq'::regclass)
> =A0time=A0=A0=A0=A0=A0 | timestamp without time zone | not null
> =A0bufferid=A0 | integer=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0 | not null
> =A0type=A0=A0=A0=A0=A0 | integer=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0 | not null
> =A0flags=A0=A0=A0=A0 | integer=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0 | not null
> =A0senderid=A0 | integer=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0 | not null
> =A0message=A0=A0 | text=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0 |
> Indexes:
> =A0=A0=A0 "backlog_pkey" PRIMARY KEY, btree (messageid)
> =A0=A0=A0 "backlog_bufferid_idx" btree (bufferid, messageid DESC)
> Foreign-key constraints:
> =A0=A0=A0 "backlog_bufferid_fkey" FOREIGN KEY (bufferid) REFERENCES buffe=
r(bufferid) ON DELETE CASCADE
> =A0=A0=A0 "backlog_senderid_fkey" FOREIGN KEY (senderid) REFERENCES sende=
r(senderid) ON DELETE SET NULL
>=20
> quassel=3D> explain (analyze, buffers) SELECT messageid, time,=A0 type, f=
lags, sender, message
> FROM backlog
> LEFT JOIN sender ON backlog.senderid =3D sender.senderid
> WHERE bufferid =3D 39
> ORDER BY messageid DESC LIMIT 10;
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 QU=
ERY PLAN
> -------------------------------------------------------------------------=
---------------------------------------------------------------------------=
-----------
> =A0Limit=A0 (cost=3D0.72..37.78 rows=3D10 width=3D102) (actual time=3D154=
410.353..154410.424 rows=3D10 loops=3D1)
> =A0=A0 Buffers: shared hit=3D13952 read=3D19244
> =A0=A0 ->=A0 Nested Loop Left Join=A0 (cost=3D0.72..145800.61 rows=3D3934=
5 width=3D102) (actual time=3D154410.350..154410.414 rows=3D10 loops=3D1)
> =A0=A0=A0=A0=A0=A0=A0=A0 Buffers: shared hit=3D13952 read=3D19244
> =A0=A0=A0=A0=A0=A0=A0=A0 ->=A0 Index Scan Backward using backlog_pkey on =
backlog=A0 (cost=3D0.43..63830.21 rows=3D39345 width=3D62) (actual time=3D1=
54410.327..154410.341 rows=3D10 loops=3D1)
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Filter: (bufferid =3D 39)
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Rows Removed by Filter: 1248320
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Buffers: shared hit=3D13921 re=
ad=3D19244
> =A0=A0=A0=A0=A0=A0=A0=A0 ->=A0 Index Scan using sender_pkey on sender=A0 =
(cost=3D0.29..2.07 rows=3D1 width=3D48) (actual time=3D0.005..0.005 rows=3D=
1 loops=3D10)
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Index Cond: (backlog.senderid =
=3D senderid)
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Buffers: shared hit=3D31
> =A0Total runtime: 154410.477 ms
> (12 rows)
>=20
> This plan is consistently chosen, even after ANALYZEing and REINDEXing th=
e table. It looks like Postgres is opting to do a sequential scan of the ba=
cklog_pkey index, filtering rows by bufferid, instead of directly using the=
 backlog_bufferid_idx index that directly maps to the operation being made =
by the query. I was advised on IRC to try dropping the backlog_pkey index t=
o force Postgres to use the correct one, and that uses a better plan:
>=20
> quassel=3D> begin;
> BEGIN
> quassel=3D> alter table backlog drop constraint backlog_pkey;
> ALTER TABLE
> quassel=3D> explain analyze SELECT messageid, time,=A0 type, flags, sende=
r, message
> FROM backlog
> LEFT JOIN sender ON backlog.senderid =3D sender.senderid
> WHERE bufferid =3D 39
> ORDER BY messageid DESC LIMIT 10;
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 QUERY PLAN
> -------------------------------------------------------------------------=
---------------------------------------------------------------------------=
--
> =A0Limit=A0 (cost=3D0.72..40.50 rows=3D10 width=3D102) (actual time=3D63.=
826..162.134 rows=3D10 loops=3D1)
> =A0=A0 ->=A0 Nested Loop Left Join=A0 (cost=3D0.72..156518.91 rows=3D3934=
5 width=3D102) (actual time=3D63.823..162.126 rows=3D10 loops=3D1)
> =A0=A0=A0=A0=A0=A0=A0=A0 ->=A0 Index Scan using backlog_bufferid_idx on b=
acklog=A0 (cost=3D0.43..74548.51 rows=3D39345 width=3D62) (actual time=3D63=
.798..63.814 rows=3D10 loops=3D1)
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Index Cond: (bufferid =3D 39)
> =A0=A0=A0=A0=A0=A0=A0=A0 ->=A0 Index Scan using sender_pkey on sender=A0 =
(cost=3D0.29..2.07 rows=3D1 width=3D48) (actual time=3D8.532..9.825 rows=3D=
1 loops=3D10)
> =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Index Cond: (backlog.senderid =
=3D senderid)
> =A0Total runtime: 162.377 ms
> (7 rows)
>=20
> quassel=3D> rollback;
> ROLLBACK
>=20
> (This query was also run with empty caches.) bufferid=3D39 in particular =
has this issue because it hasn't had any messages posted to for a long time=
, so scanning backlog upwards will take a long time to gather 10 messages f=
rom it. In contrast, most other bufferid's have their messages interleaved =
on the last entries of backlog. I believe this might be throwing Postgres' =
estimates off.
>=20
> Does anyone know if there's any tweaking I can do in Postgres so that it =
uses the appropriate plan?
>=20
> Info about my setup:
> PostgreSQL 9.3.5 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.9.1=
, 64-bit
> Arch Linux, PostgreSQL installed from the official repositories, running =
inside a Xen HVM VPS.
> Connecting to PostgreSQL using psql via UNIX socket.
> Changed options: (locale-related ones omitted)
> =A0 listen_addresses =3D=A0
> =A0 max_stack_depth =3D 2MB
> =A0 shared_buffers =3D=A0256MB (Issue is also present with default value)
> Total RAM: 1GB
>=20
>=20
> Thanks,
> --yuriks


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