nehalem
Reputation: 417
Including some records in an SQL query increases query time fivefold on Heroku
We use Django with django-guardian for object-based permissions. Recently, we have been experiencing an extreme increase in runtime of a specific query for at least one user with a lot of annotation_texthighlight . Here is the query:
SELECT "annotation_texthighlight"."uuid",
[omitted for readability]
FROM "annotation_texthighlight"
INNER JOIN "annotation_annotation"
ON ("annotation_texthighlight"."annotation_id" = "annotation_annotation"."uuid")
WHERE (
"annotation_texthighlight"."annotation_id" IN
(SELECT U0."uuid"
FROM "annotation_annotation" U0
WHERE (U0."chapter_id" =
'9a481c82-c44b-4ead-94bb-48de0910877b'::uuid AND
U0."min_revision_id" IN
('5a301886-e200-441f-ad8e-03c4eb9bd773'::uuid,
'6f539d6f-c9eb-41e2-956e-32b4a5950c33'::uuid))) AND
"annotation_texthighlight"."uuid" IN
(SELECT CAST(U0."object_pk" AS uuid) AS "obj_pk"
FROM "guardian_userobjectpermission" U0
INNER JOIN "auth_permission" U2 ON (U0."permission_id" = U2."id")
WHERE (U0."user_id" = 1522 AND U2."content_type_id" = 89 AND
U2."codename" IN ('view_texthighlight')))
);
This puzzles me quite a bit. Here are the results of my investigation so far:
- Copying the database from its original Heroku (Postgres 13.4, standard-2, 4GB RAM, 1.2 GB DB size) to local (stock Postgres 13 via standard Docker image) will cut the runtime ~250ms.
- In total, about 1200 records will be returned. The first 700 (
LIMIT 700) will take ~5 seconds. The remaining (OFFSET 700 LIMIT 700) will take ~25 seconds. - Removing either of the
WHEREfilters will reduce runtime <1s.
My best guess would be a different configuration on Heroku as compared to the default Postgres Docker image.
I EXPLAIN ANALYSE both queries:
Postgres locally via Docker
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|QUERY PLAN |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|Nested Loop (cost=143.39..316.69 rows=1 width=179) (actual time=33.930..98.371 rows=1561 loops=1) |
| -> Nested Loop (cost=142.97..316.17 rows=1 width=70) (actual time=33.926..96.589 rows=1561 loops=1) |
| -> Nested Loop (cost=142.55..245.95 rows=133 width=54) (actual time=33.732..68.199 rows=11663 loops=1) |
| -> HashAggregate (cost=142.13..143.46 rows=133 width=37) (actual time=33.697..35.988 rows=11872 loops=1) |
| Group Key: (u0_1.object_pk)::uuid |
| Batches: 1 Memory Usage: 2209kB |
| -> Nested Loop (cost=0.55..141.79 rows=133 width=37) (actual time=0.228..26.688 rows=11872 loops=1) |
| -> Seq Scan on auth_permission u2 (cost=0.00..6.99 rows=1 width=4) (actual time=0.181..0.186 rows=1 loops=1) |
| Filter: ((content_type_id = 89) AND ((codename)::text = 'view_texthighlight'::text)) |
| Rows Removed by Filter: 265 |
| -> Index Only Scan using guardian_userobjectpermi_user_id_permission_id_ob_b0b3d2fc_uniq on guardian_userobjectpermission u0_1 (cost=0.55..114.05 rows=2075 width=41) (actual time=0.038..7.742 rows=11872 loops=1)|
| Index Cond: ((user_id = 1522) AND (permission_id = u2.id)) |
| Heap Fetches: 0 |
| -> Index Scan using annotation_texthighlight_pkey on annotation_texthighlight (cost=0.42..0.77 rows=1 width=54) (actual time=0.002..0.002 rows=1 loops=11872) |
| Index Cond: (uuid = (u0_1.object_pk)::uuid) |
| -> Index Scan using annotation_annotation_pkey on annotation_annotation u0 (cost=0.42..0.53 rows=1 width=16) (actual time=0.002..0.002 rows=0 loops=11663) |
| Index Cond: (uuid = annotation_texthighlight.annotation_id) |
| Filter: ((min_revision_id = ANY ('{5a301886-e200-441b-ad8e-03c4eb9bd773,6f539d6f-c9eb-41f2-956e-32b4a5950c33}'::uuid[])) AND (chapter_id = '9a481c82-c44b-4ecd-94bb-48de0910877b'::uuid)) |
| Rows Removed by Filter: 1 |
| -> Index Scan using annotation_annotation_pkey on annotation_annotation (cost=0.42..0.52 rows=1 width=125) (actual time=0.001..0.001 rows=1 loops=1561) |
| Index Cond: (uuid = annotation_texthighlight.annotation_id) |
|Planning Time: 4.189 ms |
|Execution Time: 98.961 ms |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
Postgres on Heroku
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|QUERY PLAN |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|Nested Loop Semi Join (cost=7.33..978.55 rows=1 width=180) (actual time=9.721..63411.623 rows=1561 loops=1) |
| Join Filter: (annotation_texthighlight.uuid = (u0_1.object_pk)::uuid) |
| Rows Removed by Join Filter: 46967551 |
| -> Nested Loop (cost=7.24..13.28 rows=1 width=180) (actual time=0.415..139.459 rows=4745 loops=1) |
| -> Nested Loop (cost=7.16..13.17 rows=1 width=142) (actual time=0.406..89.086 rows=4745 loops=1) |
| -> Bitmap Heap Scan on annotation_annotation u0 (cost=7.07..9.08 rows=1 width=16) (actual time=0.394..11.477 rows=4745 loops=1) |
| Recheck Cond: ((chapter_id = '9a481c82-c44b-4ecd-94bb-48de0910877b'::uuid) AND (min_revision_id = ANY ('{5a301886-e200-441b-ad8e-03c4eb9bd773,6f539d6f-c9eb-41f2-956e-32b4a5950c33}'::uuid[]))) |
| Heap Blocks: exact=163 |
| -> BitmapAnd (cost=7.07..7.07 rows=1 width=0) (actual time=0.373..0.375 rows=0 loops=1) |
| -> Bitmap Index Scan on annotation_annotation_chapter_id_d4a757a7 (cost=0.00..2.35 rows=174 width=0) (actual time=0.120..0.121 rows=4825 loops=1) |
| Index Cond: (chapter_id = '9a481c82-c44b-4ecd-94bb-48de0910877b'::uuid) |
| -> Bitmap Index Scan on annotation_annotation_min_revision_id_e84e9c27 (cost=0.00..4.68 rows=339 width=0) (actual time=0.246..0.246 rows=4825 loops=1) |
| Index Cond: (min_revision_id = ANY ('{5a301886-e200-441b-ad8e-03c4eb9bd773,6f539d6f-c9eb-41f2-956e-32b4a5950c33}'::uuid[])) |
| -> Index Scan using annotation_annotation_pkey on annotation_annotation (cost=0.08..4.09 rows=1 width=126) (actual time=0.010..0.010 rows=1 loops=4745) |
| Index Cond: (uuid = u0.uuid) |
| -> Index Scan using annotation_texthighlight_annotation_id_key on annotation_texthighlight (cost=0.08..0.12 rows=1 width=54) (actual time=0.008..0.008 rows=1 loops=4745) |
| Index Cond: (annotation_id = annotation_annotation.uuid) |
| -> Nested Loop (cost=0.09..964.62 rows=142 width=37) (actual time=0.042..7.175 rows=9899 loops=4745) |
| -> Seq Scan on auth_permission u2 (cost=0.00..4.00 rows=1 width=4) (actual time=0.028..0.032 rows=1 loops=4745) |
| Filter: ((content_type_id = 89) AND ((codename)::text = 'view_texthighlight'::text)) |
| Rows Removed by Filter: 254 |
| -> Index Only Scan using guardian_userobjectpermi_user_id_permission_id_ob_b0b3d2fc_uniq on guardian_userobjectpermission u0_1 (cost=0.09..953.57 rows=2353 width=41) (actual time=0.013..6.360 rows=9899 loops=4745)|
| Index Cond: ((user_id = 1522) AND (permission_id = u2.id)) |
| Heap Fetches: 46834604 |
|Planning Time: 0.733 ms |
|Execution Time: 63412.909 ms |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
The difference seems to be that locally Postgres is using HashAggregate (cost=142.13..143.46 rows=133 width=37) (actual time=33.697..35.988 rows=11872 loops=1) while on Heroku its doing a Bitmap Heap Scan on annotation_annotation.
Upvotes: 0
Views: 39
Answers (0)
Related Questions
- Improve PostgreSQL query performance
- How optimize SQL query with DISTINCT ON and JOIN many values?
- Discrepancy between Explain Analyze Actual Row Scanned vs. Total Row in Table
- Postgres slow query (slow index scan)
- Improving query performance in PostgreSQL with nested not in
- DISTINCT INNER JOIN slow
- How do you efficiently determine if a Postgres table has rows