loops and actual time in PostgreSQL EXPLAIN ANALYZE

What it does

Every step in an EXPLAIN ANALYZE plan ends with measurements in brackets:

(actual time=0.009..0.287 rows=50.00 loops=1000)

• actual time=A..B: milliseconds. A is the time until the step returned its first row (start-up time), B the time until it returned its last. Both include the time spent in the steps below it.
• rows: rows the step returned.
• loops: how many times the step ran.

The catch: time and rows are averages per loop. The line above means the step ran 1,000 times, took 0.287 ms and returned 50 rows each time. In total it took about 287 ms and returned 50,000 rows.

When you see it

On every step of EXPLAIN ANALYZE. loops is 1 for most steps. It’s more than 1:

• on the inner side of a Nested Loop, which runs once per outer row;
• in a correlated subquery (SubPlan), which runs once per row of the outer query;
• in a parallel plan, where each process counts as a loop: loops=3 is two workers plus the leader.

A step that never ran shows (never executed) instead.

Reading its numbers

1. Total time = B × loops. For a parallel step, that’s the sum over processes running at the same time, so it can be more than the query’s execution time. Compare it with the Gather above it for wall-clock time.
2. Total rows = rows × loops. In PostgreSQL 18, rows has two decimals, so an average such as rows=3333.33 or rows=0.40 shows as it is. PostgreSQL 17 and earlier print whole numbers, so an average below 0.5 rows per loop shows as rows=0.
3. Self time = own total − children’s totals. Times include everything below, so the step where the time starts is the one whose total is much bigger than its children’s.
4. Some counters are totals already. Buffers, Heap Fetches, Index Searches and Heap Blocks are not divided by loops. Rows Removed by Filter is, like rows.
5. The estimate is per loop too. rows=49 in the cost=… bracket is what the planner expected per execution, so compare it with the actual per-loop rows, not the total.

When it’s a problem

When a cheap step runs many times. An index lookup that takes 0.3 ms is fast; run 1,000 times it’s most of the query. Look for:

• A nested loop whose outer side returns far more rows than the planner expected. The plan was chosen for a few loops and got thousands. Fix the estimate first: ANALYZE, extended statistics, or a simpler condition. See cost and rows estimates.
• A SubPlan with a large loops. A correlated subquery in the SELECT list or WHERE clause runs once per row. Rewriting it as a join, or EXISTS, often lets the planner use a hash join.
• A missing index on the inner side. If the inner step is a Seq Scan with loops=1000, the table is read 1,000 times; an index on the join column turns each loop into a lookup.

Example

PostgreSQL 18.6. customers has 20,000 rows; orders has 1,000,000 rows, 50 per customer, with an index on customer_id (setup in Rows Removed by Filter):

SET search_path = seo_terms;
CREATE TABLE customers (id int PRIMARY KEY, name text NOT NULL, country text NOT NULL, city text NOT NULL);
INSERT INTO customers
SELECT i, 'Customer ' || i,
       (ARRAY['GB','FR','DE','US','JP'])[1 + i % 5],
       (ARRAY['London','Paris','Berlin','New York','Tokyo'])[1 + i % 5] || ' ' || (i % 20)
FROM generate_series(1, 20000) AS i;
ANALYZE customers;
SET max_parallel_workers_per_gather = 0;

EXPLAIN (ANALYZE, BUFFERS)
SELECT c.name, o.id, o.total
FROM customers c JOIN orders o ON o.customer_id = c.id
WHERE c.id BETWEEN 100 AND 119;

Nested Loop  (cost=5.09..3699.00 rows=988 width=28) (actual time=0.025..2.262 rows=1000.00 loops=1)
  Buffers: shared hit=1063
  ->  Index Scan using customers_pkey on customers c  (cost=0.29..8.69 rows=20 width=18) (actual time=0.005..0.013 rows=20.00 loops=1)
        Index Cond: ((id >= 100) AND (id <= 119))
        Index Searches: 1
        Buffers: shared hit=3
  ->  Bitmap Heap Scan on orders o  (cost=4.80..184.03 rows=49 width=18) (actual time=0.008..0.107 rows=50.00 loops=20)
        Recheck Cond: (c.id = customer_id)
        Heap Blocks: exact=1000
        Buffers: shared hit=1060
        ->  Bitmap Index Scan on orders_customer_id_idx  (cost=0.00..4.79 rows=49 width=0) (actual time=0.003..0.003 rows=50.00 loops=20)
              Index Cond: (customer_id = c.id)
              Index Searches: 20
              Buffers: shared hit=60
Planning:
  Buffers: shared hit=175
Planning Time: 0.327 ms
Execution Time: 2.320 ms

20 customers, so the inner scan ran 20 times: 0.107 ms × 20 = 2.1 ms of the 2.26 ms total, and 50 rows × 20 = the 1,000 rows the join returned. Heap Blocks: exact=1000 and Index Searches: 20 are totals across the 20 loops.

The same join for 1,000 customers (everyone in Tokyo 4), with hash and merge joins turned off to force a nested loop:

SET enable_hashjoin = off;
SET enable_mergejoin = off;

EXPLAIN (ANALYZE, BUFFERS)
SELECT c.name, o.id, o.total
FROM customers c JOIN orders o ON o.customer_id = c.id
WHERE c.city = 'Tokyo 4';

Nested Loop  (cost=0.42..47097.47 rows=49378 width=28) (actual time=0.227..296.023 rows=50000.00 loops=1)
  Buffers: shared hit=44662 read=8489
  ->  Seq Scan on customers c  (cost=0.00..401.00 rows=1000 width=18) (actual time=0.157..1.801 rows=1000.00 loops=1)
        Filter: (city = 'Tokyo 4'::text)
        Rows Removed by Filter: 19000
        Buffers: shared read=151
  ->  Index Scan using orders_customer_id_idx on orders o  (cost=0.42..46.21 rows=49 width=18) (actual time=0.009..0.287 rows=50.00 loops=1000)
        Index Cond: (customer_id = c.id)
        Index Searches: 1000
        Buffers: shared hit=44662 read=8338
Planning:
  Buffers: shared hit=152 read=6
Planning Time: 0.453 ms
Execution Time: 298.085 ms

The index scan’s 0.287 ms looks harmless until you multiply: 0.287 × 1,000 = 287 ms, almost all of the 298 ms. Left to itself, the planner chose a hash join for this query instead.

When the outer side returns nothing, the inner side never runs (WHERE c.id = 0, with the planner’s own choice of join):

Nested Loop  (cost=5.09..200.21 rows=49 width=22) (actual time=0.053..0.056 rows=0.00 loops=1)
  Buffers: shared read=2
  ->  Index Scan using customers_pkey on customers c  (cost=0.29..8.30 rows=1 width=18) (actual time=0.052..0.053 rows=0.00 loops=1)
        Index Cond: (id = 0)
        Index Searches: 1
        Buffers: shared read=2
  ->  Bitmap Heap Scan on orders o  (cost=4.80..191.42 rows=49 width=12) (never executed)
        Recheck Cond: (customer_id = 0)
        ->  Bitmap Index Scan on orders_customer_id_idx  (cost=0.00..4.79 rows=49 width=0) (never executed)
              Index Cond: (customer_id = 0)
              Index Searches: 0

In a parallel plan, the default here, the per-loop numbers are per process:

->  Parallel Seq Scan on orders  (cost=0.00..15802.33 rows=4111 width=34) (actual time=1.874..20.326 rows=3333.33 loops=3)
      Filter: (status = 'cancelled'::text)
      Rows Removed by Filter: 330000

Three processes returned about 3,333 rows each (10,000 in all) and each spent about 20 ms, at the same time, so the query took about 25 ms, not 60.

In Inlet

Inlet draws EXPLAIN ANALYZE as a tree and highlights the slowest step and badly misestimated row counts. You can also paste a plan into the free plan visualizer.