Search code examples
postgresqlsql-execution-planexplain

Understanding Postgres explain plan


I am trying to understand a Postgres explain plan using this website (http://explain.depesz.com).

This is my plan:

Unique  (cost=795.43..800.89 rows=546 width=23) (actual time=0.599..0.755 rows=620 loops=1)
  ->  Sort  (cost=795.43..796.79 rows=546 width=23) (actual time=0.598..0.626 rows=620 loops=1)
        Sort Key: m.member_id, c.total_charged_amt DESC, c.claim_status
        Sort Method: quicksort  Memory: 73kB
        ->  Nested Loop  (cost=9.64..770.60 rows=546 width=23) (actual time=0.023..0.342 rows=620 loops=1)
              ->  Bitmap Heap Scan on member m  (cost=9.22..222.50 rows=63 width=8) (actual time=0.016..0.024 rows=62 loops=1)
                    Recheck Cond: (((member_id >= 1584161838) AND (member_id <= 1584161898)) OR (member_birth_dt = '1978-03-13'::date))
                    Heap Blocks: exact=3
                    ->  BitmapOr  (cost=9.22..9.22 rows=63 width=0) (actual time=0.013..0.013 rows=0 loops=1)
                          ->  Bitmap Index Scan on member_pkey  (cost=0.00..4.31 rows=2 width=0) (actual time=0.007..0.007 rows=61 loops=1)
                                Index Cond: ((member_id >= 1584161838) AND (member_id <= 1584161898))
                          ->  Bitmap Index Scan on idx_dob  (cost=0.00..4.88 rows=61 width=0) (actual time=0.006..0.006 rows=1 loops=1)
                                Index Cond: (member_birth_dt = '1978-03-13'::date)
              ->  Index Scan using idx_memberid on claim c  (cost=0.42..8.60 rows=10 width=23) (actual time=0.001..0.003 rows=10 loops=62)
                    Index Cond: (member_id = m.member_id)
Planning Time: 0.218 ms
Execution Time: 0.812 ms

The plan is also available in the following link: https://explain.depesz.com/s/Qzau.

I have following questions:

  1. Bitmap Index Scans which runs in 0.007s and 0.006s respectively runs in parallel because of indentation.

    So why does Bitmapor start at 0.013s? Why is it adding time of both its children? The start time of Bitmapor should be the maximum of its 2 children. So ideally the exclusive time of Bitmapor should be 0.006 (0.013-0.007), but it is 0 (0.013-0.007-0.006)

  2. Bitmap Heap Scan and index scan are children of Nested Loop and run in 0.024s and 0.186s, respectively.

    Because of the indentation I assume these 2 children run in parallel. So the parent exclusive time should be 0.156 (0.342-0.186), but instead it is 0.132(0.342-0.186-0.24).

My understanding is we should subtract maximum of the child timings (since they run in parallel) to get the exclusive time spent in the node. But instead it is adding up child timings and then subtracting the sum from the end time of the parent to get the exclusive time. Did i understand incorrectly about explain plans?

Any help is really appreciated as I am totally confused with interpreting them.


Solution

  • As the horse said, there is no parallel processing involved. If parallel query were involved, you would see a Gather node that collects the results.

    The indentation visualizes the graph of the query execution plan:

                             Unique
                               |
                              Sort
                               |
                          Nested Loop
                            /      \
              Bitmap Heap Scan    Index Scan
                      |
                  Bitmap Or
                   /     \
    Bitmap Index Scan   Bitmap Index Scan
    

    That explains why explain.depesz.com calculates the exclusive time the way it does. Note that that is just a best effort, not the absolute truth, because (for example) a "bitmap or" does not take zero time. But explain.depesz.com can only go by the numbers it gets from EXPLAIN.