Plan output: actual execution time not considering loops?

From: Thomas Kellerer <spam_eater(at)gmx(dot)net>
To: pgsql-general(at)lists(dot)postgresql(dot)org
Subject: Plan output: actual execution time not considering loops?
Date: 2018-06-20 10:51:26
Message-ID: c920e568-5b6a-7014-b2a4-6a59c403a704@gmx.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Consider the following execution plan:

Seq Scan on orders o1  (cost=0.00..18818840.86 rows=3500 width=16) (actual time=0.033..8625.104 rows=99906 loops=1)
  Filter: (amount = (SubPlan 1))
  Rows Removed by Filter: 600094
  Buffers: shared hit=7719778
  SubPlan 1
    ->  Aggregate  (cost=26.87..26.87 rows=1 width=32) (actual time=0.012..0.012 rows=1 loops=700000)
          Buffers: shared hit=7714631
          ->  Bitmap Heap Scan on orders o2  (cost=3.45..26.85 rows=8 width=8) (actual time=0.004..0.008 rows=8 loops=700000)
                Recheck Cond: (customer_id = o1.customer_id)
                Heap Blocks: exact=5597311
                Buffers: shared hit=7714631
                ->  Bitmap Index Scan on orders_customer_id_order_date_idx  (cost=0.00..3.45 rows=8 width=0) (actual time=0.003..0.003 rows=8 loops=700000)
                      Index Cond: (customer_id = o1.customer_id)
                      Buffers: shared hit=2117320
Planning time: 0.136 ms
Execution time: 8628.724 ms

My expectation would have been that the "Aggregate" step shows the actual time as a product of the number of loops.

The Bitmap Heap Scan takes 0.008ms for each execution, so shouldn't the "actual time" for the "Aggregate" step be 0.008ms * 700000 (= 5600ms)?

The plan was generated using Postgres 10.4 (on Windows 10, but I think that is irrelevant)

Thomas

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Janning Vygen 2018-06-20 11:51:25 Suggestion about logging only every n-th statement
Previous Message Thomas Kellerer 2018-06-20 08:16:54 Re: PostgreSQL Volume Question