7. A query traced end to end
DuckDB · 7. A query traced end to endThis is the chapter that connects the previous five. One query, one machine, every stage named, with the time each stage actually takes.
The setup
Section titled “The setup” MACHINE 16 cores, 32 GB RAM, NVMe SSD
DATA s3-style layout on local disk: events/year=2026/month=*/part-*.parquet 41,318,022 rows 38 columns 84 Parquet files ~2,400 row groups 6.1 GB on disk
dimension table: customers.parquet 480,000 rows, 12 columnsSELECT c.segment, count(*) AS orders, sum(e.amount) AS revenueFROM 'events/**/*.parquet' eJOIN 'customers.parquet' c ON e.customer_id = c.idWHERE e.event_type = 'purchase' AND e.year = 2026 AND e.month >= 7GROUP BY ALLORDER BY revenue DESC;Total: 1.41 seconds. Here is where every millisecond went.
Stage 1 — Parser (0.4 ms)
Section titled “Stage 1 — Parser (0.4 ms)”The SQL string goes to a parser forked from PostgreSQL’s, producing a parse tree of statement nodes. Purely syntactic: it does not know whether events/**/*.parquet exists, whether segment is a column, or what sum means.
SelectStatement ├─ select_list: [c.segment, │ count(*), │ sum(e.amount)] ├─ from: JoinRef │ ├─ BaseTableRef 'events/**/*.parquet' │ └─ BaseTableRef 'customers.parquet' ├─ where: AND(=(e.event_type,'purchase'), │ AND(=(e.year,2026), │ >=(e.month,7))) ├─ groups: GROUP BY ALL ← still a marker └─ order: [revenue DESC]GROUP BY ALL is not expanded yet — it is a flag the binder will resolve, because expanding it requires knowing which select-list entries are aggregates.
Stage 2 — Binder (38 ms)
Section titled “Stage 2 — Binder (38 ms)”The binder attaches meaning to names, and this is where the two replacement scans fire.
'events/**/*.parquet' — a table? not in the catalog. → REPLACEMENT SCAN → looks like a path with a glob → rewrite as read_parquet('events/**/*.parquet')
GLOB the filesystem 84 files OPEN each file's FOOTER 84 reads, ~30 KB each UNIFY the schemas 38 columns, types agree DETECT hive partitioning year=, month= → two extra columnsThirty-eight of the forty-two milliseconds are footer reads. On a local NVMe that is trivial; over S3 those would be 84 HTTP round trips and this stage would be several hundred milliseconds — which is exactly what enable_object_cache (chapter 5) removes on the second run.
Then:
─ `e.amount` → column 14 of the events binding, type DOUBLE ─ `sum` → the aggregate function sum(DOUBLE) → DOUBLE ─ `count(*)` → the count-star aggregate ─ `c.segment` → column 3 of customers, VARCHAR ─ `e.customer_id = c.id` → BIGINT = BIGINT, an equality join condition ─ GROUP BY ALL → resolved: the select list has one non-aggregate, `c.segment`. GROUP BY c.segment. ─ `revenue` in ORDER BY → the alias of sum(e.amount)Output: a logical plan, correct but unoptimised.
ORDER BY revenue DESC AGGREGATE group: c.segment agg: count(*), sum(e.amount) FILTER event_type='purchase' AND year=2026 AND month>=7 JOIN e.customer_id = c.id GET read_parquet('events/**/*.parquet') GET read_parquet('customers.parquet')Note what is wrong with that plan. The filter is above the join, so it would join 41 million rows and then throw most of them away. Fixing that is the next stage’s job.
Stage 3 — Optimiser (11 ms)
Section titled “Stage 3 — Optimiser (11 ms)”A sequence of rewrite passes over the logical plan. The ones that matter here:
Filter pushdown
Section titled “Filter pushdown” FILTER moves BELOW the join, and splits:
year=2026 AND month>=7 → these are HIVE PARTITION columns. They become a FILE-LIST filter, evaluated before any file is opened.
event_type='purchase' → pushed into the events GET as a scan filter. 84 files → partition filter (year=2026, month>=7) → 31 files survive → 53 files never opened at allProjection pushdown
Section titled “Projection pushdown” The query needs, from events: customer_id, amount, event_type (+ year, month from the path)
→ 3 of 38 columns are read. 35 column chunks are never touched.Join order and side selection
Section titled “Join order and side selection” ESTIMATED CARDINALITIES: customers 480,000 (from the footer) events 41.3M, × selectivity of event_type='purchase' ≈ 0.22 → ~9M estimated
→ BUILD the hash table on CUSTOMERS (the small side) → PROBE with eventsGetting this backwards is the single most expensive optimiser mistake, and chapter 8 is about how it gets it right and when it does not.
The rest
Section titled “The rest” ─ common subexpression elimination ─ constant folding: `2026` stays a literal ─ the ORDER BY is on ~40 output rows, so it is trivial and stays where it is ─ TOP-N is not applicable (no LIMIT)Result: a physical plan.
ORDER_BY revenue DESC HASH_GROUP_BY c.segment count_star(), sum(amount) HASH_JOIN INNER e.customer_id = c.id │ ├─ (build) PARQUET_SCAN customers │ projection: id, segment │ └─ (probe) PARQUET_SCAN events files: 31 of 84 projection: customer_id, amount, event_type filter: event_type = 'purchase'Stage 4 — Pipeline construction (0.2 ms)
Section titled “Stage 4 — Pipeline construction (0.2 ms)”The physical plan is cut at every pipeline breaker (chapter 4).
PIPELINE 1 customers scan → hash join BUILD ▲ breaker
PIPELINE 2 events scan → filter → hash join PROBE → group-by SINK ▲ breaker (depends on 1)
PIPELINE 3 group-by SOURCE → order-by SINK ▲ breaker (depends on 2)
PIPELINE 4 order-by SOURCE → result (depends on 3)Stage 5 — Execution
Section titled “Stage 5 — Execution”Pipeline 1 — build the hash table (46 ms)
Section titled “Pipeline 1 — build the hash table (46 ms)” customers.parquet, 480,000 rows, 2 columns projected
4 row groups → 4 morsels → 4 threads (only 4, because the file has only 4 row groups. The other 12 cores idle here. This is chapter 4's point about needing enough morsels.)
each thread: read → decode → insert into the SHARED hash table (this one is shared, with atomic insert into partitioned buckets)
result: a hash table, 480,000 entries, ~22 MBPipeline 2 — the scan, the probe, the aggregate (1,290 ms)
Section titled “Pipeline 2 — the scan, the probe, the aggregate (1,290 ms)”This is 91% of the query. All sixteen threads, morsel by morsel.
31 files → ~890 row groups → 890 morsels 16 threads pulling from the shared queue
PER MORSEL (one thread, ~122k rows):
1. read the byte ranges for 3 column chunks ~0.9 ms 2. decode: dictionary + RLE + bitpacking → vectors ~0.4 ms 3. filter event_type='purchase' → a SELECTION VECTOR. ~27k of 122k rows survive. No data is copied. ~0.1 ms 4. probe the hash table with customer_id, through the selection vector ~0.6 ms 5. push matched rows into this THREAD'S OWN aggregate hash table, keyed by segment ~0.3 ms
≈ 2.3 ms per morsel 890 morsels × 2.3 ms ÷ 16 threads ≈ 1.28 sNotice step 5. Each thread aggregates into its own hash table with no locking. With only 40 distinct segments, each thread’s table has 40 entries and lives entirely in L1 cache. This is why the aggregation is nearly free and the scan is the cost.
The combine (4 ms)
Section titled “The combine (4 ms)” 16 thread-local hash tables × 40 segments each → merged into one 40-row resultPipeline 3 and 4 — the sort and the output (0.8 ms)
Section titled “Pipeline 3 and 4 — the sort and the output (0.8 ms)”Forty rows. Nothing to say.
The accounting
Section titled “The accounting” parse 0.4 ms 0.03% bind (84 footers) 38 ms 2.7% optimise 11 ms 0.8% build pipelines 0.2 ms 0.01% pipeline 1 (build) 46 ms 3.3% pipeline 2 (scan/probe/ aggregate) 1,290 ms 91.4% combine 4 ms 0.3% sort + output 0.8 ms 0.06% ───────────────────────────────────────── TOTAL 1,410 msAnd what the optimiser saved:
files opened 31 of 84 -63% columns read 3 of 38 -92% rows past filter 9.1M of 41.3M -78%
Without pushdown, the same query reads 6.1 GB and joins 41 million rows. With it, it reads 340 MB and joins 9 million.
Measured: 1.41 s versus 14.8 s.A factor of ten, from three optimiser passes that took eleven milliseconds to decide. That is the argument of chapter 9 in one number.
What you would see in a profile
Section titled “What you would see in a profile”PRAGMA enable_profiling = 'query_tree'; ┌───────────────────────────┐ │ ORDER_BY │ 0.8ms │ 40 rows │ └─────────────┬─────────────┘ ┌─────────────┴─────────────┐ │ HASH_GROUP_BY │ 52.0ms │ segment │ │ 40 rows │ └─────────────┬─────────────┘ ┌─────────────┴─────────────┐ │ HASH_JOIN │ 640.0ms │ INNER cust_id = id │ │ 9,142,003 rows │ └──────┬─────────────┬──────┘ ┌──────┴──────┐ ┌────┴──────────────┐ │PARQUET_SCAN │ │ PARQUET_SCAN │ │ customers │ │ events │ │ 480,000 │ │ filters: 1 │ │ 46.0ms │ │ files: 31/84 │ └─────────────┘ │ 9,142,003 rows │ │ 698.0ms │ └───────────────────┘Read it in this order, every time:
files: 31/84— did partition pruning work? If it says 84/84, your filter did not push down.- The row count out of the scan. 9.1M out of 41.3M means the filter is being applied in the scan, not above it.
- Where the time is. Scan plus join is 1.34 s of 1.41 s — this query is I/O and probe bound, which is the healthy shape.
- Which side built. If the profile shows the 41-million-row side as the build, you have found your problem.
The one-line version
Section titled “The one-line version” STRING → parse tree (syntax only) → LOGICAL PLAN (names resolved, types known) → OPTIMISED LOGICAL (filters pushed, columns pruned, join order chosen) → PHYSICAL PLAN (hash join, hash aggregate chosen) → PIPELINES (cut at breakers) → MORSELS (row groups, one atomic queue, all cores) → thread-local results → combined → ANSWERWhat to take from this chapter
Section titled “What to take from this chapter”- 41 million rows, 6.1 GB, one machine, 1.41 seconds — and 91% of it is one pipeline doing scan, probe and aggregate.
- The parser is syntax only. The binder resolves names, and it is where the replacement scan turns a path into
read_parquet, globs the files and reads 84 footers — 2.7% locally, and the dominant cost over S3 untilenable_object_cachecaches it. - The unoptimised logical plan joins first and filters after. Fixing that is the optimiser’s whole job here.
- Three passes did the work: partition pruning (84 files → 31), projection pushdown (38 columns → 3), and choosing the small side to build.
- Pipelines are cut at breakers: join build, aggregate, sort. Four pipelines, executed in dependency order.
- The scan pipeline runs 890 morsels across 16 threads, each doing read → decode → selection-vector filter → probe → thread-local aggregate. No locking until the combine.
- Pipeline 1 used only 4 threads because the file had only 4 row groups — parallelism is bounded by morsels, not by cores.
- Eleven milliseconds of optimisation saved thirteen seconds: 1.41 s with pushdown against 14.8 s without.
- Read a profile in this order: files pruned, rows out of the scan, where the time sits, which side built.
Next: the optimiser itself — cardinality estimation, join ordering, and the statistics that decide whether any of this happens.