Slow performance on postgres query with count/sort

Question

I've inherited an Django/postgres app from another developer and I'm finding many of the queries are very slow. I've spent a lot of time correctly organising/normalising the data which was not done before which has helped a lot but some queries can still take minutes.

In particular we do a number of queries to summarise the data by showing a count of images according to particular criteria and one example of this is shown below - Top images by hashtag.

The query returns the hashtags with highest number of images. The image-hashtag relationship is a many-to-many relationship across a join table. There are various other WHERE criteria that can be applied to this query but this is the simplest example - as a minimum we filter by created timestamp and query_id field.

pg version: PostgreSQL 9.6.11 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.3 20140911 (Red Hat 4.8.3-9), 64-bit

hardware: AWS RDS Postgres db.t2.large recently upgraded from db.t2.medium which seems to have eliminated a recheck conditions step in many queries

query:

SELECT
    base_hashtag.*,
    COUNT(DISTINCT base_image.id)
FROM
    base_hashtag
    JOIN base_imagehashtag ON base_hashtag.id = base_imagehashtag.hashtag_id
    JOIN base_image ON base_imagehashtag.image_id = base_image.id
WHERE
    base_image.query_id = '566591d4-33a3-4a96-a2d9-99e7bd625c18'
    AND base_image.created > 1548979200
    AND base_image.created < 1551398400
    AND base_hashtag.id <> 1
GROUP BY
    base_hashtag.id
ORDER BY
    base_hashtag.count DESC
LIMIT
    40
;

table definitions: follows is a simplified subset of the tables fields for the example query. there are a number of potentially redundant indexes but I don't think they should affect select performance and I intend to clear these up in time

- Table: public.base_image

CREATE TABLE public.base_image
(
    id integer NOT NULL DEFAULT nextval('base_image_id_seq'::regclass),
    image_url character varying(100000) COLLATE pg_catalog."default",
    username character varying(100000) COLLATE pg_catalog."default",
    created integer,
    location_id character varying(10000000) COLLATE pg_catalog."default",
    query_id uuid,
    CONSTRAINT base_image_pkey PRIMARY KEY (id),
    CONSTRAINT base_image_query_id_b2da2903_fk_base_query_pk_id FOREIGN KEY (query_id)
        REFERENCES public.base_query (pk_id) MATCH SIMPLE
        ON UPDATE NO ACTION
        ON DELETE NO ACTION
        DEFERRABLE INITIALLY DEFERRED
)
WITH (
    OIDS = FALSE
)
TABLESPACE pg_default;

CREATE INDEX base_image_0bbeda9c
    ON public.base_image USING btree
    (query_id)
    TABLESPACE pg_default;

CREATE INDEX base_image_created_idx
    ON public.base_image USING btree
    (created)
    TABLESPACE pg_default;

CREATE INDEX base_image_created_imageid_queryid
    ON public.base_image USING btree
    (id, created, query_id)
    TABLESPACE pg_default;

CREATE INDEX base_image_id_idx
    ON public.base_image USING btree
    (id)
    TABLESPACE pg_default;

CREATE INDEX base_image_id_query_id_idx
    ON public.base_image USING btree
    (id, query_id)
    TABLESPACE pg_default;

CREATE UNIQUE INDEX base_image_query_id_id_idx
    ON public.base_image USING btree
    (query_id, id)
    TABLESPACE pg_default;

CREATE INDEX base_image_query_id_idx
    ON public.base_image USING btree
    (query_id)
    TABLESPACE pg_default;

-- Table: public.base_imagehashtag

CREATE TABLE public.base_imagehashtag
(
    id integer NOT NULL DEFAULT nextval('base_imagehashtag_id_seq'::regclass),
    hashtag_id integer NOT NULL,
    image_id integer NOT NULL,
    CONSTRAINT base_imagehashtag_pkey PRIMARY KEY (id),
    CONSTRAINT base_imagehashtag_image_id_96133dcc_uniq UNIQUE (image_id, hashtag_id),
    CONSTRAINT base_imagehashtag_hashtag_id_0d819bb9_fk_base_hashtag_id FOREIGN KEY (hashtag_id)
        REFERENCES public.base_hashtag (id) MATCH SIMPLE
        ON UPDATE NO ACTION
        ON DELETE NO ACTION
        DEFERRABLE INITIALLY DEFERRED,
    CONSTRAINT base_imagehashtag_image_id_79e99aa4_fk_base_image_id FOREIGN KEY (image_id)
        REFERENCES public.base_image (id) MATCH SIMPLE
        ON UPDATE NO ACTION
        ON DELETE NO ACTION
        DEFERRABLE INITIALLY DEFERRED
)
WITH (
    OIDS = FALSE
)
TABLESPACE pg_default;

CREATE INDEX base_imagehashtag_e4858d5c
    ON public.base_imagehashtag USING btree
    (hashtag_id)
    TABLESPACE pg_default;

CREATE INDEX base_imagehashtag_f33175e6
    ON public.base_imagehashtag USING btree
    (image_id)
    TABLESPACE pg_default;

CREATE INDEX base_imagehashtag_imageid_hashtag_id
    ON public.base_imagehashtag USING btree
    (hashtag_id, image_id)
    TABLESPACE pg_default;

-- Table: public.base_hashtag

CREATE TABLE public.base_hashtag
(
    id integer NOT NULL DEFAULT nextval('base_hashtag_id_seq'::regclass),
    name character varying(255) COLLATE pg_catalog."default" NOT NULL,
    CONSTRAINT base_hashtag_pkey PRIMARY KEY (id),
    CONSTRAINT base_hashtag_name_key UNIQUE (name)
)
WITH (
    OIDS = FALSE
)
TABLESPACE pg_default;

CREATE INDEX base_hashtag_name_a8f89285_like
    ON public.base_hashtag USING btree
    (name COLLATE pg_catalog."default" varchar_pattern_ops)
    TABLESPACE pg_default;

cardinalities: approximately

• base_image: 23M
• base_hashtag: 5M
• base_imagehashtag: 211M

query plan:

Limit  (cost=7895851.20..7895851.30 rows=40 width=36) (actual time=188165.607..188165.641 rows=40 loops=1)
   Buffers: shared hit=137658 read=1129357, temp read=652059 written=652045
   ->  Sort  (cost=7895851.20..7904963.31 rows=3644846 width=36) (actual time=188165.605..188165.618 rows=40 loops=1)
         Sort Key: (count(base_hashtag.*)) DESC
         Sort Method: top-N heapsort  Memory: 28kB
         Buffers: shared hit=137658 read=1129357, temp read=652059 written=652045
         ->  GroupAggregate  (cost=7434552.18..7780638.93 rows=3644846 width=36) (actual time=178023.985..188051.536 rows=290908 loops=1)
               Group Key: base_hashtag.id
               Buffers: shared hit=137658 read=1129357, temp read=652059 written=652045
               ->  Merge Join  (cost=7434552.18..7716854.12 rows=3644846 width=68) (actual time=178023.656..186172.736 rows=3812014 loops=1)
                     Merge Cond: (base_hashtag.id = base_imagehashtag.hashtag_id)
                     Buffers: shared hit=137658 read=1129357, temp read=652059 written=652045
                     ->  Index Scan using base_hashtag_pkey on base_hashtag  (cost=0.43..205295.87 rows=5894881 width=64) (actual time=0.014..1961.031 rows=4341714 loops=1)
                           Filter: (id <> 1)
                           Rows Removed by Filter: 1
                           Buffers: shared hit=39911
                     ->  Materialize  (cost=7433940.57..7452164.81 rows=3644847 width=8) (actual time=177776.569..181299.695 rows=4055074 loops=1)
                           Buffers: shared hit=97747 read=1129357, temp read=652059 written=652045
                           ->  Sort  (cost=7433940.57..7443052.69 rows=3644847 width=8) (actual time=177776.566..179584.317 rows=4055074 loops=1)
                                 Sort Key: base_imagehashtag.hashtag_id
                                 Sort Method: external merge  Disk: 71336kB
                                 Buffers: shared hit=97747 read=1129357, temp read=652059 written=652045
                                 ->  Hash Join  (cost=1201261.72..6937033.15 rows=3644847 width=8) (actual time=46237.509..174816.562 rows=4055074 loops=1)
                                       Hash Cond: (base_imagehashtag.image_id = base_image.id)
                                       Buffers: shared hit=97747 read=1129357, temp read=631968 written=631954
                                       ->  Seq Scan on base_imagehashtag  (cost=0.00..3256836.88 rows=211107488 width=8) (actual time=0.103..72452.659 rows=211056752 loops=1)
                                             Buffers: shared hit=16405 read=1129357
                                       ->  Hash  (cost=1194732.58..1194732.58 rows=397931 width=4) (actual time=1284.293..1284.294 rows=261208 loops=1)
                                             Buckets: 131072  Batches: 8  Memory Usage: 2174kB
                                             Buffers: shared hit=81342, temp written=667
                                             ->  Bitmap Heap Scan on base_image  (cost=180976.73..1194732.58 rows=397931 width=4) (actual time=950.553..1191.553 rows=261208 loops=1)
                                                   Recheck Cond: ((created > 1548979200) AND (created < 1551398400) AND (query_id = '566591d4-33a3-4a96-a2d9-99e7bd625c18'::uuid))
                                                   Rows Removed by Index Recheck: 179762
                                                   Heap Blocks: exact=8033 lossy=43452
                                                   Buffers: shared hit=81342
                                                   ->  BitmapAnd  (cost=180976.73..180976.73 rows=397931 width=0) (actual time=948.947..948.947 rows=0 loops=1)
                                                         Buffers: shared hit=29857
                                                         ->  Bitmap Index Scan on base_image_created_idx  (cost=0.00..32677.36 rows=1488892 width=0) (actual time=171.198..171.198 rows=1484511 loops=1)
                                                               Index Cond: ((created > 1548979200) AND (created < 1551398400))
                                                               Buffers: shared hit=5154
                                                         ->  Bitmap Index Scan on base_image_query_id_idx  (cost=0.00..148100.16 rows=6159946 width=0) (actual time=760.218..760.219 rows=6274189 loops=1)
                                                               Index Cond: (query_id = '566591d4-33a3-4a96-a2d9-99e7bd625c18'::uuid)
                                                               Buffers: shared hit=24703
 Planning time: 0.689 ms
 Execution time: 188176.901 ms

As you can see the query can take minutes to complete. We use caching at the app level but users are often submitting unique queries so this only helps a little. There are many of these type of queries occurring simultaneously to populate a dashboard which puts a huge load on the database. I'm not expecting an instant response but hoping it would be possible to reduce to seconds rather than minutes.

I appreciate that a large amount of data is involved in this query because i presume it has perform all hashtag counts before it can sort the results to get the highest.

I know there's a lot of information about how to tune postgres but I am hoping someone might be able to see something obviously inefficient in this setup and point me in the right direction so I can start experimenting.

Edit

The same query with set enable_seqscan=off

    Limit  (cost=8386776.05..8386776.15 rows=40 width=36) (actual time=75981.675..75981.712 rows=40 loops=1)
   Buffers: shared hit=43238 read=414995, temp read=20088 written=20088
   ->  Sort  (cost=8386776.05..8395626.09 rows=3540015 width=36) (actual time=75981.674..75981.687 rows=40 loops=1)
         Sort Key: (count(base_hashtag.*)) DESC
         Sort Method: top-N heapsort  Memory: 28kB
         Buffers: shared hit=43238 read=414995, temp read=20088 written=20088
         ->  GroupAggregate  (cost=7941630.37..8274877.45 rows=3540015 width=36) (actual time=64678.453..75862.227 rows=290908 loops=1)
               Group Key: base_hashtag.id
               Buffers: shared hit=43238 read=414995, temp read=20088 written=20088
               ->  Merge Join  (cost=7941630.37..8212927.18 rows=3540015 width=68) (actual time=64678.087..73943.416 rows=3812014 loops=1)
                     Merge Cond: (base_imagehashtag.hashtag_id = base_hashtag.id)
                     Buffers: shared hit=43238 read=414995, temp read=20088 written=20088
                     ->  Sort  (cost=7939229.85..7948079.89 rows=3540015 width=8) (actual time=64541.756..66215.773 rows=4055074 loops=1)
                           Sort Key: base_imagehashtag.hashtag_id
                           Sort Method: external merge  Disk: 71344kB
                           Buffers: shared hit=35902 read=375789, temp read=20088 written=20088
                           ->  Merge Join  (cost=34646.33..7457355.98 rows=3540015 width=8) (actual time=58023.450..61805.075 rows=4055074 loops=1)
                                 Merge Cond: (base_image.id = base_imagehashtag.image_id)
                                 Buffers: shared hit=35902 read=375789
                                 ->  Index Only Scan using base_image_country_created_imageid_query_id on base_image  (cost=0.56..268172.32 rows=384264 width=4) (actual time=217.707..832.100 rows=261208 loops=1)
                                       Index Cond: ((query_id = '566591d4-33a3-4a96-a2d9-99e7bd625c18'::uuid) AND (created > 1548979200) AND (created < 1551398400))
                                       Heap Fetches: 0
                                       Buffers: shared hit=35724 read=9321
                                 ->  Index Only Scan using base_imagehashtag_image_id_96133dcc_uniq on base_imagehashtag  (cost=0.57..6621360.73 rows=212655744 width=8) (actual time=3.366..34853.999 rows=113968400 loops=1)
                                       Heap Fetches: 0
                                       Buffers: shared hit=178 read=366468
                     ->  Index Scan using base_hashtag_pkey on base_hashtag  (cost=0.43..205820.87 rows=5910767 width=64) (actual time=0.041..3822.781 rows=7862820 loops=1)
                           Filter: (id <> 1)
                           Rows Removed by Filter: 1
                           Buffers: shared hit=7336 read=39206
 Planning time: 0.609 ms
 Execution time: 75991.874 ms

Edit 2

The same query with enable_mergejoin=off and enable_hashjoin=off

Limit  (cost=44144721.02..44144721.12 rows=40 width=36) (actual time=25487.908..25487.942 rows=40 loops=1)
   Buffers: shared hit=17297009 read=83, temp read=88580 written=88580
   ->  Sort  (cost=44144721.02..44154290.01 rows=3827596 width=36) (actual time=25487.906..25487.915 rows=40 loops=1)
         Sort Key: (count(base_hashtag.*)) DESC
         Sort Method: top-N heapsort  Memory: 28kB
         Buffers: shared hit=17297009 read=83, temp read=88580 written=88580
         ->  GroupAggregate  (cost=43947180.16..44023732.08 rows=3827596 width=36) (actual time=21791.076..25377.264 rows=290908 loops=1)
               Group Key: base_hashtag.id
               Buffers: shared hit=17297009 read=83, temp read=88580 written=88580
               ->  Sort  (cost=43947180.16..43956749.15 rows=3827596 width=68) (actual time=21790.924..23315.027 rows=3812014 loops=1)
                     Sort Key: base_hashtag.id
                     Sort Method: external merge  Disk: 259024kB
                     Buffers: shared hit=17297009 read=83, temp read=88580 written=88580
                     ->  Nested Loop  (cost=1.56..43214685.68 rows=3827596 width=68) (actual time=2.965..17525.982 rows=3812014 loops=1)
                           Buffers: shared hit=17297009 read=83
                           ->  Nested Loop  (cost=1.13..15358809.52 rows=3827597 width=8) (actual time=2.508..3727.578 rows=4055074 loops=1)
                                 Buffers: shared hit=1060857 read=42
                                 ->  Index Only Scan using base_image_queryid_created_id on base_image  (cost=0.56..17668.67 rows=417605 width=4) (actual time=0.018..85.571 rows=261208 loops=1)
                                       Index Cond: ((query_id = '566591d4-33a3-4a96-a2d9-99e7bd625c18'::uuid) AND (created > 1548979200) AND (created < 1551398400))
                                       Heap Fetches: 0
                                       Buffers: shared hit=4205
                                 ->  Index Only Scan using base_imagehashtag_image_id_96133dcc_uniq on base_imagehashtag  (cost=0.57..28.74 rows=800 width=8) (actual time=0.002..0.006 rows=16 loops=261208)
                                       Index Cond: (image_id = base_image.id)
                                       Heap Fetches: 0
                                       Buffers: shared hit=1056652 read=42
                           ->  Index Scan using base_hashtag_pkey on base_hashtag  (cost=0.43..7.27 rows=1 width=64) (actual time=0.002..0.002 rows=1 loops=4055074)
                                 Index Cond: (id = base_imagehashtag.hashtag_id)
                                 Filter: (id <> 1)
                                 Rows Removed by Filter: 0
                                 Buffers: shared hit=16236152 read=41
 Planning time: 0.507 ms
 Execution time: 25527.201 ms

Answer 1

Since you are willing to use cached query results, one possibility is to create a materialized view which will precompute the values for all base_image.query_id at one time, rather the compute each one at need and storing it. It looks like computing the value for all of them at once should not be much more time consuming than just doing it for a single one. But this would only work if the values that base_image.created is compared against are stable, or at least follow a predictable pattern. So something like:

create materialized view foobar as SELECT
    base_image.query_id,
    base_hashtag.*,
    COUNT(DISTINCT base_image.id) as dist_count
FROM
    base_hashtag
    JOIN base_imagehashtag ON base_hashtag.id = base_imagehashtag.hashtag_id
    JOIN base_image ON base_imagehashtag.image_id = base_image.id
WHERE
    base_image.created > 1548979200
    AND base_image.created < 1551398400
    AND base_hashtag.id <> 1
GROUP BY
    base_image.query_id,
    base_hashtag.id

To stick with the query itself, it looks like your work_mem is too low for this type of query. This is indicated both by

Buckets: 131072 Batches: 8 Memory Usage: 2174kB

and

Heap Blocks: exact=8033 lossy=43452

If you can afford to increase the work_mem enough that you can do the hash in a single batch, and so there are no lossy blocks in the bitmap scan, that would be a help some. (Although the bitmap scan is not part of the bottleneck to start with, so it can't really be a massive help).

An index on base_image (query_id, created, id) could help a bit by avoiding the BitmapAnd and by doing a index-only-scan, but again it can only help so much because getting the data from "base_image" is not the slowest step.

I don't think you are going to get drastic improvements without getting rid of the massive "Seq Scan on base_imagehashtag". I would like to see the EXPLAIN (ANALYZE,BUFFERS) of the query after you set enable_seqscan=off, to see what it chooses then. Even if that ends up being slower, seeing what it does might provide some clues.

Another thing, upgrading from 9.6 to v11 would open up parallel query execution. That wouldn't increase the efficiency but would improve the latency if you don't have multiple queries at the same. Although with a db.t2.large, that might not be much help. In my experience hyperthreading is useless in this situation, so 2 vCPU probably just means 1 CPU, so nothing to parallelize to.

---

Looking at the execution when running with enable_seqscan=off, it switches from scanning the entire table "base_imagehashtag" to scanning the entirety of one of its indexes. And that was an improvement, but now scanning that entire index is the bottleneck instead, so it is not a huge improvement.

I was hoping to see a nested loop over that index, not a merge join of it. So can you show another explain (analyze, buffers) after set enable_mergejoin=off? That is going to better target what I wanted to see than enable_seqscan did. The nested loop risks having horrible performance if run with a cold cache, but might have much better performance on a hot cache, which is what we want to find out. Since scanning the full index is still quite slow and the bottleneck, I think the nested loop is about the only option you have left, before resorting to either a hardware upgrade or refactoring your data representation.

If you just want to get it to use the 75 second plan rather than 180 second plan in production, there are a several avenues to pursue. One is just to set enable_seqscan=off just before running the query and resetting it afterwards, if your application/framework/abstraction layer offers this flexibility. It is nice to fix the underlying problem, but sometimes you have to pick your battles and take the easier way out.

One suspicious line is this one:

-> Index Only Scan using base_imagehashtag_image_id_96133dcc_uniq on base_imagehashtag (cost=0.57..6621360.73 rows=212655744 width=8) (actual time=3.366..34853.999 rows=113968400 loops=1)

Why is it finding half as many rows as it is expecting? If it got this estimate correct, then the planner would be finding this plan faster, and so should use this plan without resorting to tricks. Are your statistics up to date (e.g. vacuum analyze often enough)? The only other thing I can think of here is that the scan of base_image_country_created_imageid_query_id for your given "query_id" and "created" values only returned values of base_image.id from the lower half of the full range of base_image.id values, so that the other half of the merge join got to quit early. But if this is the case, I don't know how to exploit that fact to get the planner to do a better job. Plus then the actual performance would depend on what exact parameter values were used in the query.

I think another way to encourage the full index scan over the seq scan would be to lower the value of "cpu_index_tuple_cost", relative to "cpu_tuple_cost". I've recently been thinking that maybe the default setting of "cpu_index_tuple_cost" is to high anyway. How much would you have to lower "cpu_index_tuple_cost" to get it to switch plans, if it ever does?