Slow query in production: queryid 1578651367
Since the last deploy of 10.5.2-ee we are seeing this query running consuming excessive time in production:
This is taking 250-500ms per execution and running up to 8 requests per second. It's using up to 3 cpu cores. It also seems to be using temporary file sorting which indicates it may be processing an unreasonable amount of data for a web transaction.
Here are some examples that are all currently running:
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 1283398 AND ("todos"."state" IN ('pending')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 1283398 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 1283398 AND ("todos"."state" IN ('pending')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 2019579 AND ("todos"."state" IN ('done')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 2019579 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 2019579 AND ("todos"."state" IN ('done')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 1401443 AND ("todos"."state" IN ('pending')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 1401443 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 1401443 AND ("todos"."state" IN ('pending')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 6395 AND ("todos"."state" IN ('done')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 6395 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 6395 AND ("todos"."state" IN ('done')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 732930 AND ("todos"."state" IN ('pending')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 732930 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 732930 AND ("todos"."state" IN ('pending')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 1422445 AND ("todos"."state" IN ('done')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 1422445 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 1422445 AND ("todos"."state" IN ('done')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 1645465 AND ("todos"."state" IN ('pending')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 1645465 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 1645465 AND ("todos"."state" IN ('pending')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 546368 AND ("todos"."state" IN ('pending')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 546368 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 546368 AND ("todos"."state" IN ('pending')))
SELECT COUNT(*) FROM "todos" INNER JOIN "projects" ON "projects"."id" = "todos"."project_id" WHERE "todos"."user_id" = 1533933 AND ("todos"."state" IN ('pending')) AND (projects.id IN (SELECT projects.id FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 1533933 AND (project_authorizations.project_id = projects.id)))
UNION
SELECT projects.id FROM "projects" WHERE "projects"."visibility_level" IN (10, 20))) AND "projects"."id" IN (SELECT "todos"."project_id" FROM "todos" WHERE "todos"."user_id" = 1533933 AND ("todos"."state" IN ('pending')))
Here's the explain plan for one of those:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=33441.20..33441.21 rows=1 width=8) (actual time=1459.895..1459.896 rows=1 loops=1)
-> Nested Loop (cost=23110.48..33441.19 rows=1 width=0) (actual time=1284.975..1459.739 rows=464 loops=1)
-> Hash Join (cost=23110.05..33277.71 rows=23 width=12) (actual time=1284.811..1444.554 rows=4 loops=1)
Hash Cond: (projects_1.id = projects.id)
-> HashAggregate (cost=22737.93..27019.03 rows=428110 width=4) (actual time=1051.222..1320.691 rows=443982 loops=1)
Group Key: projects_1.id
-> Append (cost=9.78..21667.66 rows=428110 width=4) (actual time=0.166..555.766 rows=443982 loops=1)
-> Nested Loop (cost=9.78..202.26 rows=95 width=4) (actual time=0.165..1.054 rows=31 loops=1)
-> HashAggregate (cost=9.35..10.30 rows=95 width=4) (actual time=0.134..0.143 rows=31 loops=1)
Group Key: project_authorizations.project_id
-> Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations (cost=0.56..9.11 rows=95 width=4) (actual time=0.103..0.119 rows=31 loops=1)
Index Cond: (user_id = 1533933)
Heap Fetches: 27
-> Index Only Scan using projects_pkey on projects projects_1 (cost=0.43..2.01 rows=1 width=4) (actual time=0.027..0.028 rows=1 loops=31)
Index Cond: (id = project_authorizations.project_id)
Heap Fetches: 3
-> Index Only Scan using index_projects_on_id_partial_for_visibility on projects projects_2 (cost=0.42..17184.30 rows=428015 width=4) (actual time=0.118..350.186 rows=443951 loops=1)
Heap Fetches: 16070
-> Hash (cost=371.54..371.54 rows=46 width=8) (actual time=8.461..8.461 rows=4 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
-> Nested Loop (cost=278.47..371.54 rows=46 width=8) (actual time=8.338..8.454 rows=4 loops=1)
-> HashAggregate (cost=278.04..278.50 rows=46 width=4) (actual time=8.218..8.221 rows=4 loops=1)
Group Key: todos_1.project_id
-> Index Scan using index_todos_on_user_id on todos todos_1 (cost=0.43..277.92 rows=46 width=4) (actual time=0.117..8.033 rows=464 loops=1)
Index Cond: (user_id = 1533933)
Filter: ((state)::text = 'pending'::text)
Rows Removed by Filter: 201
-> Index Only Scan using projects_pkey on projects (cost=0.43..2.01 rows=1 width=4) (actual time=0.052..0.052 rows=1 loops=4)
Index Cond: (id = todos_1.project_id)
Heap Fetches: 1
-> Index Scan using index_todos_on_project_id on todos (cost=0.43..7.10 rows=1 width=4) (actual time=0.124..3.723 rows=116 loops=4)
Index Cond: (project_id = projects.id)
Filter: ((user_id = 1533933) AND ((state)::text = 'pending'::text))
Rows Removed by Filter: 542
Planning time: 1.386 ms
Execution time: 1464.085 ms
(36 rows)
Edited by Gregory Stark