From: "Mike Sofen" <msofen@runbox.com>
To: <pgsql-performance@postgresql.org>
References: 
 <CAP3LSG7iwYS6V555qqjNBvuoi3gsMhTU-nN7PcfxJhHhJVbXRw@mail.gmail.com>
 <CAP3LSG7PfEfaK5V6rT7rgP1MjLED-wnqGY5Qtp5Gx0s64L16tg@mail.gmail.com>
In-Reply-To: 
 <CAP3LSG7PfEfaK5V6rT7rgP1MjLED-wnqGY5Qtp5Gx0s64L16tg@mail.gmail.com>
Subject: Re: Unexpected expensive index scan
Date: Tue, 27 Sep 2016 17:41:55 -0700
Message-ID: <00e901d21921$1e647180$5b2d5480$@runbox.com>
MIME-Version: 1.0
Content-Type: multipart/alternative;
	boundary="----=_NextPart_000_00EA_01D218E6.72074730"
Thread-Index: AQJqaizE6AYNkKf1PF1s+az2031ZTwFZAL7Cn1KhGwA=
Content-Language: en-us
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

This is a multipart message in MIME format.

------=_NextPart_000_00EA_01D218E6.72074730
Content-Type: text/plain;
	charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

From: Jake Nielsen    Sent: Tuesday, September 27, 2016 5:22 PM


the query

SELECT * FROM SyncerEvent WHERE ID > 12468 AND propogatorId NOT IN =
('"d8130ab9!-66d0!-4f13!-acec!-a9556362f0ad"') AND conflicted !=3D 1 AND =
userId =3D '57dc984f1c87461c0967e228' ORDER BY ID LIMIT 4000;^

=20

On Tue, Sep 27, 2016 at 5:02 PM, Jake Nielsen <jake.k.nielsen@gmail.com =
<mailto:jake.k.nielsen@gmail.com> > wrote:

I've got a query that takes a surprisingly long time to run, and I'm =
having a really rough time trying to figure it out.

=20

Before I get started, here are the specifics of the situation:

=20

Here is the table that I'm working with (apologies for spammy indices, =
I've been throwing shit at the wall)

                            Table "public.syncerevent"

    Column    |  Type   |                        Modifiers               =
         =20

--------------+---------+------------------------------------------------=
----------

 id           | bigint  | not null default =
nextval('syncerevent_id_seq'::regclass)

 userid       | text    |=20

 event        | text    |=20

 eventid      | text    |=20

 originatorid | text    |=20

 propogatorid | text    |=20

 kwargs       | text    |=20

 conflicted   | integer |=20

Indexes:

    "syncerevent_pkey" PRIMARY KEY, btree (id)

    "syncereventidindex" UNIQUE, btree (eventid)

    "anothersyncereventidindex" btree (userid)

    "anothersyncereventidindexwithascending" btree (userid, id)

    "asdfasdgasdf" btree (userid, id DESC)

    "syncereventuseridhashindex" hash (userid)

=20

To provide some context, as per the wiki,=20

there are 3,290,600 rows in this table.=20

It gets added to frequently, but never deleted from.=20

The "kwargs" column often contains mid-size JSON strings (roughly 30K =
characters on average)

As of right now, the table has 53 users in it. About 20% of those have a =
negligible number of events, but the rest of the users have a fairly =
even smattering.

=20

EXPLAIN (ANALYZE, BUFFERS) says:

                                                                         =
 QUERY PLAN                                                              =
           =20

-------------------------------------------------------------------------=
-------------------------------------------------------------------------=
------------

 Limit  (cost=3D0.43..1218.57 rows=3D4000 width=3D615) (actual =
time=3D3352.390..3403.572 rows=3D4000 loops=3D1)  Buffers: shared =
hit=3D120244 read=3D160198

   ->  Index Scan using syncerevent_pkey on syncerevent  =
(cost=3D0.43..388147.29 rows=3D1274560 width=3D615) (actual =
time=3D3352.386..3383.100 rows=3D4000 loops=3D1)

         Index Cond: (id > 12468)

         Filter: ((propogatorid <> =
'"d8130ab9!-66d0!-4f13!-acec!-a9556362f0ad"'::text) AND (conflicted <> =
1) AND (userid =3D '57dc984f1c87461c0967e228'::text))

         Rows Removed by Filter: 1685801

         Buffers: shared hit=3D120244 read=3D160198

 Planning time: 0.833 ms

 Execution time: 3407.633 ms

(9 rows)

If it matters/interests you, here is my underlying confusion: