0

I'm struggling to make sense of postgres EXPLAIN to figure out why my query is slow. Can someone help? This is my query, it's a pretty simple join:

SELECT DISTINCT graph_concepts.* 
FROM graph_concepts 
INNER JOIN graph_family_links 
        ON graph_concepts.id = graph_family_links.descendent_concept_id 
WHERE graph_family_links.ancestor_concept_id = 1016 
AND graph_family_links.generation = 1 
AND graph_concepts.state != 2

It's starting from a concept and it's getting a bunch of related concepts through the links table.

Notably, I have an index on graph_family_links.descendent_concept_id, yet this query takes about 3 seconds to return a result. This is way too long for my purposes.

This is the SQL explain:

 Unique  (cost=46347.01..46846.16 rows=4485 width=108) (actual time=27.406..33.667 rows=13 loops=1)
   Buffers: shared hit=13068 read=5
   I/O Timings: read=0.074
   ->  Gather Merge  (cost=46347.01..46825.98 rows=4485 width=108) (actual time=27.404..33.656 rows=13 loops=1)
         Workers Planned: 1
         Workers Launched: 1
         Buffers: shared hit=13068 read=5
         I/O Timings: read=0.074
         ->  Sort  (cost=45347.01..45348.32 rows=2638 width=108) (actual time=23.618..23.621 rows=6 loops=2)
               Sort Key: graph_concepts.id, graph_concepts.definition, graph_concepts.checkvist_task_id, graph_concepts.primary_question_id, graph_concepts.created_at, graph_concepts.updated_at, graph_concepts.tsn, graph_concepts.state, graph_concepts.search_phrases
               Sort Method: quicksort  Memory: 25kB
               Buffers: shared hit=13068 read=5
               I/O Timings: read=0.074
               Worker 0:  Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop  (cost=301.97..45317.02 rows=2638 width=108) (actual time=8.890..23.557 rows=6 loops=2)
                     Buffers: shared hit=13039 read=5
                     I/O Timings: read=0.074
                     ->  Parallel Bitmap Heap Scan on graph_family_links  (cost=301.88..39380.60 rows=2640 width=4) (actual time=8.766..23.293 rows=6 loops=2)
                           Recheck Cond: (ancestor_concept_id = 1016)
                           Filter: (generation = 1)
                           Rows Removed by Filter: 18850
                           Heap Blocks: exact=2558
                           Buffers: shared hit=12985
                           ->  Bitmap Index Scan on index_graph_family_links_on_ancestor_concept_id  (cost=0.00..301.66 rows=38382 width=0) (actual time=4.744..4.744 rows=47346 loops=1)
                                 Index Cond: (ancestor_concept_id = 1016)
                                 Buffers: shared hit=67
                     ->  Index Scan using graph_concepts_pkey on graph_concepts  (cost=0.08..2.25 rows=1 width=108) (actual time=0.036..0.036 rows=1 loops=13)
                           Index Cond: (id = graph_family_links.descendent_concept_id)
                           Filter: (state <> 2)
                           Buffers: shared hit=54 read=5
                           I/O Timings: read=0.074
 Planning:
   Buffers: shared hit=19
 Planning Time: 0.306 ms
 Execution Time: 33.747 ms
(35 rows)

I'm doing lots of googling to help me figure out how to read this EXPLAIN and I'm struggling. Can someone help translate this into plain english for me?

Answering myself (for the benefit of future people):

My question was primarily how to understand EXPLAIN. Many people below contributed to my understanding but no one really gave me the beginner unpacking I was looking for. I want to teach myself to fish rather than simply having other people read this and give me advice on solving this specific issue, although I do greatly appreciate the specific suggestions!

For others trying to understand EXPLAIN, this is the important context you need to know, which was holding me back:

  • "Cost" is some arbitrary unit of how expense each step of the process is, you can think of it almost like a stopwatch.
  • Look near the end of your EXPLAIN until you find: cost=0.00.. This is the very start of your query execution. In my case, cost=0.00..301.66 is the first step and cost=0.08..2.25 runs in parallel (from step 0.08 to step 2.25, just a small fraction of the 0 to 300).
  • Find the step with the biggest "span" of cost. In my case, cost=301.88..39380.60. Although I was confused because I also have a cost=301.97..45317.02. I think those are, again, both happening in parallel so I'm not sure which one is contributing more.
Keith Schacht
  • 1,998
  • 15
  • 23
  • Please post complete query and results form EXPLAIN (ANALYZE, BUFFERS). Also post table definition (DDL script). – Belayer Jul 14 '22 at 03:17
  • Your performance enemy is probably the horrible combination of `select distinct` together with with `select *`. Choose the columns you actually need instead, don't use *, then it might perform better. **OR**, you need to join to a subquery instead of the table - with that subquery reducing the columns/rows as needed. – Paul Maxwell Jul 14 '22 at 04:21
  • 1
    some useful link: https://www.pgmustard.com/ https://www.cybertec-postgresql.com/en/how-to-interpret-postgresql-explain-analyze-output/ – jian Jul 14 '22 at 04:24
  • 1
    https://use-the-index-luke.com/sql/explain-plan –  Jul 14 '22 at 05:19
  • Your new plan shows it took only .033 seconds. Maybe it is faster now because all the data is in memory, or maybe you misread the original timing. – jjanes Jul 14 '22 at 13:33

3 Answers3

1
SELECT DISTINCT
    graph_concepts.* 
FROM
    graph_concepts
    INNER JOIN graph_family_links ON graph_concepts.id = graph_family_links.descendent_concept_id 
WHERE
    graph_family_links.ancestor_concept_id = 1016 
    AND graph_family_links.generation = 1 
    AND graph_concepts.state != 2

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique  (cost=46347.01..46846.16 rows=4485 width=108)
   ## (Merge records DISTINCT)
   ->  Gather Merge  (cost=46347.01..46825.98 rows=4485 width=108)
         Workers Planned: 1
                 
        ## (Sort table graph_concepts.* )
         ->  Sort  (cost=45347.01..45348.32 rows=2638 width=108)
               Sort Key: graph_concepts.id, graph_concepts.definition, graph_concepts.checkvist_task_id, graph_concepts.primary_question_id, graph_concepts.created_at, graph_concepts.updated_at, graph_concepts.tsn, graph_concepts.state, graph_concepts.search_phrases
                             
                             
               ->  Nested Loop  (cost=301.97..45317.02 rows=2638 width=108)
                     ## WHERE graph_family_links.ancestor_concept_id = 1016     (Use Parallel Bitmap Heap Scan table and filter record)
                     ->  Parallel Bitmap Heap Scan on graph_family_links  (cost=301.88..39380.60 rows=2640 width=4)
                           Recheck Cond: (ancestor_concept_id = 1016)
                           Filter: (generation = 1)
                                                     
                            ## AND graph_family_links.generation = 1 (Use Bitmap Index Scan table and filter record)
                           ->  Bitmap Index Scan on index_graph_family_links_on_ancestor_concept_id  (cost=0.00..301.66 rows=38382 width=0)
                                 Index Cond: (ancestor_concept_id = 1016)
                     
                                         
                                ## AND graph_concepts.state != 2 (Use Index Scan table and filter record)
                                ->  Index Scan using graph_concepts_pkey on graph_concepts  (cost=0.08..2.25 rows=1 width=108)
                                Index Cond: (id = graph_family_links.descendent_concept_id)
                                Filter: (state <> 2)
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Please refer to the below sql script.

SELECT DISTINCT graph_concepts.* 
FROM graph_concepts
    INNER JOIN (select descendent_concept_id from graph_family_links where ancestor_concept_id = 1016 and generation = 1) A ON graph_concepts.id = A.descendent_concept_id 
WHERE graph_concepts.state != 2
Courser Xu
  • 142
  • 4
0

This command displays the execution plan that the PostgreSQL planner generates for the supplied statement. The execution plan shows how the table(s) referenced by the statement will be scanned — by plain sequential scan, index scan, etc. — and if multiple tables are referenced, what join algorithms will be used to bring together the required rows from each input table.

Since you only do explain your select command meaning the output is the system planner generate a execute plan for this select query. But if you do explain analyze then it will plan and execute the query.

  • First there is two table there. For each table use some ways to found out which rows meet the where criteria. index scan (one of the way to find out where is the row) found out in table graph_concepts which row meet the condition: graph_concepts.state != 2. Also in the mean time(Parallel) use Bitmap Heap Scan to found out in table graph_family_links which row meet the criteria: graph_family_links.ancestor_concept_id = 1016
  • After that then do join operation. In this case, it's Nested Loop.
  • After join then do Sort. Why we need to sort operation? Because you specified: SELECT DISTINCT : https://www.postgresql.org/docs/current/sql-select.html -After sort then since you specified key word DISTINCT then eliminate the duplicates.
jian
  • 4,119
  • 1
  • 17
  • 32
  • I updated my original question with the result of EXPLAIN ANALYZE, in case that helps. – Keith Schacht Jul 14 '22 at 12:57
  • Thank you for your explanation. I read and re-read everyone's answers but yours was the most foundational explanation that helped me to begin to untangle how to even make sense of the EXPLAIN output. I appreciate your help! There is one key thing about my EXPLAIN which I still can't figure out. My JOIN operation is an expensive Nested Loop `cost=301.97..45317.02`. But immediately after this is a Parallel Bitmap Heap Scan on graph_family_links with almost the same cost `(cost=301.88..39380.60)`. I assume these are happening in parallel? Which is my real culprit, then? – Keith Schacht Jul 15 '22 at 19:49
  • @KeithSchacht I am not sure. But I found these two links maybe will be helpful for you to understand. https://stackoverflow.com/questions/60211067/how-to-understand-the-nested-loop-in-postgresql-explain https://www.postgresql.org/message-id/flat/12553.1135634231%40sss.pgh.pa.us#bf329c95dc1ad2c6e3eb91e71c600db8 – jian Jul 16 '22 at 06:55
0

People have given you general links and advice on understanding plans. To focus on one relevant part of the plan, it expects to find 38382 rows satisfying ancestor_concept_id = 1016, but then well over 90% of them are expected to fail the generation = 1 filter. But that is expensive as it was to jump to some random table page to fetch the "generation" value to apply the filter.

If you had a combined index on (ancestor_concept_id, generation) it could apply both restrictions efficiently simultaneously. Alternatively, of you had separate single column indexes on those columns, it could combine then with a BitmapAnd operation. That would be more efficient than what you are currently doing to but less efficient than the combined index.

jjanes
  • 37,812
  • 5
  • 27
  • 34
  • I really appreciate this suggestion! I added a generation index and it's helping quite a bit and there are many cases where I will filter on `generation`. How do I decide whether I should also add a (ancestor_concept_id, generation) index. How do I determine how much more it might help and what the "cost" to this extra index would be? And is that cost simply database storage space or is it also a write cost? – Keith Schacht Jul 15 '22 at 19:37
  • Since you already have an index on ancestor_concept_id, replacing it with one on `(ancestor_concept_id,generation)` should have almost no extra cost. – jjanes Jul 17 '22 at 15:16