Performance Forensics: A Slow Query, Traced End-to-End

The mental model: four layers, cheapest signal first

Performance forensics is not "open EXPLAIN and stare at it." It's an elimination sequence, cheapest and least specific signal first, each layer telling you whether it's worth paying for the next one:

Layer 1 — the query's own efficiency signature, from system.query_log. Before touching a plan, ask the cheapest possible question: how much did this query actually read, relative to what it returned? read_rows and read_bytes are documented as "Total number of rows [bytes] read from all tables and table functions participated in query," and result_rows is "Number of rows in the result of a SELECT query." A query reading 8 million rows to return 10 is not automatically broken — some aggregations legitimately need to touch most of a table — but it's the first fork in the road: does this ratio match what the query's own filter should achieve, or not? The same row also carries projections, documented as "Names of the projections used during the query execution" — an empty array here, for a query where a relevant projection exists, is itself a finding, not a null result.

Layer 2 — which mechanism actually engaged, from EXPLAIN indexes=1. system.query_log tells you how much was read. It doesn't tell you why. EXPLAIN indexes=1 shows, for the specific query, which of ClickHouse's pruning machinery actually fired: the primary key's Parts/Granules before and after filtering, any data skipping index's own Parts/Granules, and a Projections: block naming any projection that was actually selected and used to answer the query. This is the layer that turns "reading too much" into "the primary key didn't help" or "the skip index didn't help" or "a projection exists but wasn't picked," as three structurally different findings.

Layer 3 — the specific rule, from source. "Didn't help" is not an explanation on its own — each of the three has a different, specific, source-level reason: a primary key only narrows a range efficiently when the filtered column is a leading key column; a data skipping index's usefulness depends on its type matching the column's actual value distribution; a projection is selected only if it wins a direct read-cost comparison and its own filter is a subset of the query's filter. Naming which specific rule applies is what separates "add an index and hope" from an actual fix.

Layer 4 — the fix informed by the specific mechanism. A fix aimed at the wrong layer's problem (adding a projection when the real issue is index-type mismatch; reordering ORDER BY when the real issue is a projection's WHERE clause) burns effort without moving the ratio from Layer 1.

Codebase tour: where projection selection actually happens

Reading EXPLAIN indexes=1 end to end: a primary key that helps, and one that doesn't

ClickHouse's own guide to primary indexes runs this exact comparison on a real table, hits_UserID_URL, with ORDER BY (UserID, URL) — and it's worth reading in full before this lesson's walkthrough builds on it, because both outcomes below are real, captured output, not constructed for this course.

Filtering on UserID — the sorting key's leading column:

EXPLAIN indexes = 1
SELECT URL, count(URL) AS Count
FROM hits_UserID_URL
WHERE UserID = 749927693
GROUP BY URL
ORDER BY Count DESC
LIMIT 10;

┌─explain───────────────────────────────────────────────────────────────────────────────┐
│ Expression (Projection)                                                                │
│   Limit (preliminary LIMIT (without OFFSET))                                           │
│     Sorting (Sorting for ORDER BY)                                                     │
│       Expression (Before ORDER BY)                                                     │
│         Aggregating                                                                    │
│           Expression (Before GROUP BY)                                                 │
│             Filter (WHERE)                                                             │
│               SettingQuotaAndLimits (Set limits and quota after reading from storage)   │
│                 ReadFromMergeTree                                                       │
│                 Indexes:                                                                │
│                   PrimaryKey                                                            │
│                     Keys:                                                               │
│                       UserID                                                            │
│                     Condition: (UserID in [749927693, 749927693])                       │
│                     Parts: 1/1                                                          │
│                     Granules: 1/1083                                                    │
└───────────────────────────────────────────────────────────────────────────────────────┘

That's the primary key doing what a primary key is for: one out of 1083 granules possibly contains a matching row, so 1082 are never touched.

Filtering on URL — same table, same ORDER BY, but URL is the second key column, not the first:

SELECT UserID, count(UserID) AS Count
FROM hits_UserID_URL
WHERE URL = 'http://public_search'
GROUP BY UserID
ORDER BY Count DESC
LIMIT 10;

Processed 8.81 million rows, 799.69 MB (102.11 million rows/s., 9.27 GB/s.)
1076/1083 marks by primary key, 1076 marks to read from 5 ranges

Same table, same declared ORDER BY, same-shaped WHERE = 'literal' filter — and the primary key prunes almost nothing. The guide's own explanation is a source-level one, not a coincidence: "when a query is filtering on a column that is part of a compound key, but isn't the first key column, then ClickHouse is using the generic exclusion search algorithm" instead of binary search, and that algorithm's "effectiveness is dependant on the cardinality difference between the [filtered] column and its predecessor key column" — here, UserID (the predecessor) has cardinality similar to URL itself, so "the directly succeeding index mark does not have the same UserID value as the current mark," and the index can't rule most marks out. The table having a primary key told you nothing about whether it would help this query — only which column the filter hit did.

Debugging walkthrough: "we added an index, then a projection, and only one helped"

Symptom. This course's events table (user_id, campaign_id, event_type, event_time, url) is ORDER BY (user_id, event_time). A conversion-dashboard query filters WHERE url = 'https://checkout/confirm' — a column that isn't part of the sorting key at all. It's slow, and it's been getting slower as the table grows. A teammate's first move is to add a minmax index on url. It doesn't help. Their second move is a projection reordered by url. That helps — for the exact query they tested. A second, only slightly different query against the same table still isn't accelerated, and now the team genuinely can't tell why without opening more than the UI shows them.

Step 1 — before touching either fix, read the query's own efficiency signature. For the original slow query's query_id:

SELECT read_rows, read_bytes, result_rows, memory_usage, query_duration_ms, projections
FROM system.query_log
WHERE query_id = '3f8a1c2e-...' AND type = 'QueryFinish';

┌─read_rows─┬─read_bytes─┬─result_rows─┬─memory_usage─┬─query_duration_ms─┬─projections─┐
│  41802113 │  3980112640 │          10 │    118203904 │              4210 │          [] │
└───────────┴────────────┴─────────────┴──────────────┴───────────────────┴─────────────┘

read_rows is essentially the whole table for a query returning ten rows, and projections is empty — this query used no projection at all, confirmed rather than assumed. That's the Layer 1 signal: something isn't pruning, and whatever the team adds next, this same query afterward should show a materially smaller read_rows and a populated projections if it actually worked.

Step 2 — before the minmax index, confirm EXPLAIN indexes=1 explains why the base table alone is this expensive. url isn't in ORDER BY (user_id, event_time) at all. This course's Module 3 already established why that matters: a sparse primary index only stores marks for its declared sorting key, so a column that was never part of that key has no index entries to search against — a stronger version of hits_UserID_URL's URL-as-second-column case above, where at least a compound key existed for generic exclusion search to run over. The PrimaryKey block doesn't disappear in this case — a real captured example from a similar unusable-key-condition case shows it still printed, just degenerate: Condition: true, Parts: 3/3, Granules: 12208/12208, every part and granule selected because the condition couldn't be evaluated against the key at all. Either way, reading nearly every granule here is the expected, correct behavior of a primary key that was never built to answer this filter — not a bug to chase inside the index itself.

Step 3 — after adding the minmax index, re-run EXPLAIN indexes=1 rather than trusting that "an index was added."

Indexes:
  Skip
    Name: idx_url_minmax
    Description: minmax GRANULARITY 4
    Parts: 118/120
    Granules: 8340/8512

The index is there, and it is being consulted — Parts/Granules show it ran — but it barely reduced anything. This is the same structural reason hits_UserID_URL's guide gave for URL: minmax records a block's minimum and maximum value, and this course's own glossary already states the condition for that to help — the column's values need to "cluster together within blocks rather than being scattered evenly across the whole table." A checkout/confirm URL hit shows up throughout the table's entire time range, not clustered into a few granules, so nearly every block's min/max range still spans it. The index isn't malfunctioning; minmax was never going to help a column with this distribution, and no amount of re-tuning GRANULARITY fixes that — the fix has to change index type (a set or bloom_filter index, per this course's Module 3 glossary) or, as the team tried second, change physical layout entirely via a projection.

Step 4 — the projection that worked: confirm it in system.query_log, not just by feel. After materializing a projection ordered by url, re-running the original query:

SELECT read_rows, result_rows, projections
FROM system.query_log
WHERE query_id = '9b21f0a4-...' AND type = 'QueryFinish';

┌─read_rows─┬─result_rows─┬─projections──────────────────────────┐
│      6120 │          10 │ ['default.events.url_order_projection'] │
└───────────┴─────────────┴────────────────────────────────────────┘

projections naming default.events.url_order_projection directly, in the fully-qualified db.table.projection_name form ClickHouse's own documentation shows, is the confirmation — not a guess based on lower latency, which could have other causes. EXPLAIN indexes=1 corroborates it with its own dedicated block, distinct from PrimaryKey and Skip: ReadFromMergeTree (default.events) followed by Projections: and a Name: line for the projection used. Source-level, this is optimizeUseNormalProjections() at work: the projection has no WHERE clause of its own, so doesQueryFilterImplyProjectionWhere()'s conjunct-matching gate has nothing to fail against — it's trivially satisfied — and the projection wins the sum_marks comparison outright because its physical order makes url a leading key for that layout.

Step 5 — the second query that didn't get accelerated: confirm which of the two gates it failed. The team's second query adds AND event_type != 'pageview' to the same url filter, against a different projection someone had already built for a fraud-review tool — one materialized with its own WHERE event_type = 'click'. system.query_log.projections comes back empty for this second query, and the instinct is to assume the projection "doesn't cover" the query. It's narrower than that: event_type != 'pageview' does not structurally imply event_type = 'click' — plenty of rows satisfying the query's filter (any non-pageview, non-click event) would violate the projection's own filter, so using the projection could silently return wrong results, and doesQueryFilterImplyProjectionWhere() correctly refuses it. This isn't a sum_marks loss — the projection would almost certainly win on read cost if it were eligible at all. It fails the other gate, and no amount of adding more indexes fixes a WHERE-clause mismatch a projection was never built to serve.

Failure mode gallery

A data skipping index present and consulted, but structurally unable to help. EXPLAIN indexes=1's Skip block appearing with Parts/Granules barely reduced from the total, exactly as Step 3 above showed, is not the same finding as an index that isn't running at all — this course's glossary already distinguishes minmax (needs block-level clustering), set (needs a bounded number of distinct values per block), and bloom_filter (needs the filtered value to be rare, not clustered) as requiring three different, non-overlapping value distributions. The signature: someone adds an index, sees no improvement, and concludes "skip indexes don't work here" — when the actual finding is narrower: this index type doesn't match this column's distribution, and a different type might.

A projection that would clearly win on cost, and still isn't selected. system.query_log.projections staying empty despite an apparently on-topic projection existing is the signature Step 5 traced: doesQueryFilterImplyProjectionWhere() checks structural implication between the query's filter conjuncts and the projection's own, and a query filter that is semantically broader — but not textually a superset — than the projection's filter fails this check even when a human would call the projection "obviously" applicable. This is deliberately conservative: a projection is pre-filtered data, and using it for a query whose filter doesn't provably cover the projection's own filter risks silently wrong results, not just a missed optimization.

Read/result ratio looks healthy, but query_duration_ms is still high. This is the boundary of what this lesson's tools can diagnose. If system.query_log shows read_rows close to what the filter should actually match, and EXPLAIN indexes=1 shows the primary key and any relevant projection genuinely pruning well, the plan itself isn't the problem — the query is reading roughly the right amount of data and still taking too long somewhere inside execution. That's query-to-execution-plan's territory, not this lesson's: system.processors_profile_log, comparing elapsed_us against input_wait_elapsed_us/output_wait_elapsed_us per processor, is the tool for "the plan is fine, so which running processor is actually slow" — a genuinely different question from everything traced above.

Hands-on forensics: a diagnostic checklist for "why is this query reading so much"

1. Query system.query_log for the specific query_id first. read_rows, read_bytes, result_rows, memory_usage, query_duration_ms, projections. Is the read/result ratio consistent with what the filter should achieve? Is projections empty when you expected it populated?
2. If the ratio looks wrong, run EXPLAIN indexes=1 next — not before. Cross-referencing a genuinely healthy read/result ratio against a slow EXPLAIN read is wasted effort; Step 1 tells you whether Step 2 is even worth running.
3. Read the PrimaryKey block first. Does Keys include the column your filter actually hit? Is Granules: x/y meaningfully smaller than y? A table "having a primary key" is not evidence it helped this query — only the leading-column match does that.
4. Read every Skip block by index type, not just by presence. A skip index showing up with barely-reduced Granules is a type mismatch finding (locality for minmax, cap for set, rarity for bloom_filter), not a "the index is broken" finding.
5. If a candidate projection exists, check both gates independently. Would it win on sum_marks against the base table? Does the query's WHERE structurally imply the projection's own WHERE (trivially true if the projection has none)? A projection can pass one gate and fail the other, and system.query_log.projections only tells you the combined outcome, not which gate failed.
6. Only once the plan itself looks right — good ratio, real pruning, correct projection use — move to system.processors_profile_log. That tool answers "which running processor is slow," a different question from everything above it.