0

Running Postgres 13.8 on Ubuntu 20, I have a complicated-looking, yet relatively straightforward query. For some reason, the optimizer is wrong about the expected row count of the joins and is using a nested loop when it shouldn't. You can see that in the nested loop statements in the explain output, it's off by an order of magnitude on each of the row counts.

This query takes about 2,500ms to execute. But when I re-run it with set enable_nestloop = False it runs in about 150ms. Keeping that setting on is an option of course, but it feels like a sledgehammer and I'm trying to understand if there's a way to refactor the query instead.

Each table has several hundred thousand rows, and I've explicitly run vacuum analyze as part of my testing.

Query:

SELECT 
    t3."bundle_id" 
FROM 
    "user_rec_scores" AS t0 INNER JOIN 
    "reviews" AS r1 ON t0."network_user_id" = r1."recd_by_id" INNER JOIN 
    "items" AS p2 ON r1."item_id" = p2."id" INNER JOIN 
    "bundle_elements" AS t3 ON (t3."item_id" = p2."id")  INNER JOIN 
    "bundles" AS t4 ON t3."bundle_id" = t4."id" 
WHERE (
    (NOT (t3."bundle_id" = ANY('{}')) AND t4."is_public") AND 
    (t0."user_id" = 'some uuid')) AND 
        ST_Contains(
            ST_SetSRID(
                ST_MakePolygon(ST_GeomFromText('redacted list of coordinates)')),
                4326), 
            p2."lng_lat_point")
GROUP BY 
    t3."bundle_id" 
HAVING 
    (count(t3."item_id") >= 1) 
ORDER BY sum(t0."score") DESC 
LIMIT 8 OFFSET 0

Query Plan:

Limit  (cost=2858.21..2858.21 rows=2 width=24) (actual time=2577.007..2577.011 rows=8 loops=1)
  ->  Sort  (cost=2858.21..2858.21 rows=2 width=24) (actual time=2577.006..2577.009 rows=8 loops=1)
        Sort Key: (sum(t0.score)) DESC
        Sort Method: top-N heapsort  Memory: 26kB
        ->  GroupAggregate  (cost=2858.17..2858.21 rows=2 width=24) (actual time=2576.710..2576.979 rows=221 loops=1)
              Group Key: t3.bundle_id
              Filter: (count(t3.item_id) >= 1)
              ->  Sort  (cost=2858.17..2858.17 rows=7 width=40) (actual time=2576.699..2576.769 rows=1516 loops=1)
                    Sort Key: t3.bundle_id
                    Sort Method: quicksort  Memory: 167kB
                    ->  Nested Loop  (cost=0.39..2858.15 rows=7 width=40) (actual time=69.453..2575.737 rows=1516 loops=1)
                          ->  Nested Loop  (cost=0.31..2857.52 rows=7 width=40) (actual time=69.438..2569.811 rows=1516 loops=1)
                                ->  Nested Loop  (cost=0.22..1051.38 rows=3 width=40) (actual time=0.091..9.652 rows=225 loops=1)
                                      ->  Nested Loop  (cost=0.14..1026.30 rows=77 width=48) (actual time=0.063..6.135 rows=617 loops=1)
                                            ->  Index Scan using items_geom_idx on items p2  (cost=0.06..355.43 rows=57 width=16) (actual time=0.054..2.593 rows=469 loops=1)
                                                  Index Cond: (lng_lat_point @ 'xxx'::geometry)
                                                  Filter: _st_contains('xxx'::geometry, lng_lat_point)
                                            ->  Index Scan using reviews_item_id_index on reviews r1  (cost=0.08..11.75 rows=5 width=32) (actual time=0.005..0.006 rows=1 loops=469)
                                                  Index Cond: (item_id = p2.id)
                                      ->  Index Scan using user_rec_scores_user_id_network_user_id_index on user_rec_scores t0  (cost=0.08..0.32 rows=1 width=24) (actual time=0.004..0.005 rows=0 loops=617)
                                            Index Cond: ((user_id = 'some uuid'::uuid) AND (network_user_id = r1.recd_by_id))
                                ->  Index Only Scan using bundle_elements_bundle_id_item_id_index on bundle_elements t3  (cost=0.08..602.01 rows=13 width=32) (actual time=6.008..11.375 rows=7 loops=225)
                                      Index Cond: (item_id = r1.item_id)
                                      Heap Fetches: 39
                          ->  Index Only Scan using bundles_pkey on bundles t4  (cost=0.08..0.09 rows=1 width=16) (actual time=0.003..0.003 rows=1 loops=1516)
                                Index Cond: (id = t3.bundle_id)
                                Heap Fetches: 67
Planning Time: 1.667 ms
Execution Time: 2577.071 ms

Tables and indices:

CREATE TABLE IF NOT EXISTS public.user_rec_scores (
    user_id uuid,
    network_user_id uuid,
    score double precision NOT NULL,
    inserted_at timestamp(0) without time zone NOT NULL,
    updated_at timestamp(0) without time zone NOT NULL,
    CONSTRAINT user_rec_scores_network_user_id_fkey FOREIGN KEY (network_user_id)
        REFERENCES public.users (id),
    CONSTRAINT user_rec_scores_user_id_fkey FOREIGN KEY (user_id)
        REFERENCES public.users (id)
);

CREATE INDEX IF NOT EXISTS user_rec_scores_network_user_id_index
    ON public.user_rec_scores (network_user_id);

CREATE INDEX IF NOT EXISTS user_rec_scores_user_id_network_user_id_index
    ON public.user_rec_scores (user_id, network_user_id);


CREATE TABLE IF NOT EXISTS public.items (
    id uuid NOT NULL,
    lng_lat_point geometry(Point,4326),
    CONSTRAINT items_pkey PRIMARY KEY (id),
);

CREATE INDEX IF NOT EXISTS items_geom_idx
    ON public.items USING gist (lng_lat_point);


CREATE TABLE IF NOT EXISTS public.bundles (
    id uuid NOT NULL,
    user_id uuid,
    name character varying(255) COLLATE pg_catalog."default",
    is_public boolean DEFAULT true,
    deleted boolean DEFAULT false,
    inserted_at timestamp(0) without time zone NOT NULL,
    updated_at timestamp(0) without time zone NOT NULL,
    CONSTRAINT bundles_pkey PRIMARY KEY (id),
    CONSTRAINT bundles_source_bundle_id_fkey FOREIGN KEY (source_bundle_id)
        REFERENCES public.bundles (id),
    CONSTRAINT bundles_user_id_fkey FOREIGN KEY (user_id)
        REFERENCES public.users (id)
);

CREATE INDEX IF NOT EXISTS bundles_user_id_is_public_deleted_index
    ON public.bundles USING btree (user_id, is_public, deleted)
    WHERE deleted;


CREATE TABLE IF NOT EXISTS public.bundle_elements (
    id uuid NOT NULL,
    bundle_id uuid,
    item_id uuid,
    inserted_at timestamp(0) without time zone NOT NULL,
    updated_at timestamp(0) without time zone NOT NULL,
    CONSTRAINT bundle_elements_pkey PRIMARY KEY (id),
    CONSTRAINT bundle_elements_item_id_fkey FOREIGN KEY (item_id)
        REFERENCES public.items (id),
    CONSTRAINT bundle_elements_bundle_id_fkey FOREIGN KEY (bundle_id)
        REFERENCES public.bundles (id)
);

CREATE INDEX IF NOT EXISTS bundle_elements_bundle_id_item_id_index
    ON public.bundle_elements (bundle_id, item_id);


CREATE TABLE IF NOT EXISTS public.reviews (
    id uuid NOT NULL,
    recd_by_id uuid NOT NULL,
    item_id uuid,
    inserted_at timestamp(0) without time zone NOT NULL,
    updated_at timestamp(0) without time zone NOT NULL,
    deleted boolean DEFAULT false,
    CONSTRAINT reviews_pkey PRIMARY KEY (id),
    CONSTRAINT reviews_item_id_fkey FOREIGN KEY (item_id)
        REFERENCES public.items (id),
    CONSTRAINT reviews_recd_by_id_fkey FOREIGN KEY (recd_by_id)
        REFERENCES public.users (id)
);

CREATE INDEX IF NOT EXISTS reviews_inserted_at_index
    ON public.reviews (inserted_a);

CREATE INDEX IF NOT EXISTS reviews_item_id_index
    ON public.reviews (item_id);

CREATE UNIQUE INDEX IF NOT EXISTS reviews_recd_by_id_item_id_inserted_at_deleted_index
    ON public.reviews (recd_by_id, item_id, inserted_at, deleted);

Note that I've had to massage schema element names to protect the innocent, so if you see an inconsistency, that's the source of it.

Edit

Here's the explain analyze output of running this with enable_nestloop = False

Limit  (cost=13215.00..13215.00 rows=2 width=24) (actual time=148.619..157.869 rows=8 loops=1)
  ->  Sort  (cost=13215.00..13215.00 rows=2 width=24) (actual time=148.617..157.866 rows=8 loops=1)
        Sort Key: (sum(t0.score)) DESC
        Sort Method: top-N heapsort  Memory: 26kB
        ->  Finalize GroupAggregate  (cost=12354.39..13214.99 rows=2 width=24) (actual time=119.754..157.792 rows=222 loops=1)
              Group Key: t3.bundle_id
              Filter: (count(t3.item_id) >= 1)
              ->  Gather Merge  (cost=12354.39..13214.96 rows=6 width=32) (actual time=119.641..157.563 rows=548 loops=1)
                    Workers Planned: 2
                    Workers Launched: 2
                    ->  Partial GroupAggregate  (cost=11354.38..12214.31 rows=3 width=32) (actual time=82.696..109.873 rows=183 loops=3)
                          Group Key: t3.bundle_id
                          ->  Merge Join  (cost=11354.38..12214.30 rows=3 width=40) (actual time=82.544..109.673 rows=508 loops=3)
                                Merge Cond: (t3.bundle_id = t4.id)
                                ->  Sort  (cost=11349.99..11349.99 rows=3 width=40) (actual time=81.856..81.945 rows=508 loops=3)
                                      Sort Key: t3.bundle_id
                                      Sort Method: quicksort  Memory: 64kB
                                      Worker 0:  Sort Method: quicksort  Memory: 80kB
                                      Worker 1:  Sort Method: quicksort  Memory: 48kB
                                      ->  Merge Join  (cost=11349.70..11349.98 rows=3 width=40) (actual time=80.967..81.639 rows=508 loops=3)
                                            Merge Cond: (r1.recd_by_id = t0.network_user_id)
                                            ->  Sort  (cost=10961.77..10961.81 rows=75 width=48) (actual time=80.680..80.881 rows=2493 loops=3)
                                                  Sort Key: r1.recd_by_id
                                                  Sort Method: quicksort  Memory: 288kB
                                                  Worker 0:  Sort Method: quicksort  Memory: 338kB
                                                  Worker 1:  Sort Method: quicksort  Memory: 207kB
                                                  ->  Parallel Hash Join  (cost=6188.99..10961.31 rows=75 width=48) (actual time=48.666..79.734 rows=2522 loops=3)
                                                        Hash Cond: (r1.item_id = p2.id)
                                                        ->  Parallel Seq Scan on reviews r1  (cost=0.00..4699.98 rows=96326 width=32) (actual time=0.011..11.880 rows=77482 loops=3)
                                                        ->  Parallel Hash  (cost=6188.80..6188.80 rows=55 width=48) (actual time=48.334..48.337 rows=226 loops=3)
                                                              Buckets: 1024  Batches: 1  Memory Usage: 136kB
                                                              ->  Hash Join  (cost=334.48..6188.80 rows=55 width=48) (actual time=3.914..48.147 rows=226 loops=3)
                                                                    Hash Cond: (t3.item_id = p2.id)
                                                                    ->  Parallel Seq Scan on bundle_elements t3  (cost=0.00..5766.55 rows=167182 width=32) (actual time=0.018..17.249 rows=134293 loops=3)
                                                                    ->  Hash  (cost=334.28..334.28 rows=57 width=16) (actual time=3.767..3.769 rows=469 loops=3)
                                                                          Buckets: 1024  Batches: 1  Memory Usage: 30kB
                                                                          ->  Bitmap Heap Scan on items p2  (cost=4.32..334.28 rows=57 width=16) (actual time=0.429..3.637 rows=469 loops=3)
                                                                                Recheck Cond: ('0103000020E610000001000000050000000B7BDAE1AFF055C09E60FF756EF044403EAE0D15E3E355C09E60FF756EF044403EAE0D15E3E355C0D19332A9A1E344400B7BDAE1AFF055C0D19332A9A1E344400B7BDAE1AFF055C09E60FF756EF04440'::geometry ~ lng_lat_point)
                                                                                Filter: _st_contains('0103000020E610000001000000050000000B7BDAE1AFF055C09E60FF756EF044403EAE0D15E3E355C09E60FF756EF044403EAE0D15E3E355C0D19332A9A1E344400B7BDAE1AFF055C0D19332A9A1E344400B7BDAE1AFF055C09E60FF756EF04440'::geometry, lng_lat_point)
                                                                                Heap Blocks: exact=439
                                                                                ->  Bitmap Index Scan on items_geom_idx  (cost=0.00..4.31 rows=172 width=0) (actual time=0.347..0.347 rows=469 loops=3)
                                                                                      Index Cond: (lng_lat_point @ '0103000020E610000001000000050000000B7BDAE1AFF055C09E60FF756EF044403EAE0D15E3E355C09E60FF756EF044403EAE0D15E3E355C0D19332A9A1E344400B7BDAE1AFF055C0D19332A9A1E344400B7BDAE1AFF055C09E60FF756EF04440'::geometry)
                                            ->  Sort  (cost=387.93..388.03 rows=199 width=24) (actual time=0.258..0.312 rows=679 loops=3)
                                                  Sort Key: t0.network_user_id
                                                  Sort Method: quicksort  Memory: 40kB
                                                  Worker 0:  Sort Method: quicksort  Memory: 40kB
                                                  Worker 1:  Sort Method: quicksort  Memory: 40kB
                                                  ->  Bitmap Heap Scan on user_rec_scores t0  (cost=38.39..386.41 rows=199 width=24) (actual time=0.086..0.182 rows=200 loops=3)
                                                        Recheck Cond: (user_id = 'f83246cd-f03e-4d79-893f-a8bef864caa2'::uuid)
                                                        Heap Blocks: exact=9
                                                        ->  Bitmap Index Scan on user_rec_scores_user_id_network_user_id_index  (cost=0.00..38.38 rows=199 width=0) (actual time=0.070..0.070 rows=200 loops=3)
                                                              Index Cond: (user_id = 'f83246cd-f03e-4d79-893f-a8bef864caa2'::uuid)
                                ->  Index Only Scan using bundles_pkey on bundles t4  (cost=0.08..835.17 rows=58271 width=16) (actual time=0.053..22.433 rows=58456 loops=3)
                                      Heap Fetches: 54733
Planning Time: 1.569 ms
Execution Time: 157.975 ms

And for posterity, here it is with the index added as suggested by the answer:

Limit  (cost=1031.17..1031.17 rows=2 width=24) (actual time=9.710..9.714 rows=8 loops=1)
  ->  Sort  (cost=1031.17..1031.17 rows=2 width=24) (actual time=9.709..9.712 rows=8 loops=1)
        Sort Key: (sum(t0.score)) DESC
        Sort Method: top-N heapsort  Memory: 26kB
        ->  GroupAggregate  (cost=1031.13..1031.17 rows=2 width=24) (actual time=9.376..9.681 rows=222 loops=1)
              Group Key: t3.bundle_id
              Filter: (count(t3.item_id) >= 1)
              ->  Sort  (cost=1031.13..1031.13 rows=7 width=40) (actual time=9.368..9.439 rows=1524 loops=1)
                    Sort Key: t3.bundle_id
                    Sort Method: quicksort  Memory: 168kB
                    ->  Nested Loop  (cost=4.65..1031.11 rows=7 width=40) (actual time=0.269..8.954 rows=1524 loops=1)
                          ->  Nested Loop  (cost=4.57..1030.49 rows=7 width=40) (actual time=0.262..6.210 rows=1524 loops=1)
                                ->  Nested Loop  (cost=4.49..1029.79 rows=3 width=40) (actual time=0.213..4.213 rows=225 loops=1)
                                      ->  Nested Loop  (cost=4.40..1005.15 rows=77 width=48) (actual time=0.201..3.102 rows=618 loops=1)
                                            ->  Bitmap Heap Scan on items p2  (cost=4.32..334.28 rows=57 width=16) (actual time=0.190..1.168 rows=469 loops=1)
                                                  Recheck Cond: ('0103000020E610000001000000050000000B7BDAE1AFF055C09E60FF756EF044403EAE0D15E3E355C09E60FF756EF044403EAE0D15E3E355C0D19332A9A1E344400B7BDAE1AFF055C0D19332A9A1E344400B7BDAE1AFF055C09E60FF756EF04440'::geometry ~ lng_lat_point)
                                                  Filter: _st_contains('0103000020E610000001000000050000000B7BDAE1AFF055C09E60FF756EF044403EAE0D15E3E355C09E60FF756EF044403EAE0D15E3E355C0D19332A9A1E344400B7BDAE1AFF055C0D19332A9A1E344400B7BDAE1AFF055C09E60FF756EF04440'::geometry, lng_lat_point)
                                                  Heap Blocks: exact=439
                                                  ->  Bitmap Index Scan on items_geom_idx  (cost=0.00..4.31 rows=172 width=0) (actual time=0.140..0.140 rows=469 loops=1)
                                                        Index Cond: (lng_lat_point @ '0103000020E610000001000000050000000B7BDAE1AFF055C09E60FF756EF044403EAE0D15E3E355C09E60FF756EF044403EAE0D15E3E355C0D19332A9A1E344400B7BDAE1AFF055C0D19332A9A1E344400B7BDAE1AFF055C09E60FF756EF04440'::geometry)
                                            ->  Index Scan using reviews_item_id_index on reviews r1  (cost=0.08..11.75 rows=5 width=32) (actual time=0.003..0.004 rows=1 loops=469)
                                                  Index Cond: (item_id = p2.id)
                                      ->  Index Scan using user_rec_scores_user_id_network_user_id_index on user_rec_scores t0  (cost=0.08..0.32 rows=1 width=24) (actual time=0.001..0.002 rows=0 loops=618)
                                            Index Cond: ((user_id = 'f83246cd-f03e-4d79-893f-a8bef864caa2'::uuid) AND (network_user_id = r1.recd_by_id))
                                ->  Index Scan using bundle_elements_item_id on bundle_elements t3  (cost=0.08..0.19 rows=13 width=32) (actual time=0.005..0.008 rows=7 loops=225)
                                      Index Cond: (item_id = r1.item_id)
                          ->  Index Only Scan using bundles_pkey on bundles t4  (cost=0.08..0.09 rows=1 width=16) (actual time=0.002..0.002 rows=1 loops=1524)
                                Index Cond: (id = t3.bundle_id)
                                Heap Fetches: 466
Planning Time: 1.836 ms
Execution Time: 9.788 ms

I'm still unsure why it's so far off in its row estimates, but with this index in place, the nested loops strategy is 15x faster than the hash merge (I re-ran with nested loops on and off and with the index in place to verify) so it doesn't appear to matter.

2
  • "'redacted list of coordinates)'" You don't have to give us your real input, but you have to at least give us some plausible input.
    – jjanes
    Nov 8, 2022 at 23:33
  • 1
    Please add the EXPLAIN ANALYZE with enable_nestloop = False set so we can compare & contrast without needing a full data set. That said, it would help us to put a fiddle together with a reasonable test case. You can use explain.depesz.com to obfuscate explain plans if needed.
    – dwhitemv
    Nov 9, 2022 at 0:31

2 Answers 2

3

You have a bunch of estimation problems here, some of which might be be easy to explain and some of which are hard to explain. But I would say the real problem is a missing index. You don't have an index on bundle_elements which starts with item_id. So instead, it is using an index which has item_id as it its 2nd column, and this is horribly inefficient.

If you had the right index, then the performance would almost certainly be good enough, even if it is using the "wrong" plan. Since getting estimates exactly right under every circumstance is basically impossible, being robust to incorrect estimates is very desirable.

1
  • well I'll be. good catch -- I had assumed that since both of the columns in the existing composite index were in use, that was "good enough," which it clearly wasn't. adding a single index on bundle_elements.item_id brought the execution time down to 10ms, though interestingly it's still using the nested loops and it's still similarly wrong on row counts. it's just a lot faster now at it now.
    – kolosy
    Nov 9, 2022 at 17:42
0

If the query plans are anything like mysql or sql server, they are estimates and are subject to change between running them. I ran into this issue when trying to get accurate rowcounts pre and post migration; the only way to get around it was to run a select count(*) from each table before and after. That served to warm up the cache so it wasn't a total waste but point is, I'm sure that postgres is taking a cursory look based on statistics and giving it's best guess.

2
  • that's not the case here. this is an active server and the row counts don't change materially relative to the overall table size.
    – kolosy
    Nov 8, 2022 at 21:34
  • I'm just saying that it uses estimates when it's coming up with the query plan. Even if yo u update table statistics, they will still be approximations and not 100% accurate. That's also why you can end up with crazy over estimates in the execution plan or not enough. Adam mechanic did an interesting presentation about row goals years ago that comes to mind.
    – Muab Nhoj
    Nov 8, 2022 at 21:45

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.