1

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

1
  • 1
    Aer you sure this plan is correct? I don't understand how it is possible to have 150 seconds of IO reads taken place in 10 seconds of execution time. That would take 5 times more parallel work than you show having.
    – jjanes
    Jan 6, 2023 at 3:46

1 Answer 1

0

As far as I can tell (without looking into the source code) PostgreSQL only knows of one way to execute a query filter like WHERE col1 in (select...) or col2 in (select...), so it doesn't bother trying to come up with very good row estimates. When only one branch or the other is there, it will rewrite the query into a different form in which it can both get better estimates and better execution. But with the OR in place, it can't do that.

I can't explain why it isn't using a seq scan, in my hands it does use one. (But it won't use parallel workers, no matter what I do)

Note that the actual execution of this should be much better if you vacuum the table so that most of those "heap fetches" disappear.

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.