I'm trying to analyze a slow query that uses parallel index-only scan of two filters (using sub-queries). Specifically I'm the number of 'open_questions' that returned by either subplan1 OR subplan2.
The query itself is generated by Django ORM, so I can definitely see that there are places I can optimize it (doing the sub-sub query of U0."final_answer" IN ('1st Option')
and U0."final_answer" IN NULL
.
However, running explain (analyze, buffers)
showed me that the culprit of the slowness is the Parallel Index Only Scan using primary key of open_question. It was over-estimated the returned ids by 19M+ records (the table size of open_question
is roughly 19.5M rows)
SELECT
COUNT(*) AS "__count"
FROM
"open_question"
WHERE
(
"open_question"."id" IN (
SELECT
DISTINCT U0."id"
FROM
"open_question" U0
INNER JOIN "book" U1 ON (U0."book_id" = U1."id")
INNER JOIN "picture" U3 ON (U0."picture_id" = U3."id")
WHERE
(
NOT (
U0."final_answer" IN (
'DELETED',
'DELETED_NOT_ANSWERED',
'NO_ONE_ANSWER'
)
AND U0."final_answer" IS NOT NULL
)
AND U1."project_id" = '107e827e-346a-4178-bb53-7cbd2ff0d66c'::uuid
AND U3."picture_group_id" IN ('ff3d7383-f086-499d-b59c-09d49733e327'::uuid)
AND U3."color_schema_id" IN ('2ee66308-1b4b-4473-b2b8-717974ccbfdf'::uuid)
AND U0."book_id" IN (
'ef4ad3c8-8ff5-411b-8577-202212202103'::uuid,
'671d56b3-41f1-450b-afbf-202212191825'::uuid,
'c986ce5e-36ad-44d0-a2ab-202212132131'::uuid,
... 40 more records
)
AND (U0."final_answer" IN ('1st Option')
)
)
OR "open_question"."id" IN (
SELECT
V0."open_question_id"
FROM
"scoped_question" V0
WHERE
(
V0."date_submitted" IS NULL
AND V0."date_answered" IS NULL
AND V0."open_question_id" IN (
SELECT
DISTINCT U0."id"
FROM
"open_question" U0
INNER JOIN "book" U1 ON (U0."book_id" = U1."id")
INNER JOIN "picture" U3 ON (U0."picture_id" = U3."id")
WHERE
(
NOT (
U0."final_answer" IN (
'DELETED',
'DELETED_NOT_ANSWERED',
'NO_ONE_ANSWER'
)
AND U0."final_answer" IS NOT NULL
)
AND U1."project_id" = '107e827e-346a-4178-bb53-7cbd2ff0d66c'::uuid
AND U3."picture_group_id" IN ('ff3d7383-f086-499d-b59c-09d49733e327'::uuid)
AND U3."color_schema_id" IN ('2ee66308-1b4b-4473-b2b8-717974ccbfdf'::uuid)
AND U0."book_id" IN (
'ef4ad3c8-8ff5-411b-8577-202212202103'::uuid,
'671d56b3-41f1-450b-afbf-202212191825'::uuid,
'c986ce5e-36ad-44d0-a2ab-202212132131'::uuid,
... 40 more records as above
)
AND U0."final_answer" IS NULL
)
)
AND V0."type" IN ('REVALIDATE_ANSWER')
)
)
);
Running each of the sub-plans individually is very fast, and eventually the result of all this long query is 2 (only 2 open_questions).
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=479208.85..479208.86 rows=1 width=8) (actual time=10159.397..10164.554 rows=1 loops=1)
Buffers: shared hit=18316732 read=77554
I/O Timings: read=150757.132
-> Gather (cost=479208.63..479208.84 rows=2 width=8) (actual time=10159.041..10164.548 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=18316732 read=77554
I/O Timings: read=150757.132
-> Partial Aggregate (cost=478208.63..478208.64 rows=1 width=8) (actual time=10154.771..10154.782 rows=1 loops=3)
Buffers: shared hit=18316732 read=77554
I/O Timings: read=150757.132
-> Parallel Index Only Scan using open_question_pkey on open_question (cost=155.73..463070.55 rows=6055232 width=0) (actual time=5538.715..10154.776 rows=1 loops=3)
Filter: ((hashed SubPlan 1) OR (hashed SubPlan 2))
Rows Removed by Filter: 6471867
Heap Fetches: 4463629
Buffers: shared hit=18316732 read=77554
I/O Timings: read=150757.132
SubPlan 1
-> Unique (cost=74.48..74.49 rows=1 width=16) (actual time=330.591..330.599 rows=2 loops=3)
Buffers: shared hit=4993 read=595
I/O Timings: read=568.918
-> Sort (cost=74.48..74.49 rows=1 width=16) (actual time=330.590..330.595 rows=2 loops=3)
Sort Key: u0.id
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=4993 read=595
I/O Timings: read=568.918
Worker 0: Sort Method: quicksort Memory: 25kB
Worker 1: Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=34.74..74.47 rows=1 width=16) (actual time=207.845..329.926 rows=2 loops=3)
Buffers: shared hit=4976 read=595
I/O Timings: read=565.144
-> Nested Loop (cost=34.45..71.40 rows=1 width=32) (actual time=207.823..329.890 rows=2 loops=3)
Buffers: shared hit=4956 read=595
I/O Timings: read=565.144
-> Bitmap Heap Scan on picture u3 (cost=33.89..35.37 rows=1 width=16) (actual time=2.851..3.235 rows=118 loops=3)
Recheck Cond: ((picture_group_id = 'ff3d7383-f086-499d-b59c-09d49733e327'::uuid) AND (color_schema_id = '2ee66308-1b4b-4473-b2b8-717974ccbfdf'::uuid))
Heap Blocks: exact=118
Buffers: shared hit=411 read=7
I/O Timings: read=6.323
-> BitmapAnd (cost=33.89..33.89 rows=1 width=0) (actual time=2.830..2.831 rows=0 loops=3)
Buffers: shared hit=57 read=7
I/O Timings: read=6.323
-> Bitmap Index Scan on picture_picture_group_id_ea80b794 (cost=0.00..12.02 rows=549 width=0) (actual time=2.221..2.221 rows=792 loops=3)
Index Cond: (picture_group_id = 'ff3d7383-f086-499d-b59c-09d49733e327'::uuid)
Buffers: shared hit=28 read=7
I/O Timings: read=6.323
-> Bitmap Index Scan on color_schema_id_c798104e (cost=0.00..21.62 rows=2042 width=0) (actual time=0.567..0.568 rows=4973 loops=3)
Index Cond: (color_schema_id = '2ee66308-1b4b-4473-b2b8-717974ccbfdf'::uuid)
Buffers: shared hit=29
-> Index Scan using open_question_id_ff531421 on open_question u0 (cost=0.56..36.02 rows=1 width=48) (actual time=2.736..2.765 rows=0 loops=354)
Index Cond: (picture_id = u3.id)
Filter: ((final_answer = '1st Option'::text) AND ((final_answer <> ALL ('{DELETED,DELETED_NOT_ANSWERED,NO_ONE_ANSWER}'::text[])) OR (final_answer IS NULL)) AND (book_id = ANY ('{ef4ad3c8-8ff5-411b-8577-202212202103,671d56b3-41f1-450b-afbf-202212191825,c986ce5e-36ad-44d0-a2ab-202212132131, ...}'::uuid[])))
Rows Removed by Filter: 27
Buffers: shared hit=4545 read=588
I/O Timings: read=558.821
-> Index Scan using book_pkey on book u1 (cost=0.29..3.06 rows=1 width=16) (actual time=0.013..0.013 rows=1 loops=6)
Index Cond: (id = u0.book_id)
Filter: (project_id = '107e827e-346a-4178-bb53-7cbd2ff0d66c'::uuid)
Buffers: shared hit=20
SubPlan 2
-> Nested Loop (cost=74.74..80.67 rows=1 width=16) (actual time=6.960..6.965 rows=0 loops=3)
Buffers: shared hit=4624
-> Unique (cost=74.32..74.33 rows=1 width=16) (actual time=6.959..6.964 rows=0 loops=3)
Buffers: shared hit=4624
-> Sort (cost=74.32..74.33 rows=1 width=16) (actual time=6.959..6.963 rows=0 loops=3)
Sort Key: u0_1.id
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=4624
Worker 0: Sort Method: quicksort Memory: 25kB
Worker 1: Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=34.74..74.31 rows=1 width=16) (actual time=6.950..6.953 rows=0 loops=3)
Buffers: shared hit=4624
-> Nested Loop (cost=34.45..71.34 rows=1 width=32) (actual time=6.949..6.952 rows=0 loops=3)
Buffers: shared hit=4624
-> Bitmap Heap Scan on picture u3_1 (cost=33.89..35.37 rows=1 width=16) (actual time=0.686..0.927 rows=118 loops=3)
Recheck Cond: ((picture_group_id = 'ff3d7383-f086-499d-b59c-09d49733e327'::uuid) AND (color_schema_id = '2ee66308-1b4b-4473-b2b8-717974ccbfdf'::uuid))
Heap Blocks: exact=118
Buffers: shared hit=414
-> BitmapAnd (cost=33.89..33.89 rows=1 width=0) (actual time=0.667..0.668 rows=0 loops=3)
Buffers: shared hit=60
-> Bitmap Index Scan on picture_picture_group_id_ea80b794 (cost=0.00..12.02 rows=549 width=0) (actual time=0.088..0.089 rows=792 loops=3)
Index Cond: (picture_group_id = 'ff3d7383-f086-499d-b59c-09d49733e327'::uuid)
Buffers: shared hit=33
-> Bitmap Index Scan on color_schema_id_c798104e (cost=0.00..21.62 rows=2042 width=0) (actual time=0.538..0.539 rows=4973 loops=3)
Index Cond: (color_schema_id = '2ee66308-1b4b-4473-b2b8-717974ccbfdf'::uuid)
Buffers: shared hit=27
-> Index Scan using open_question_id_ff531421 on open_question u0_1 (cost=0.56..35.97 rows=1 width=48) (actual time=0.050..0.050 rows=0 loops=354)
Index Cond: (picture_id = u3_1.id)
Filter: ((final_answer IS NULL) AND ((final_answer <> ALL ('{DELETED,DELETED_NOT_ANSWERED,NO_ONE_ANSWER}'::text[])) OR (final_answer IS NULL)) AND (book_id = ANY ('{ef4ad3c8-8ff5-411b-8577-202212202103,671d56b3-41f1-450b-afbf-202212191825,c986ce5e-36ad-44d0-a2ab-202212132131, ...}'::uuid[])))
Rows Removed by Filter: 27
Buffers: shared hit=4210
-> Index Scan using book_pkey on book u1_1 (cost=0.29..2.96 rows=1 width=16) (never executed)
Index Cond: (id = u0_1.book_id)
Filter: (project_id = '107e827e-346a-4178-bb53-7cbd2ff0d66c'::uuid)
-> Index Scan using single_scoped_question_per_eta on scoped_question v0 (cost=0.42..3.37 rows=1 width=16) (never executed)
Index Cond: (open_question_id = u0_1.id)
Filter: ((date_submitted IS NULL) AND (type = 'RECALLED_ANSWER'::text))
Planning:
Buffers: shared hit=1491
Planning Time: 4.680 ms
Execution Time: 10165.867 ms
(101 rows)
What bothers me specifically is this part (node):
Parallel Index Only Scan using open_question_pkey on open_question (cost=155.73..463070.55 rows=6055232 width=0) (actual time=5538.715..10154.776 rows=1 loops=3)
Filter: ((hashed SubPlan 1) OR (hashed SubPlan 2))
Rows Removed by Filter: 6471867
Heap Fetches: 4463629
Buffers: shared hit=18316732 read=77554
I/O Timings: read=150757.132
Why does Postgres so way off here? If I reduce the query to just count by specific open questions (as returned from the 2 subqueries), the result is very fast and uses the same index. I also suspect that since Postgres over estimate the number of returned rows from the filter (6471867 times 3 due to parallelism) it actually does some kind of sequence scan on 19M records.
Would like to get better explanation on what's going inside Postgres