Parsing EXPLAIN JSON Output #

A 400-line text plan from a reporting query is open in your editor, and the question is simple: which three nodes consumed the time? Reading it by eye means mentally subtracting nested timings through a dozen levels of indentation, multiplied by loop counts. FORMAT JSON turns the same plan into a tree you can query, and PostgreSQL can query it for you.

The option set that produces the fields used here is described in EXPLAIN options and output formats. This page is the method for extracting answers from it.

The Structure and the Inclusive-Time Rule #

EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) returns a JSON array with one element per statement. Each element holds a Plan object and summary keys:

[
  {
    "Plan": {
      "Node Type": "Hash Join",
      "Actual Total Time": 812.4,
      "Actual Rows": 91840,
      "Actual Loops": 1,
      "Shared Hit Blocks": 20410,
      "Shared Read Blocks": 18822,
      "Plans": [
        { "Node Type": "Seq Scan", "Relation Name": "orders", "Parent Relationship": "Outer", "…": "…" },
        { "Node Type": "Hash", "Parent Relationship": "Inner", "Plans": [ { "…": "…" } ] }
      ]
    },
    "Planning Time": 1.21,
    "Execution Time": 815.9
  }
]

Two rules govern every calculation:

  1. Per-loop values. Actual Total Time and Actual Rows are averages per loop. A node’s total is the value multiplied by Actual Loops.
  2. Inclusive values. A node’s time and buffer counts include everything beneath it. Exclusive cost is the node’s total minus the sum of its direct children’s totals.

Some nodes break rule 2 in harmless ways — an InitPlan or SubPlan appears as a child with a Parent Relationship of InitPlan or SubPlan, and parallel workers are folded into totals — but for ranking hot spots the rule holds. It is the same arithmetic described for text output in reading cost vs actual time in EXPLAIN ANALYZE.

Inclusive totals and exclusive time A Hash Join node with inclusive total 812 milliseconds has two children: a Seq Scan with 402 milliseconds and a Hash node with 310 milliseconds. The Hash node's own child, a Seq Scan, totals 288 milliseconds. Exclusive time is 100 milliseconds for the Hash Join, 22 for the Hash, and 402 and 288 for the scans. Hash Join · total 812 exclusive 812 − 402 − 310 = 100 Seq Scan orders · 402 leaf: exclusive = 402 Hash · total 310 exclusive 310 − 288 = 22 Seq Scan customers · 288 totals = per-loop time × loops

Annotated Evidence: Flattening the Tree in SQL #

Store plans in a table first:

CREATE TABLE captured_plans (
  id          bigserial PRIMARY KEY,
  captured_at timestamptz DEFAULT now(),
  label       text,
  plan        jsonb
);

DO $$
DECLARE p json;
BEGIN
  EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) '
       || 'SELECT c.name, sum(o.total) FROM orders o JOIN customers c ON c.id = o.customer_id GROUP BY c.name'
  INTO p;
  INSERT INTO captured_plans (label, plan) VALUES ('revenue-by-customer', p::jsonb);
END $$;

Then flatten it with a recursive CTE that carries a path for each node, so children can be matched to their parent:

WITH RECURSIVE nodes AS (
  SELECT cp.id AS plan_id,
         ARRAY[0]            AS path,
         cp.plan -> 0 -> 'Plan' AS node
  FROM captured_plans cp WHERE cp.label = 'revenue-by-customer'
  UNION ALL
  SELECT n.plan_id,
         n.path || (c.ord::int - 1),
         c.child
  FROM nodes n,
       jsonb_array_elements(n.node -> 'Plans') WITH ORDINALITY AS c(child, ord)
),
totals AS (
  SELECT plan_id, path,
         node ->> 'Node Type'                         AS node_type,
         node ->> 'Relation Name'                     AS relation,
         (node ->> 'Actual Loops')::numeric           AS loops,
         (node ->> 'Actual Total Time')::numeric
           * (node ->> 'Actual Loops')::numeric       AS incl_ms,
         (node ->> 'Shared Read Blocks')::bigint      AS incl_read
  FROM nodes
)
SELECT t.node_type, t.relation, t.loops,
       round(t.incl_ms - coalesce(sum(c.incl_ms), 0), 1)     AS excl_ms,
       t.incl_read - coalesce(sum(c.incl_read), 0)            AS excl_read_blocks
FROM totals t
LEFT JOIN totals c
  ON c.plan_id = t.plan_id
 AND c.path[1:array_length(t.path, 1)] = t.path
 AND array_length(c.path, 1) = array_length(t.path, 1) + 1
GROUP BY t.plan_id, t.path, t.node_type, t.relation, t.loops, t.incl_ms, t.incl_read
ORDER BY excl_ms DESC
LIMIT 5;
   node_type    | relation  | loops | excl_ms | excl_read_blocks
----------------+-----------+-------+---------+------------------
 Seq Scan       | orders    |     1 |   402.1 |            18104
 Seq Scan       | customers |     1 |   288.3 |              718
 HashAggregate  |           |     1 |   141.9 |                0
 Hash Join      |           |     1 |   100.2 |                0
 Hash           |           |     1 |    22.0 |                0
-- excl_ms: the node's own work; the scan of orders is the hot spot
-- excl_read_blocks: disk reads attributable to that node alone

For quick searches that do not need the parent–child arithmetic, SQL/JSON path queries are shorter:

-- every node that spilled to disk, anywhere in the tree
SELECT n ->> 'Node Type' AS node, n ->> 'Sort Method' AS method,
       n ->> 'Sort Space Used' AS kb, n ->> 'Sort Space Type' AS space
FROM captured_plans,
     jsonb_path_query(plan, 'strict $[0].**') AS n
WHERE label = 'revenue-by-customer'
  AND n ? 'Node Type'
  AND (n ->> 'Sort Space Type' = 'Disk' OR (n ->> 'Temp Written Blocks')::int > 0);
Keys used for exclusive time Four JSON keys are annotated. Actual Total Time is per loop and inclusive. Actual Loops multiplies it. Plans holds the children to subtract. Shared Read Blocks is inclusive I/O. "Actual Total Time": 0.04 per loop, includes children "Actual Loops": 250000 multiply before anything else "Plans": [ … ] children to subtract "Shared Read Blocks": 18822 inclusive I/O, subtract too

Step-by-Step Resolution #

  1. Capture JSON with the options you will query. ANALYZE for times and rows, BUFFERS for block counts, VERBOSE if you need output columns. Keys only exist for options that were requested.

  2. Store it as jsonb. jsonb supports path queries and indexing; keep the original capture label, server version and settings alongside.

  3. Flatten the tree with the recursive query above, or a variant keyed on your own table.

  4. Compute totals, then exclusive values. Multiply per-loop values by loops before subtracting children. For parallel plans, times on parallel-aware nodes are already averaged across workers; treat exclusive values as relative, not absolute.

  5. Rank and inspect. Order by exclusive time or exclusive read blocks, then open the top nodes in the text plan to read their conditions. Compare two captures of the same query by joining on node_type and path to see which node regressed.

From JSON plan to ranked hot nodes Four stages left to right: capture EXPLAIN JSON into jsonb, flatten with a recursive CTE into one row per node, compute exclusive time and buffers by subtracting children, and order by exclusive time to get the hot nodes. capture FORMAT JSON → jsonb flatten recursive CTE + path subtract node − children rank ORDER BY excl_ms the same pipeline works on auto_explain JSON log lines

Before and After #

-- BEFORE: reading 400 lines of text, top-level node "took" 815 ms
Hash Join  (actual time=402.6..812.4 rows=91840 loops=1)

-- AFTER: exclusive ranking from JSON
Seq Scan orders 402.1 ms · Seq Scan customers 288.3 ms · HashAggregate 141.9 ms

Common Pitfalls #

Summing inclusive times. Adding Actual Total Time across nodes counts leaf work repeatedly. Diagnostic signal: node totals that add up to several times Execution Time. Fix: subtract children before summing or ranking.

Forgetting loops. A nested-loop inner index scan with Actual Total Time: 0.04 and Actual Loops: 250000 costs 10 seconds, not 40 microseconds. Diagnostic signal: the real bottleneck ranking near the bottom. Fix: multiply by Actual Loops first.

Treating missing keys as zero. Shared Read Blocks is absent without BUFFERS; Actual Total Time is absent with TIMING OFF. Diagnostic signal: every node reporting zero I/O. Fix: check ? for the key and record which options the capture used.

Using json instead of jsonb for path queries. jsonb_path_query requires jsonb. Diagnostic signal: a function-does-not-exist error on the path call. Fix: cast with ::jsonb when inserting.

Frequently Asked Questions #

How do I get EXPLAIN JSON into a table I can query? Capture EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) into a jsonb column, for example with EXECUTE … INTO in PL/pgSQL. For production plans, set auto_explain.log_format = json and load the log lines into the same table.

Why do my per-node times add up to more than the execution time? Actual Total Time is inclusive of children and reported per loop. Multiply by Actual Loops, then subtract the children’s totals to get exclusive time.

Are the JSON keys stable across PostgreSQL versions? The core keys have been stable for many releases. New options add new keys, so parsers should ignore unknown keys and treat missing ones as absent rather than zero.

Up: EXPLAIN Options and Output Formats