From b1411ce291d6655616d9f9c8f0f59acbd32c4df0 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 9 Jul 2026 21:44:25 -0400 Subject: [PATCH 1/6] Add portable query-plan-analysis skill A self-contained Agent Skill that teaches any Claude agent to read a SQL Server execution plan without needing PerformanceStudio installed. Nothing in it refers to this repo, so the directory copies out cleanly. The valuable content is negative knowledge -- the confident-sounding conclusions that are wrong. Cost percentages are estimates even in actual plans. Row-mode operator times are cumulative, so ranking by raw ActualElapsedms ranks by depth and always crowns the root. Estimated vs actual rows must be normalized by ActualExecutions or the inner side of every nested loop looks catastrophically underestimated. Missing-index requests emit equality columns in arbitrary order and ignore existing indexes. Contents: SKILL.md seven-step triage, ordered to establish ground truth before forming an opinion, plus a "not evidence" list scripts/ extract.py flattens a .sqlplan into a digest; --node drills into one operator; --sql recovers full statement text references/ timing, cardinality, warnings, parallelism, indexes, operators, and a no-Python fallback extract.py exists because .sqlplan files are UTF-16 (so grep silently matches nothing), some declare an encoding they don't use, and a trivial plan is 120 KB while the largest fixture here is 7 MB. It mirrors PlanAnalyzer.Timing.cs and NodeTimeAttribution.cs for self-time attribution: batch mode reports standalone times, row mode cumulative, exchange operators accumulate downstream wait time, and parallel self-time must subtract within a thread rather than across threads. Validated by seven agents with no prior context, run against the 299 example plans. All reached correct conclusions, including on three traps: a plan with nothing wrong, a no-join-predicate warning that was a false alarm, and an estimated-only plan where the correct answer is to decline and ask for an actual plan. Their findings fixed a real bug (Table Spool matched the Index Spool detection, so update plans were told they needed an index), a documentation hole that would have produced a wrong cross-join diagnosis, two factual errors about scalar-UDF parallelism reasons and parallel self-time arithmetic, and an answer key that had leaked from a test fixture into SKILL.md. Co-Authored-By: Claude Opus 4.8 (1M context) --- skills/query-plan-analysis/SKILL.md | 231 ++++ .../references/cardinality.md | 127 ++ .../references/extracting-without-python.md | 92 ++ .../query-plan-analysis/references/indexes.md | 139 +++ .../references/operators.md | 138 ++ .../references/parallelism.md | 106 ++ .../query-plan-analysis/references/timing.md | 149 +++ .../references/warnings.md | 207 +++ skills/query-plan-analysis/scripts/extract.py | 1108 +++++++++++++++++ 9 files changed, 2297 insertions(+) create mode 100644 skills/query-plan-analysis/SKILL.md create mode 100644 skills/query-plan-analysis/references/cardinality.md create mode 100644 skills/query-plan-analysis/references/extracting-without-python.md create mode 100644 skills/query-plan-analysis/references/indexes.md create mode 100644 skills/query-plan-analysis/references/operators.md create mode 100644 skills/query-plan-analysis/references/parallelism.md create mode 100644 skills/query-plan-analysis/references/timing.md create mode 100644 skills/query-plan-analysis/references/warnings.md create mode 100644 skills/query-plan-analysis/scripts/extract.py diff --git a/skills/query-plan-analysis/SKILL.md b/skills/query-plan-analysis/SKILL.md new file mode 100644 index 0000000..39e2ad4 --- /dev/null +++ b/skills/query-plan-analysis/SKILL.md @@ -0,0 +1,231 @@ +--- +name: query-plan-analysis +description: Analyze a SQL Server execution plan (.sqlplan / showplan XML) and explain what is actually slow and why. Use whenever a user shares a query plan, asks why a query is slow, asks what an operator means, asks whether an index would help, or asks you to interpret estimated vs actual rows, spills, memory grants, or parallelism. Prevents the standard wrong conclusions - reading cost percentages as measurements, calling scans bad, or pasting missing-index DDL verbatim. +--- + +# Reading a SQL Server execution plan + +A query plan tells you what SQL Server *decided* to do and, if it's an actual +plan, what happened when it did. Most bad plan analysis comes from confusing +those two things, or from reaching for the most visually obvious number rather +than the one that means something. + +Work through the triage order below. It exists to establish ground truth before +you form an opinion, because almost every wrong conclusion about a plan comes +from forming the opinion first. + +## Step 0: extract the plan before you read it + +**Never read a `.sqlplan` file directly into context, and never `grep` one.** + +- They are large. A trivial two-table join runs 120 KB; real plans run into + megabytes. Reading one wastes your context and you will still miss things, + because the interesting attributes are scattered across thousands of lines. +- They are usually **UTF-16**, so `grep`, `rg`, and friends silently match + nothing. Finding no `PlanAffectingConvert` in a UTF-16 plan tells you + nothing at all about whether the plan contains one. +- Some plans lie about their own encoding: SSMS writes UTF-16, but a plan + that has been opened and re-saved is often UTF-8 bytes still declaring + `encoding="utf-16"`. Strict XML parsers reject those. + +Run the bundled extractor, which handles all of this and prints a digest ordered +to match the steps below. Use the **absolute path** to `extract.py` — your +working directory is not necessarily the skill root: + +``` +python /absolute/path/to/skills/query-plan-analysis/scripts/extract.py /path/to/plan.sqlplan +``` + +Add `--top 20` to widen the ranked sections on a large plan. + +When you need more detail about one operator — its predicates, its seek keys, its +per-thread numbers — do **not** open the raw XML. Ask the extractor: + +``` +python .../scripts/extract.py /path/to/plan.sqlplan --node 16 +``` + +That prints everything known about node 16: object and index, predicate, seek +predicate, outer references, output columns, estimates, actuals, and per-thread +stats. The digest already surfaces predicates for the hot and warned operators, +so you will often not need it. + +If Python is genuinely unavailable, see `references/extracting-without-python.md`. + +## Step 1: is this an actual plan or an estimated plan? + +The digest says so explicitly. It decides what you are allowed to conclude. + +An **estimated plan** contains no runtime information whatsoever. Every row +count in it is a guess, nothing ran, and you cannot say anything about what +was slow. You can reason about plan *shape*, index usage, obvious type +mismatches, and estimates that are self-evidently wrong. You cannot say "this +operator took the longest" because no operator took any time. + +An **actual plan** has runtime counters. Now you can talk about time. + +If someone asks why a query is slow and hands you an estimated plan, say that +you need an actual plan and explain how to capture one, rather than guessing +from cost percentages. + +## Step 2: read the warnings SQL Server already gave you + +These are free. They require no inference, and they are the highest +signal-to-noise content in the entire plan. The digest lists them all, tagged +with the node they came from. + +Spills, implicit conversions, missing statistics, memory grant problems, and +no-join-predicate warnings all appear here. Read `references/warnings.md` for +what each one means and what to do about it. Several are more subtle than they +look, and at least one (no join predicate) is frequently a false alarm. + +## Step 3: find where the time went, never where the cost went + +This is the single most important rule in this document. + +**Cost is always an estimate. Always.** The "Query cost (relative to batch): +97%" figure that SSMS puts at the top of a plan is computed from the +optimizer's guesses. It is present in actual plans. It is *not* a measurement, +it does not get updated with what really happened, and the highest-cost +operator in a plan is routinely not the slow one. A plan can show an operator +at 0% cost that consumed the entire query's runtime. + +Never say "this operator is 97% of the cost, so it's the problem." Instead: + +- Use the digest's **TOP OPERATORS BY SELF TIME** section. +- Or read `QueryTimeStats` for total elapsed and CPU, and per-operator + `RunTimeCountersPerThread` for the breakdown. + +Self time is not the number printed on the operator. In row mode, an operator's +elapsed and CPU are **cumulative** — they include everything beneath it — so +sorting operators by their raw `ActualElapsedms` always crowns the root node. +Batch mode reports each operator standalone. Exchange operators report times +that are nearly meaningless. Getting this wrong produces confident, precise, +completely inverted answers, which is the worst failure mode available to you. + +Two things the operator list will not tell you, and both are commonly the answer: + +- **`UdfCpuTime`.** A scalar UDF's time is not attributed to any operator. If + `` reports a large `UdfCpuTime` or `UdfElapsedTime`, that is the + query, whatever the operators say. The digest prints it as a percentage of + elapsed and as a per-invocation cost. +- **Self times need not sum to the total.** In a parallel plan they legitimately + exceed it, because elapsed is the max across threads and branches overlap. Do + not second-guess a correct answer because the arithmetic looks off. + +Read `references/timing.md` before you say anything about where time went. It +is short and it is the part most likely to embarrass you. + +## Step 4: find where the estimates went wrong + +Compare estimated rows to actual rows — but **per execution**, not in total. + +On the inner side of a nested loop join, an operator runs once per outer row. +Showplan reports `EstimateRows` per execution and `ActualRows` as the sum +across all executions. Dividing is mandatory: + +``` +actual per execution = ActualRows / ActualExecutions +``` + +An operator showing "estimated 1 row, actual 4,000,000 rows" that ran 4,000,000 +times estimated perfectly. Announcing a four-million-times underestimate there +is the most common way to be loudly wrong about a plan. The digest does this +division for you. + +Large skew in either direction is worth investigating; see +`references/cardinality.md`, which also covers the optimizer's default guess +selectivities. When an estimate lands on exactly 30% of table cardinality, the +optimizer had no useful statistics and guessed — that is a fingerprint, and it +points at a different fix than a merely stale histogram. + +## Step 5: check for skew before you trust a parallel plan + +A parallel plan that ran DOP 8 but did all its work on one thread is a serial +plan that also paid for coordination. The digest reports per-thread row +distribution. Idle workers mean the rows did not distribute, and the usual +cause is upstream — an uneven partition key or a serial zone feeding the +exchange. See `references/parallelism.md`. + +Also: high CPU relative to elapsed is normal and expected in a parallel plan. +It is not evidence of a problem by itself. Eight threads working for one second +burn eight CPU-seconds. + +## Step 6: parameters, then memory grants + +The digest prints `ParameterCompiledValue` against `ParameterRuntimeValue`. If +they differ, the plan was built for one value and executed with another. That +is parameter sniffing, sitting in plain sight, and it explains a large share of +"the same query is sometimes fast and sometimes slow" reports. + +For memory grants, compare `GrantedMemory` to `MaxUsedMemory`. A query granted +9 GB that used 200 MB is stealing memory from everything else on the server and +may be waiting to get it (`GrantWaitTime`). A query that spilled despite a large +grant usually has skew, not a grant sizing problem. + +## Step 7: only now, missing indexes + +The `` element is a hint about which predicates went unserved. +It is **not** DDL to hand to a user. + +- The equality columns come out in arbitrary order. Key order is the single + most important decision in index design and SQL Server does not make it. +- It ignores every index that already exists, so it will happily ask for a + near-duplicate of one you have. +- It ignores the rest of the workload. +- Its `Impact` percentage is relative to the estimated cost of a plan you have + already established is estimated. +- `INCLUDE` lists are frequently enormous, because it includes every column the + query touches. + +Read the request as "a seek on these columns would have helped." Then design the +index yourself, considering existing indexes and column selectivity. See +`references/indexes.md`. + +## Things that are not evidence + +Say none of these: + +- **"There's a scan, that's bad."** A scan of a small table is optimal. A seek + executed four million times is not. Scans of a 200-row lookup table are fine + forever. Judge by rows touched and time spent, not operator name. +- **"The thick arrow is the problem."** Arrow thickness is row count, and in an + estimated plan it is *guessed* row count. Rows are not time. +- **"Cost is 97% here."** See step 3. +- **"Key lookups are always bad."** A key lookup on 12 rows is nothing. On 12 + million it is the whole query. The count is what matters. +- **"The optimizer chose a bad plan."** Usually the optimizer chose the correct + plan for the row counts it was given, and the row counts were wrong. Fix the + estimate and the plan often fixes itself. Diagnose the estimate first. +- **"This query needs `OPTION (RECOMPILE)` / `MAXDOP 1` / a hint."** Hints + suppress symptoms. Reach for them after you understand the cause, and say + what the cause was. + +## Writing the answer + +Lead with what is actually slow and why, in one sentence, before any detail. +Quote the numbers you used and name their source, so the reader can check you: +name the operator, its node id, its self elapsed time, and the query's total +elapsed time, in that form. Precision about *which* number you are citing — self +time versus cumulative, per-execution versus total, estimated versus actual — is +the difference between a useful answer and a plausible one. + +Then say what you ruled out, and why. "The memory grant used 17% of what it +asked for, so this is not a grant problem" is worth a line, because it stops the +reader from chasing it next. + +If the plan does not support a conclusion, say so. "This is an estimated plan, +so I can tell you the shape looks wrong but not what was slow" is a good +answer. Inventing a bottleneck from cost percentages is not. + +## Reference files + +| File | Read it when | +|---|---| +| `references/timing.md` | Before making any claim about where time went | +| `references/cardinality.md` | Estimates disagree with actuals | +| `references/warnings.md` | The plan carries any warning | +| `references/parallelism.md` | The plan is parallel | +| `references/indexes.md` | You are about to recommend an index | +| `references/operators.md` | You need to explain a specific operator | +| `references/extracting-without-python.md` | Python is unavailable | diff --git a/skills/query-plan-analysis/references/cardinality.md b/skills/query-plan-analysis/references/cardinality.md new file mode 100644 index 0000000..3abff6d --- /dev/null +++ b/skills/query-plan-analysis/references/cardinality.md @@ -0,0 +1,127 @@ +# Estimates versus actuals + +Most bad plans are good plans built on bad row counts. Diagnose the estimate +before you blame the optimizer. + +## Always normalize per execution + +Showplan reports these on different bases: + +- `EstimateRows` — rows the optimizer expects **per execution** of the operator. +- `ActualRows` — rows actually emitted, **summed over every execution and every + thread**. +- `ActualExecutions` — how many times the operator ran, summed over threads. + +So the only valid comparison is: + +``` +actual per execution = ActualRows / ActualExecutions +skew = (actual per execution) / EstimateRows +``` + +An index seek on the inner side of a nested loop that shows `EstimateRows="1"` +and `ActualRows="4000000"` over `ActualExecutions="4000000"` estimated +**perfectly**. Reporting a 4-million-times underestimate there is the single most +common way to be loudly wrong about a plan, and it is instantly recognizable to +anyone who knows plans. + +`EstimateExecutions` (or `EstimateRebinds` + `EstimateRewinds`) tells you what +the optimizer expected the execution count to be. When the row estimate per +execution is right but the *execution count* is badly wrong, the problem is on +the outer side of the join, not at the operator you are looking at. + +## The optimizer's default guesses + +When statistics are missing or unusable, the optimizer applies fixed selectivity +guesses. Estimates that land on these fractions of `TableCardinality` are a +fingerprint: they mean the optimizer had nothing to work with, and the fix is to +give it information, not to hint the query. + +| Guess | Selectivity | Typical trigger | +|---|---|---| +| Equality | 30% | `col = @var` with no usable statistic; table variable | +| Inequality | 10% | `col > @var`, `col < @var` | +| `LIKE` / `BETWEEN` | 9% | `col LIKE @pattern` | +| Compound predicate | ~16.4% | two filters combined under the new CE | +| Multiple inequalities | 1% | `col > @a AND col < @b` | + +The new cardinality estimator (`CardinalityEstimationModelVersion` 120 and +above) also uses *exponential backoff* when combining predicates, rather than the +legacy CE's independence assumption. Two predicates each 10% selective estimate +at roughly 3.2% under the old model and roughly 5.6% under the new one. Neither +is right when the columns are correlated. + +`scripts/extract.py` flags estimates that match these fingerprints. + +## Common causes, in rough order of frequency + +**Table variables.** Before SQL Server 2019 (or under compatibility level below +150), a table variable always estimates 1 row regardless of contents, because it +has no statistics. Deferred compilation in 2019+ fixes the *initial* estimate but +not subsequent modifications. A table variable feeding a nested loop join is the +classic cause of a plan that works on a laptop and dies in production. + +**Implicit conversion on a predicate.** If the column's type must be converted to +match the literal or parameter, the optimizer cannot use the histogram and falls +back to a guess. See `warnings.md`. + +**A function wrapping the column.** `WHERE YEAR(OrderDate) = 2024` is not +SARGable. The optimizer has no statistic on `YEAR(OrderDate)` and guesses. Rewrite +as a range: `WHERE OrderDate >= '2024-01-01' AND OrderDate < '2025-01-01'`. + +**Stale statistics.** The histogram describes data that no longer exists. Check +whether the estimate matches what the table *used to* look like. Auto-update +triggers at roughly `SQRT(1000 * rowcount)` modifications for large tables, which +on a billion-row table is a million rows — a table can drift very far while +statistics still count as fresh. + +**Correlated predicates.** `WHERE City = 'Chicago' AND State = 'IL'` — the +optimizer multiplies the two selectivities as if independent, and badly +underestimates. Multi-column statistics or a filtered index can help. + +**Parameter sniffing.** The estimate is correct for the value the plan was +compiled with and wrong for the value it ran with. Check +`ParameterCompiledValue` against `ParameterRuntimeValue`. This is not a bad +estimate in the usual sense — the histogram was fine — so the fix is different. + +**Local variables and `OPTIMIZE FOR UNKNOWN`.** A local variable's value is not +known at compile time, so the optimizer uses the density vector (average rows per +distinct value) rather than the histogram. This produces a stable, mediocre +estimate rather than a good one. + +**Multi-statement table-valued functions.** Fixed estimate of 1 row before 2014, +100 rows from 2014 on, regardless of what the function returns. Interleaved +execution in 2017+ fixes this for the first execution. Inline TVFs do not have the +problem at all. + +## Which direction matters + +**Underestimate** — the optimizer thinks fewer rows than there are. It picks +nested loops, key lookups, serial plans, and too-small memory grants. The result +is spills, and joins that repeat millions of times. Underestimates usually +present as a query that is much slower than it should be. + +**Overestimate** — the optimizer thinks more rows than there are. It picks hash +joins, sorts, parallelism, and enormous memory grants. The result is memory +pressure, `RESOURCE_SEMAPHORE` waits, and concurrency collapse across the +instance. Overestimates often present as one query that is fine alone and a +server that falls over under load. + +An overestimate can also cause an eager index spool: the optimizer decides that +building a temporary index at runtime will pay for itself over the many rows it +expects, then builds it for a handful of rows. If you see one, look for a large +overestimate on the operator feeding it. + +## What to do about it + +In order of preference: + +1. Fix the estimate. Update statistics, remove the implicit conversion, make the + predicate SARGable, replace the table variable with a temp table. +2. Give the optimizer information it does not have. Multi-column statistics, + filtered statistics, a filtered index. +3. Restructure the query so the bad estimate does not matter. Materializing an + intermediate result into a `#temp` table gives the optimizer real statistics + at the cost of a write. +4. Only then, hints. And when you use one, say what estimate it is compensating + for. diff --git a/skills/query-plan-analysis/references/extracting-without-python.md b/skills/query-plan-analysis/references/extracting-without-python.md new file mode 100644 index 0000000..cd89656 --- /dev/null +++ b/skills/query-plan-analysis/references/extracting-without-python.md @@ -0,0 +1,92 @@ +# Getting at a plan without the extractor + +Use `scripts/extract.py` when you can. This file is the fallback. + +## The encoding problem comes first + +`.sqlplan` files written by SSMS are **UTF-16**. Text tools see a null byte +between every character: + +- `grep PlanAffectingConvert plan.sqlplan` matches nothing, even when the plan is + full of implicit conversions. It reports no match rather than an error, so a + negative result is worthless. +- `head`, `cat`, and `wc -l` produce garbage. + +Convert first: + +``` +iconv -f UTF-16 -t UTF-8 plan.sqlplan > plan.utf8.xml +``` + +Some plans are UTF-8 bytes that still declare `encoding="utf-16"` in the XML +prolog, because someone opened and re-saved them. `iconv` will fail on those and +strict XML parsers will reject them. Check the first bytes: if the file starts +with the literal characters `` records which predicates the optimizer could not serve with an +existing index. That is genuinely useful information. The `CREATE INDEX` +statement people paste out of it is not a recommendation, and shipping it +verbatim is the fastest way to look like you do not know what you are doing. + +What is wrong with it: + +- **Equality column order is arbitrary.** Showplan emits them in column-id order, + not selectivity order. Key column order is the most consequential decision in + index design. SQL Server does not make it for you. +- **Existing indexes are ignored.** The optimizer asks for what would help *this* + query, with no regard for the eleven indexes already on the table. Following the + requests one at a time produces near-duplicate indexes that all have to be + maintained on every write. +- **The `INCLUDE` list is every other column the query touches.** On a wide + `SELECT` this can be most of the table, producing an index nearly as large as + the table itself. +- **`Impact` is a percentage of an estimated cost.** It is an estimate of the + improvement to an estimate. It is not a promise, and a 99% impact figure on a + query with bad cardinality means nothing. +- **It never suggests a clustered index, a filtered index, or a columnstore**, + and it never suggests *dropping* anything. + +## Reading it properly + +Take the column groups as evidence about the query's access pattern: + +- `EQUALITY` columns — predicates of the form `col = something`. These belong at + the front of the key. +- `INEQUALITY` columns — `>`, `<`, `BETWEEN`, `LIKE 'x%'`. These belong after all + the equality columns. Everything after the first inequality column in a key can + only be used as a residual filter, not for seeking, so there is rarely a reason + to have more than one. +- `INCLUDE` columns — columns the query needs to return but does not filter or + join on. Adding them avoids a key lookup at the cost of index size. + +Order the equality columns by selectivity, most selective first, unless you know +the workload wants otherwise. Then check what indexes already exist: an existing +index whose key is a prefix of what you want should usually be *modified* rather +than joined by a new one. + +## Key lookups + +A `Key Lookup` (or `RID Lookup` on a heap) means a nonclustered index found the +rows but did not contain every column the query needed, so SQL Server went back +to the clustered index once per row. + +Whether it matters is entirely about the row count. Look at `ActualExecutions` on +the lookup: that is how many times it ran. Twelve is free. Twelve million is the +whole query. + +Two fixes: + +- Add the missing columns to the nonclustered index's `INCLUDE` list. Cheap, + effective, and grows the index. +- Return fewer columns. Frequently the query is selecting columns nobody uses. + +A lookup with a **residual predicate** — a `Predicate` element on the lookup +operator itself — is worse than it looks. It means the filter could not be applied +until after the lookup, so SQL Server paid for the lookup on rows it then +discarded. Compare `ActualRows` on the lookup against `ActualRows` on its parent. +The gap is wasted work, and moving that predicate's column into the index key +eliminates it. + +## Scans are not the enemy + +A `Clustered Index Scan` is a table scan. That is not automatically a defect. + +- Scanning a 200-row table is optimal. An index seek would be slower. +- Scanning is correct when the query genuinely needs most of the table. +- The optimizer chooses a scan over a seek when it estimates the seek plus + lookups would cost more. Above roughly 1% selectivity for a wide row, that is + usually correct arithmetic. + +What makes a scan a problem is a *selective predicate* that the scan had to apply +itself. Check the operator's `ActualRowsRead` against `ActualRows`. Reading 17 +million rows to emit 200 means the predicate ran as a filter instead of a seek. +*That* is worth fixing — and the fix is an index, or making the predicate +SARGable, not "avoiding the scan." + +`ActualRowsRead` is only present when a predicate is pushed into the scan. Its +absence, with `ActualRows` equal to `TableCardinality`, means the query really did +want the whole table. + +## Non-SARGable predicates + +SQL Server cannot seek on an expression it does not have an index for. These force +a scan and, worse, a cardinality guess: + +| Non-SARGable | Rewrite | +|---|---| +| `WHERE YEAR(d) = 2024` | `WHERE d >= '20240101' AND d < '20250101'` | +| `WHERE ISNULL(c, 0) = 5` | `WHERE c = 5` (handle NULL separately if needed) | +| `WHERE c LIKE '%foo'` | Full-text, or store a reversed computed column | +| `WHERE CAST(c AS VARCHAR) = '5'` | Fix the type on the other side | +| `WHERE c + 0 = 5` | `WHERE c = 5` | +| `WHERE ABS(c) = 5` | `WHERE c IN (5, -5)` | + +A leading wildcard `LIKE '%foo'` cannot seek under any index and never will. +`LIKE 'foo%'` seeks fine. + +An `OR` across different columns often defeats index usage entirely; the optimizer +may expand it into a union of seeks, or may give up and scan. Check whether it +did. `UNION ALL` of two well-indexed queries is frequently faster and always more +predictable. + +## Eager index spool + +An `Index Spool` with logical operation `Eager Spool` means the optimizer decided +to build a temporary index in tempdb, at runtime, because no suitable permanent +index existed. It builds it from scratch on every execution. + +This is the optimizer telling you, in the loudest voice it has, exactly which +index to create. Take the spool's `SeekPredicate` for the key columns and its +`OutputList` for the includes. The digest prints both under `PREDICATES ON HOT / +WARNED OPERATORS`; `extract.py --node N` prints the full detail. + +An eager spool is *eager*: it fully materializes before returning any rows. +Combined with a large overestimate on its input, it can dominate a query's +runtime entirely — building a temporary index over millions of rows to serve a +handful of seeks. + +**An eager index spool usually suppresses the missing-index request.** The plan +will contain no `` element, and the request will not appear in +`sys.dm_db_missing_index_details` either. So "SQL Server didn't suggest an index" +is not evidence that no index is needed — when a spool is present, it is evidence +of the opposite. Nothing will prompt you. You have to recognize the spool as the +request. + +In a parallel plan the spool build runs on a single thread while the others block +on it, which surfaces as `EXECSYNC` near the top of ``. That wait and +the spool are one finding, not two. + +Eager spools also appear legitimately in update plans, where they protect against +the Halloween Problem. Those are not defects. diff --git a/skills/query-plan-analysis/references/operators.md b/skills/query-plan-analysis/references/operators.md new file mode 100644 index 0000000..51d2d7a --- /dev/null +++ b/skills/query-plan-analysis/references/operators.md @@ -0,0 +1,138 @@ +# Operators worth understanding + +Not a catalogue. These are the ones whose presence changes what you should +conclude. + +## Reading order + +Plans display right to left, and data flows that way: leaves produce rows, the +root consumes them. But *logical* execution order is a depth-first walk from the +root — the root asks its first child for a row, which asks its first child, and so +on. Nested loops joins make this matter: the outer input (first child) drives, and +the inner input (second child) runs once per outer row. + +In the XML, child `RelOp` elements appear nested inside the operator-specific +element (``, ``, ``). **The first child `RelOp` is the +outer input.** Confusing outer and inner inputs inverts your entire analysis of a +nested loop. + +## Joins + +**Nested Loops** — for each row from the outer input, probe the inner. Optimal +when the outer is small and the inner has a supporting index. Catastrophic when +the outer input is large, because the inner runs once per row. Check +`ActualExecutions` on the inner side. The presence of `` means +the join correlates by passing values in, which is why a `NoJoinPredicate` +warning on a nested loop is often noise. + +**Hash Match** — builds a hash table from the build input (first child), probes +with the second. Needs a memory grant. Blocking on the build side: no rows come +out until the build input is fully consumed. Spills when the grant is too small, +which is nearly always an underestimate on the build input. Fine for large, +unsorted, unindexed joins. Its presence is not a defect. + +**Merge Join** — both inputs must be sorted on the join key. Very cheap when they +already are, because indexes provide the order. Expensive when the optimizer has +to add a `Sort` to make it work. A merge join with a sort beneath it is often a +worse choice than the hash join the optimizer rejected. A `many-to-many` merge +join uses a worktable in tempdb and is materially slower. + +**Adaptive Join** (2017+, batch mode) — defers the hash-versus-loop decision until +runtime based on actual row count. `ActualJoinType` tells you what it picked. + +## Spools + +Spools materialize rows into a hidden temporary object in tempdb. + +**Eager Spool** — reads its entire input before returning a single row. See +`indexes.md`. An eager *index* spool is the optimizer asking for an index. + +**Lazy Spool** — reads on demand, returning rows as it goes. Cheaper. + +**Table Spool / Row Count Spool** — caches a result for reuse. + +An eager spool also appears legitimately in update plans, protecting against the +Halloween Problem. Do not report those as defects. + +## Filter + +A `Filter` operator applies a predicate that could not be pushed down into a scan +or seek. Its position matters: everything below it did work on rows the filter +then discarded. Compare its `ActualRows` to its child's — the difference is +wasted. + +`Filter` with a `StartupExpression` is a startup filter guarding a branch that may +not execute at all. That is an optimization, not a problem. + +## Compute Scalar + +Usually free, and usually carries **no runtime statistics at all**. Do not +conclude that a Compute Scalar took zero time from its absent numbers; the work is +generally deferred and attributed to the operator that consumes its output. This +absence breaks naive self-time arithmetic (see `timing.md`). + +A Compute Scalar invoking a scalar UDF is a very different animal. See below. + +## Scalar UDFs + +Before SQL Server 2019, a scalar UDF in a query: + +- Runs once per row, as an interpreted call +- Is costed by the optimizer at essentially zero +- Forces the **entire plan serial** (`NonParallelPlanReason` = + `TSQLUserDefinedFunctionsNotParallelizable`) +- Does not appear as its own operator, so its time hides inside whatever calls it + +This combination — invisible in the plan, free according to cost, catastrophic in +reality — makes it the single most common cause of a query whose plan looks fine +and runs for minutes. Check ``. If it is +present and large, that is your answer regardless of what the operators say. + +SQL Server 2019 introduced Froid, which inlines many scalar UDFs into the calling +query. When inlining happens, the UDF's work becomes visible as real operators and +the plan may go parallel. Inlining is disabled by various constructs +(`WHILE` loops, time-dependent functions, `@@ROWCOUNT`, and others), so a 2019+ +plan can still contain a non-inlined UDF. + +## Sort + +Blocking — nothing comes out until everything has gone in. Needs a memory grant. +Spills to tempdb when the grant is short. + +A sort you did not ask for is the optimizer meeting a requirement of something +else: a merge join, a stream aggregate, a `DISTINCT`, an order-preserving +exchange. Removing the requirement removes the sort. An index that provides the +order removes it entirely. + +`Sort (Top N Sort)` with a small N is cheap and does not need a full sort. + +## Aggregates + +**Stream Aggregate** — requires sorted input, aggregates as it goes, no memory +grant. Cheap when an index provides the order. + +**Hash Match (Aggregate)** — no ordering requirement, needs a grant, can spill. + +**Hash Match (Partial Aggregate)** — a pre-aggregation below an exchange in a +parallel plan, reducing rows before they cross threads. Its presence is good. + +## Key Lookup / RID Lookup + +See `indexes.md`. Judge by `ActualExecutions`, never by presence. + +## Table Valued Function + +A multi-statement TVF appears as a single operator with a fixed row estimate (1 +before 2014, 100 after) regardless of what it returns. An inline TVF does not +appear at all — it is expanded into the calling query, which is why inline TVFs +are almost always preferable. + +## Constant Scan + +Produces a fixed set of rows, often zero or one. Common under `Nested Loops` for +`OR` expansion, and above an `Index Seek` in a `MERGE`. Rarely interesting. + +## Parallelism + +See `parallelism.md`. Its timings are unreliable and it is almost never the actual +problem, even when it looks expensive. diff --git a/skills/query-plan-analysis/references/parallelism.md b/skills/query-plan-analysis/references/parallelism.md new file mode 100644 index 0000000..78842fe --- /dev/null +++ b/skills/query-plan-analysis/references/parallelism.md @@ -0,0 +1,106 @@ +# Parallel plans + +## CPU exceeding elapsed is normal + +Eight threads working for one second burn eight CPU-seconds. `CpuTime` several +times `ElapsedTime` in `` is what parallelism *is*. It is not +evidence of a problem, and saying "CPU time is 5x elapsed time, something is +wrong" is a tell that you do not read plans. + +What is worth noting is CPU *close to* elapsed in a plan running at DOP 8: the +plan went parallel and got no benefit, so it paid coordination costs for nothing. + +## Thread skew + +`` has one entry per thread. **Thread 0 is the +coordinator**, not a worker. It generally shows zero rows for most operators, and +for exchange operators its elapsed time is the wall clock of the whole branch. +Exclude it when assessing distribution. + +Compare `ActualRows` across worker threads. Healthy is roughly even. Unhealthy: + +- **One worker has everything, the rest have zero.** The branch is effectively + serial and paid for parallelism anyway. Usually an exchange upstream failed to + distribute, or the branch sits on the inner side of a nested loop and runs on + one thread per outer row by design. +- **Distribution follows a skewed key.** `Repartition Streams` hashing on a + column where one value dominates. Every row with that value lands on one + thread. Repartition on a more selective column, or restructure. +- **Some workers idle entirely.** Fewer distinct hash values than threads. + +Skew is the usual reason a parallel plan is slower than its serial version. It is +also the usual reason for a hash spill on one thread while the grant looks +generous: memory is divided evenly across threads, so the thread with all the +rows spills while the others sit on unused memory. + +## Exchange operators + +`Parallelism` is the physical operator. The logical operator says what it does: + +- **Distribute Streams** — serial input, parallel output. One thread to many. +- **Repartition Streams** — parallel in, parallel out, rows reshuffled across + threads. The `PartitionColumns` element says on what. +- **Gather Streams** — parallel input, serial output. Many threads to one. + +Their timings are unreliable. An exchange accumulates the time it spends waiting +for whatever is downstream, so a spilling sort above a Gather Streams inflates the +gather's numbers. Never point at an exchange and say it is slow. See +`timing.md`. + +An **order-preserving exchange** (`Gather Streams` with an ``) is a merge +of sorted streams and is materially more expensive than an unordered one. It also +serializes on the slowest thread. Usually appears under a merge join or above a +sort feeding an `ORDER BY`. It is a common cause of exchange spills and, in older +builds, intra-query parallel deadlocks. + +## Why a plan did not go parallel + +`` tells you directly. Common values: + +- `MaxDOPSetToOne` +- `EstimatedDOPIsOne` — the optimizer costed a parallel plan and did not want it +- `NoParallelPlansInDesktopOrExpressEdition` +- `NoParallelWithRemoteQuery` +- `TSQLUserDefinedFunctionsNotParallelizable` — a scalar UDF anywhere in the + query forced the entire plan serial. +- `CouldNotGenerateValidParallelPlan` — **also very commonly a scalar UDF.** + +Do not treat `TSQLUserDefinedFunctionsNotParallelizable` as the only UDF tell. +Real plans containing a serial-forcing scalar UDF frequently report +`CouldNotGenerateValidParallelPlan` instead. Whenever a large query is stubbornly +serial, check `` regardless of which reason +string the plan gives. Before SQL Server 2019 this is a very common and very +expensive silent penalty. + +A serial plan whose dominant wait is `CXPACKET` looks self-contradictory and is +not. The outer statement is serial; the UDF's internal queries went parallel, once +per row, and their waits aggregate into the plan. Large `UdfCpuTime` alongside +serial DOP and heavy `CXPACKET` is a scalar UDF, not a puzzle. + +## DOP and the cost threshold + +`` is the DOP actually used. A plan goes +parallel only if its *estimated* serial cost exceeds `cost threshold for +parallelism` (default 5, which was calibrated in 1997 and is far too low). So the +decision to parallelize rests entirely on estimates — an overestimate can produce +a parallel plan for a query that returns four rows. + +Also: `DegreeOfParallelism` is what the optimizer requested. The query may have +run with fewer threads if none were available. Count distinct worker threads in +`RunTimeCountersPerThread` to see what it actually got. + +## Serial zones inside a parallel plan + +A parallel plan is not parallel everywhere. Between exchange operators the plan is +divided into branches, and each branch has its own DOP. Some operators force a +serial zone: + +- Scalar UDFs (pre-2019) +- `TOP` in certain positions +- Backward scans +- Global aggregates above a `Gather Streams` +- Sequence functions like `ROW_NUMBER()` over an unpartitioned window, which + must serialize + +If the expensive operator sits in a serial zone, DOP is irrelevant to it and +raising MAXDOP will not help. diff --git a/skills/query-plan-analysis/references/timing.md b/skills/query-plan-analysis/references/timing.md new file mode 100644 index 0000000..b9cc5c2 --- /dev/null +++ b/skills/query-plan-analysis/references/timing.md @@ -0,0 +1,149 @@ +# Where the time actually went + +The numbers on a plan operator do not mean what they look like they mean. This +file is the one that keeps you from being confidently, precisely wrong. + +## Cost is not time + +`EstimatedTotalSubtreeCost`, `StatementSubTreeCost`, and SSMS's "Query cost +(relative to batch): 97%" are all derived from the optimizer's row estimates and +a fixed hardware model from the late 1990s. They are **estimates in every plan, +including actual plans**. Nothing recomputes them after execution. + +Consequences: + +- The highest-cost operator is frequently not the slow one. +- An operator can show 0% cost and consume the entire runtime. A scalar UDF is + the classic case: pre-2019 the optimizer costs it at essentially nothing while + it runs once per row. +- Two plans' cost numbers are only comparable if their estimates were equally + good, which is exactly what you are trying to determine. + +Use cost to understand *why the optimizer chose what it chose*. Never use it to +say what was slow. + +## Row mode reports cumulative time; batch mode does not + +Every `RelOp` in an actual plan carries `` with one +`` per thread. The attributes you care about: + +| Attribute | Meaning | Aggregate across threads by | +|---|---|---| +| `ActualRows` | rows emitted | **sum** | +| `ActualRowsRead` | rows examined before the predicate | **sum** | +| `ActualExecutions` | times this operator started | **sum** | +| `ActualCPUms` | CPU consumed | **sum** | +| `ActualElapsedms` | wall clock | **max** | +| `ActualLogicalReads` | pages read from buffer pool | **sum** | + +Elapsed takes the max because threads run concurrently; the operator finished +when its slowest thread finished. CPU sums because every thread burned its own. + +Now the trap. In **row mode**, `ActualElapsedms` and `ActualCPUms` are +**cumulative**: an operator's numbers include everything in its subtree. The +root node's elapsed time is therefore the whole query's elapsed time. Sorting +operators by raw `ActualElapsedms` sorts them by depth, and always crowns the +root. This is meaningless and it looks authoritative. + +In **batch mode**, operators pipeline, and each reports its own standalone time. +No subtraction needed. Check `ActualExecutionMode` (falling back to +`EstimatedExecutionMode`) per operator — a single plan can mix both. + +## Computing self time + +For a row-mode operator: + +``` +self elapsed = ActualElapsedms - sum(effective elapsed of each child) +self CPU = ActualCPUms - sum(effective CPU of each child) +``` + +For a batch-mode operator, self time is the reported time. Do not subtract. + +Three complications make "effective elapsed of each child" more than a lookup: + +**Pass-through operators carry no runtime stats.** Compute Scalar is the usual +one. Its `ActualElapsedms` is absent or zero, not because it was instant but +because SQL Server does not record it. Subtracting zero for it makes its parent +absorb the whole subtree below. When a child has no runtime stats, look *through* +it and sum its children instead. + +**Exchange operators lie.** `Parallelism` (Gather Streams, Repartition Streams, +Distribute Streams) accumulates time spent waiting on whatever is downstream. A +spilling sort above an exchange inflates the exchange's numbers. Worse, thread 0 +of an exchange is the coordinator, and its elapsed time is the wall clock for the +entire parallel branch, not the operator's own work. + +When computing an exchange's own time, ignore thread 0 and use the slowest worker +thread. When an exchange is a *child* and you need its contribution to a parent, +take the max over its children rather than its own reported number. Treat any +self time you compute for an exchange as advisory. Do not build a conclusion on +it. + +**Parallel plans must subtract within a thread, never across threads.** For each +thread *t*: + +``` +self[t] = parent_elapsed[t] - sum(child_elapsed[t]) +self = max over t of self[t] +``` + +Subtracting an aggregate child total from an aggregate parent total mixes threads +that never ran together and produces garbage, frequently negative, which then +clamps to zero and hides the real hotspot. + +`scripts/extract.py` implements all of this. Prefer it to doing the arithmetic +by hand. + +## Batch-mode subtrees under a row-mode parent + +If a row-mode operator sits above a contiguous batch-mode region, that region's +operators each reported standalone times. To subtract the region's contribution +from the row-mode parent, **sum** the batch operators' elapsed times across the +region, stopping at any `Parallelism` boundary. Taking just the topmost batch +operator's time undercounts and inflates the parent's apparent self time. + +## Statement-level totals + +`` on the `QueryPlan` element gives the authoritative totals: + +- `ElapsedTime` — wall clock, milliseconds +- `CpuTime` — CPU, milliseconds +- `UdfElapsedTime` / `UdfCpuTime` — time inside scalar UDFs, when present + +`UdfCpuTime` is worth checking whenever it exists. It is time the plan's +operators mostly do not attribute to themselves, and it is often the answer. + +CPU far exceeding elapsed means parallelism, which is expected. Elapsed far +exceeding CPU means the query spent its life waiting — check ``, and +`GrantWaitTime` in ``. + +## Self times need not sum to the total in a parallel plan + +In a **serial row-mode** plan, per-operator self elapsed times should roughly sum +to `QueryTimeStats/@ElapsedTime`. If they sum to several times the total, you +forgot to subtract children. + +In a **parallel** plan they legitimately exceed it, sometimes substantially. Each +operator's elapsed is the max across its threads, and separate branches of the +plan run concurrently, so overlapping work is counted more than once. Two hot +operators showing 69.6s and 25.5s in a query that took 71.1s is not an arithmetic +error and does not mean you double-counted. Do not talk yourself out of a correct +answer because the numbers do not add up — in a parallel plan, they should not. + +Self **CPU** behaves differently again: it sums across threads, so total CPU +routinely exceeds total elapsed by roughly the degree of parallelism. That is what +parallelism is. + +## Sanity checks before you publish a number + +- Is your top operator by self time the root node? Then you almost certainly + computed cumulative time, not self time. +- Did you compute a negative self time and clamp it? That is a signal you + subtracted across threads or through an exchange, not a signal the operator + took zero time. +- Are you quoting a self elapsed time next to a *cumulative* CPU number? They are + not comparable and the pairing is nonsense. Self elapsed and self CPU are both + fine to quote, as long as you say which is which. +- Did you check `UdfCpuTime`? If it is large, the operators are lying to you by + omission and the answer is the scalar UDF. diff --git a/skills/query-plan-analysis/references/warnings.md b/skills/query-plan-analysis/references/warnings.md new file mode 100644 index 0000000..0d45a31 --- /dev/null +++ b/skills/query-plan-analysis/references/warnings.md @@ -0,0 +1,207 @@ +# Warnings SQL Server puts in the plan + +These require no inference. They are the highest signal-to-noise content in a +plan. They appear in a `` element, which can hang off the `QueryPlan` +(statement-level) or off any `RelOp` (operator-level). The location matters — +"a spill happened" is much less useful than "the hash join at node 3 spilled." + +Some are attributes on ``; some are child elements. Both are listed +below. + +## Implicit conversion — `` + +Attributes: `ConvertIssue`, `Expression`. + +Two distinct issues share this element, and they are not equally serious: + +- **`ConvertIssue="Seek Plan"`** — the conversion prevented an index seek. The + query is scanning where it could have sought. This is usually the expensive + one. +- **`ConvertIssue="Cardinality Estimate"`** — the conversion did not block the + seek but did prevent the optimizer from using the histogram, so the estimate + is a guess. Bad plan shape downstream. + +Cause: comparing columns of different types, so SQL Server converts one side. +The conversion happens on whichever side has *lower datatype precedence*. If the +column loses, the index on it becomes unusable for seeking. + +Most common in practice: + +- `NVARCHAR` parameter compared to a `VARCHAR` column. `NVARCHAR` has higher + precedence, so the *column* gets converted. Very common with ORMs, which + default to sending Unicode. This one blocks seeks. +- `VARCHAR` parameter against an `NVARCHAR` column converts the *parameter*, + which is harmless. +- Numeric types against string columns, always bad. +- A `DATE` column compared against a `DATETIME` literal. + +Fix by making the types match — change the parameter's type, or the column's. +Do not fix it by wrapping the column in `CAST`, which makes the predicate +non-SARGable and achieves nothing. + +Note that SQL Server does not always emit this warning even when an implicit +conversion is present. Its absence is not proof. + +## Spills — ``, ``, ``, `` + +The operator asked for memory, got less than it needed, and wrote to tempdb. + +`SpillLevel` matters. Level 1 is a single pass. Higher levels mean recursive +spilling — the spilled partition itself did not fit and spilled again — and cost +grows sharply. Level 3 and above is pathological and usually indicates severe +skew in the hash key rather than an undersized grant. + +`SpilledThreadCount` against the plan's DOP tells you whether the spill was +uniform or a skew problem. One thread of eight spilling is a data distribution +problem, not a memory problem. + +`GrantedMemoryKb` versus `UsedMemoryKb` on the spill detail elements shows +whether the grant was even close. + +The root cause of most spills is an **underestimate** upstream: the memory grant +is sized from estimated rows. Fix the estimate and the spill usually disappears. +Granting more memory treats the symptom, and takes memory from other queries. + +An **exchange spill** is different in character. It usually means a +`Repartition Streams` or `Gather Streams` deadlocked on its buffers and is +frequently caused by an order-preserving exchange under a merge join. It is +worth treating as its own problem rather than as "another spill." + +## Missing statistics — `` + +The optimizer wanted a histogram on a column and there wasn't one. Every estimate +involving that column is a default guess (see `cardinality.md`). + +Common causes: `AUTO_CREATE_STATISTICS` is off; the column is in a table variable; +the predicate is against a column of a type that cannot have statistics. + +Not always actionable, but when present alongside a large cardinality skew on the +same table it is very likely the cause. + +## Stale statistics — `` + +Newer builds only. Says exactly what it says. Update the statistics and recompile. + +## Memory grant — `` + +Attributes: `GrantWarningKind`, `RequestedMemory`, `GrantedMemory`, +`MaxUsedMemory` (all KB). + +`GrantWarningKind` is one of `ExcessiveGrant`, `GrantIncrease`, or +`UsedMoreThanGranted`. + +An excessive grant is a server-wide problem, not a query problem. The query may +run fine while starving everything else. Look at +`GrantedMemory / MaxUsedMemory` — a ratio above about 10x deserves attention, and +above 50x is severe. + +Grants are sized from estimated rows *and* estimated row size. A query selecting +`VARCHAR(MAX)` or wide `NVARCHAR` columns gets a grant based on **half the +declared maximum width**, not actual data length. `SELECT` of a `VARCHAR(8000)` +column that always contains 20 characters still reserves 4000 bytes per row. This +is why "just select fewer columns" is real advice and not a platitude. + +## No join predicate — `` + +**Frequently a false alarm.** Read this one skeptically. + +It genuinely fires for an accidental cross join. But it also fires when the +optimizer removed a redundant join predicate during simplification, and when an +`APPLY` correlates via an outer reference rather than a join predicate — both of +which are completely fine. + +Three cases, each with a positive tell. Check them in this order. The digest's +`PREDICATES ON HOT / WARNED OPERATORS` section prints everything you need, and +`extract.py --node N` gives you the full detail for the joining operator. + +**Correlated APPLY or outer reference (benign).** The join operator has an +`` list. Values are passed into the inner side rather than +compared by a predicate, so there is nothing for the warning to find. + +**Transitive predicate elimination (benign, and the most common false alarm).** +This one has *neither* an `` list *nor* a join predicate, so it +superficially resembles the bad case. The tell is on the join's **inputs**, not +the join. If both children are independently filtered to the same constant — each +carrying a `Predicate` or `SeekPredicate` against the same literal — then the +optimizer proved the join predicate redundant and dropped it. + +It happens any time you filter a join column by a constant: + +```sql +SELECT TOP (1) c.Id +FROM dbo.Posts AS p +JOIN dbo.Comments AS c ON p.OwnerUserId = c.UserId +WHERE p.OwnerUserId = 22656; +``` + +Given `p.OwnerUserId = 22656` and `p.OwnerUserId = c.UserId`, it follows that +`c.UserId = 22656`. SQL Server pushes `= 22656` into both tables and discards the +join condition, which trips the warning. Both inputs are pinned to the same +value, so the "cross join" emits exactly the right rows. Confirm by checking that +the join's output row count did not multiply. + +**Genuine cross join (bad).** No outer references, no join predicate, and the +inputs are *not* both pinned to the same constant. The output row count is +roughly the product of the input row counts. That multiplication is the +signature — an accidental cartesian product is loud. + +## Unmatched indexes — `` + +A filtered index could not be used because the query was parameterized and the +optimizer cannot prove at compile time that the parameter satisfies the filter +predicate. The child `` elements name the index. + +Fixes: add `OPTION (RECOMPILE)`, or write the filter predicate explicitly into +the query's `WHERE` clause so the optimizer can match it. + +## Wait stats — `` / `` + +Present in actual plans on reasonably modern builds. `WaitType`, `WaitTimeMs`, +`WaitCount`. + +The ones worth naming: + +- `RESOURCE_SEMAPHORE` — waiting for a memory grant. Somebody's grant is too big, + possibly this query's. +- `PAGEIOLATCH_SH` — reading data pages from disk. Either the working set does not + fit in memory or the query is reading far more than it needs. +- `CXPACKET` / `CXCONSUMER` — parallelism coordination. `CXCONSUMER` is generally + benign. High `CXPACKET` with thread skew points at the skew, not at parallelism. +- `EXECSYNC` — threads blocked waiting for a serial phase of a parallel plan, + classically the build of an **eager spool**. When `EXECSYNC` is near the top and + an eager index spool is present, it is the same finding twice: the other threads + sat idle while one built the spool. It corroborates, it is not a separate + problem. +- `LCK_M_*` — blocking. The plan cannot tell you who blocked you. +- `SOS_SCHEDULER_YIELD` — CPU pressure, or a spinlock. Rarely the query's fault. +- `ASYNC_NETWORK_IO` — the client is not consuming results fast enough. Not a plan + problem at all, and no amount of tuning fixes it. + +**A serial plan showing heavy `CXPACKET` is not a contradiction.** If +`DegreeOfParallelism` is 0 or 1 and `NonParallelPlanReason` is set, but `CXPACKET` +dominates the waits and `UdfCpuTime` is large, the outer statement ran serially +while the scalar UDF's *own internal queries* each went parallel. The waits are +aggregated from those inner executions. Do not let the apparent contradiction talk +you out of a correct scalar-UDF diagnosis. + +Waits are cumulative across threads, so a parallel query shows inflated wait +times. Compare against `QueryTimeStats/@ElapsedTime` before concluding anything. + +## Spill occurred / spatial guess / full update for online index build + +`` appears in lightweight profiling output and only tells you that +*something* spilled. `` and `` are +informational and rarely the story. + +## What is NOT in the warnings + +Absence of a warning proves nothing. SQL Server does not warn about: + +- Non-SARGable predicates (a function on a column) +- Key lookups, however many rows they run over +- Scalar UDFs running once per row +- Row goals gone wrong +- Eager index spools +- Nested loops joins over enormous outer inputs + +Those you find by reading the plan. diff --git a/skills/query-plan-analysis/scripts/extract.py b/skills/query-plan-analysis/scripts/extract.py new file mode 100644 index 0000000..7ce9523 --- /dev/null +++ b/skills/query-plan-analysis/scripts/extract.py @@ -0,0 +1,1108 @@ +#!/usr/bin/env python3 +""" +Flatten a SQL Server .sqlplan / showplan XML file into a compact text digest. + +Reads nothing but the standard library. Handles UTF-16 (the default encoding +SSMS writes) and UTF-8 plans transparently. + + python extract.py plan.sqlplan + python extract.py plan.sqlplan --top 15 + +The digest is ordered to match the triage procedure in SKILL.md: what kind of +plan this is, what SQL Server already told you, where time actually went, where +the estimates went wrong, and only then indexes. +""" + +import argparse +import re +import sys +import xml.etree.ElementTree as ET + +NS = "{http://schemas.microsoft.com/sqlserver/2004/07/showplan}" + +EXCHANGE_LOGICAL = {"Gather Streams", "Distribute Streams", "Repartition Streams"} + + +def tag(el): + """Local name of an element, namespace stripped.""" + return el.tag.split("}")[-1] if "}" in el.tag else el.tag + + +def num(el, name, default=0.0): + v = el.get(name) + if v is None: + return default + try: + return float(v) + except ValueError: + return default + + +class Node: + """One RelOp, with per-thread runtime stats folded to node level.""" + + def __init__(self, el, parent=None): + self.el = el + self.parent = parent + self.node_id = el.get("NodeId", "?") + self.physical = el.get("PhysicalOp", "") + self.logical = el.get("LogicalOp", "") + self.est_rows = num(el, "EstimateRows") + self.est_exec = num(el, "EstimateExecutions", 1.0) + self.est_rebinds = num(el, "EstimateRebinds") + self.est_rewinds = num(el, "EstimateRewinds") + self.subtree_cost = num(el, "EstimatedTotalSubtreeCost") + self.table_cardinality = num(el, "TableCardinality") + self.parallel = el.get("Parallel") in ("1", "true") + self.est_mode = el.get("EstimatedExecutionMode", "") + # Present only when a row goal is in effect (TOP, FAST N, EXISTS...). + self.row_goal = el.get("EstimateRowsWithoutRowGoal") is not None + + self.threads = [] + self.actual_mode = "" + self.has_actual = False + self.actual_rows = 0.0 + self.actual_rows_read = 0.0 + self.actual_executions = 0.0 + self.elapsed_ms = 0.0 + self.cpu_ms = 0.0 + self.logical_reads = 0.0 + + rti = el.find(NS + "RunTimeInformation") + if rti is not None: + for t in rti.findall(NS + "RunTimeCountersPerThread"): + self.threads.append( + { + "thread": int(num(t, "Thread")), + "rows": num(t, "ActualRows"), + "rows_read": num(t, "ActualRowsRead"), + "executions": num(t, "ActualExecutions"), + "elapsed": num(t, "ActualElapsedms"), + "cpu": num(t, "ActualCPUms"), + "reads": num(t, "ActualLogicalReads"), + } + ) + if not self.actual_mode: + self.actual_mode = t.get("ActualExecutionMode", "") + if self.threads: + self.has_actual = True + # Rows, CPU, reads SUM across threads. Elapsed takes the MAX. + self.actual_rows = sum(t["rows"] for t in self.threads) + self.actual_rows_read = sum(t["rows_read"] for t in self.threads) + self.actual_executions = sum(t["executions"] for t in self.threads) + self.cpu_ms = sum(t["cpu"] for t in self.threads) + self.logical_reads = sum(t["reads"] for t in self.threads) + self.elapsed_ms = max(t["elapsed"] for t in self.threads) + + self.children = [Node(c, self) for c in child_relops(el)] + self.warnings = parse_warnings(el) + + @property + def mode(self): + return self.actual_mode or self.est_mode + + @property + def is_exchange(self): + return self.physical == "Parallelism" or self.logical in EXCHANGE_LOGICAL + + @property + def label(self): + if self.logical and self.logical != self.physical: + return f"{self.physical} ({self.logical})" + return self.physical + + +def child_relops(el): + """ + Direct child RelOps. RelOps nest inside operator-specific elements + (, , ...), so descend until we hit the next RelOp + and stop there. + """ + found = [] + + def walk(e): + for c in e: + if tag(c) == "RelOp": + found.append(c) + else: + walk(c) + + walk(el) + return found + + +def local_elements(relop_el): + """Descendants of a RelOp that belong to it, not crossing into child RelOps.""" + out = [] + + def walk(e): + for c in e: + if tag(c) == "RelOp": + continue + out.append(c) + walk(c) + + walk(relop_el) + return out + + +def unbracket(s): + return (s or "").replace("[", "").replace("]", "") + + +def colref(c): + parts = [c.get("Table"), c.get("Column")] + return unbracket(".".join(p for p in parts if p)) + + +def node_objects(node): + """Tables/indexes this operator touches.""" + out = [] + for e in local_elements(node.el): + if tag(e) != "Object": + continue + name = unbracket(f"{e.get('Schema', '')}.{e.get('Table', '')}").strip(".") + idx = unbracket(e.get("Index", "")) + alias = unbracket(e.get("Alias", "")) + label = name + if idx: + label += f".{idx}" + if alias: + label += f" AS {alias}" + out.append(label) + return out + + +def node_predicate(node): + for e in local_elements(node.el): + if tag(e) == "Predicate": + so = e.find(NS + "ScalarOperator") + if so is not None and so.get("ScalarString"): + return so.get("ScalarString") + return None + + +def node_seek_predicates(node): + """Reconstruct 'column op expression' for each seek key.""" + out = [] + for e in local_elements(node.el): + if tag(e) != "SeekPredicateNew": + continue + for keys in e.findall(NS + "SeekKeys"): + for part in keys: + rc = part.find(NS + "RangeColumns") + rx = part.find(NS + "RangeExpressions") + cols = [colref(c) for c in rc] if rc is not None else [] + exprs = [so.get("ScalarString", "") for so in rx] if rx is not None else [] + scan_type = part.get("ScanType", "=") + if cols: + out.append(f"{tag(part)}: {', '.join(cols)} {scan_type} {', '.join(exprs)}".strip()) + return out + + +def node_outer_references(node): + for e in local_elements(node.el): + if tag(e) == "OuterReferences": + return [colref(c) for c in e.findall(NS + "ColumnReference")] + return [] + + +def node_output_list(node): + ol = node.el.find(NS + "OutputList") + if ol is None: + return [] + return [colref(c) for c in ol.findall(NS + "ColumnReference")] + + +def node_scan_order(node): + for e in local_elements(node.el): + if e.get("Ordered") is not None: + ordered = e.get("Ordered") in ("1", "true") + direction = e.get("ScanDirection", "") + return f"Ordered={'yes' if ordered else 'no'}" + (f" {direction}" if direction else "") + return None + + +def is_eager_index_spool(node): + """ + Index Spool specifically, NOT Table Spool. An eager *table* spool is ordinary + Halloween protection in an update plan and is not a defect; only the eager + *index* spool means "the optimizer built an index because you lack one," and + only it suppresses the missing-index request. + """ + return node.physical == "Index Spool" and "Eager" in node.logical + + +def own_cost(node): + """ + Estimated cost attributable to this operator alone. Subtree cost is cumulative, + so ranking by it always crowns the root. Still an ESTIMATE, in every plan. + """ + return max(0.0, node.subtree_cost - sum(c.subtree_cost for c in node.children)) + + +def fmt_duration(ms): + """Raw ms is hard to feel above about a minute.""" + if ms < 60_000: + return f"{ms:,.0f} ms" + secs = ms / 1000.0 + h, rem = divmod(int(secs), 3600) + m, s = divmod(rem, 60) + human = f"{h}h{m:02d}m{s:02d}s" if h else f"{m}m{s:02d}s" + return f"{ms:,.0f} ms ({human})" + + +# --------------------------------------------------------------------------- +# Self-time attribution. +# +# Row mode reports elapsed/CPU cumulatively: a node's number includes everything +# below it. Batch mode reports each operator standalone. Exchange operators +# accumulate downstream wait time, so their raw numbers mean little. +# --------------------------------------------------------------------------- + + +def sum_batch_subtree(node): + """Batch operators pipeline, so their elapsed times add rather than nest.""" + total = node.elapsed_ms + for c in node.children: + if c.physical == "Parallelism": + continue # zone boundary + if c.mode == "Batch" and c.has_actual: + total += sum_batch_subtree(c) + else: + total += effective_child_elapsed(c) + return total + + +def effective_child_elapsed(child): + """Elapsed time a child contributes to its parent's subtree total.""" + if child.physical == "Parallelism" and child.children: + return max(effective_child_elapsed(gc) for gc in child.children) + if child.mode == "Batch" and child.has_actual: + return sum_batch_subtree(child) + if child.elapsed_ms > 0: + return child.elapsed_ms + if not child.children: + return 0.0 + # Pass-through operator with no runtime stats (Compute Scalar and friends): + # look through it to the first descendants that have them. + return sum(effective_child_elapsed(gc) for gc in child.children) + + +def per_thread_self_elapsed(node): + """ + Parallel row mode: subtract within a thread, never across threads, then take + the slowest thread. Cross-thread subtraction produces nonsense. + """ + parent_by_thread = {t["thread"]: t["elapsed"] for t in node.threads} + child_by_thread = {} + for child in node.children: + target = child + if child.physical == "Parallelism" and child.children: + target = max(child.children, key=lambda c: c.elapsed_ms) + for t in target.threads: + child_by_thread[t["thread"]] = child_by_thread.get(t["thread"], 0.0) + t["elapsed"] + best = 0.0 + for thread_id, parent_ms in parent_by_thread.items(): + self_ms = max(0.0, parent_ms - child_by_thread.get(thread_id, 0.0)) + best = max(best, self_ms) + return best + + +def own_elapsed_ms(node): + if not node.has_actual or node.elapsed_ms <= 0: + return 0.0 + if node.mode == "Batch": + return node.elapsed_ms + if node.is_exchange: + # Thread 0 is the coordinator; its elapsed is wall clock for the whole + # branch, not this operator's work. + workers = [t["elapsed"] for t in node.threads if t["thread"] > 0] + if workers: + return max(0.0, max(workers) - sum(effective_child_elapsed(c) for c in node.children)) + return 0.0 + if len(node.threads) > 1: + return per_thread_self_elapsed(node) + return max(0.0, node.elapsed_ms - sum(effective_child_elapsed(c) for c in node.children)) + + +def effective_child_cpu(child): + if child.physical == "Parallelism" and child.children: + return max(effective_child_cpu(gc) for gc in child.children) + if child.cpu_ms > 0: + return child.cpu_ms + if not child.children: + return 0.0 + return sum(effective_child_cpu(gc) for gc in child.children) + + +def own_cpu_ms(node): + """ + Self CPU. Reported CPU is cumulative in row mode exactly like elapsed, so a + node's raw ActualCPUms includes every operator beneath it. Printing self + elapsed next to cumulative CPU produces gibberish. + """ + if not node.has_actual or node.cpu_ms <= 0: + return 0.0 + if node.mode == "Batch": + return node.cpu_ms # standalone, exactly like batch-mode elapsed + if len(node.threads) > 1: + parent_by_thread = {t["thread"]: t["cpu"] for t in node.threads} + child_by_thread = {} + for child in node.children: + target = child + if child.physical == "Parallelism" and child.children: + target = max(child.children, key=lambda c: c.cpu_ms) + for t in target.threads: + child_by_thread[t["thread"]] = child_by_thread.get(t["thread"], 0.0) + t["cpu"] + best = 0.0 + for thread_id, parent_cpu in parent_by_thread.items(): + best = max(best, max(0.0, parent_cpu - child_by_thread.get(thread_id, 0.0))) + return best + return max(0.0, node.cpu_ms - sum(effective_child_cpu(c) for c in node.children)) + + +# --------------------------------------------------------------------------- +# Warnings +# --------------------------------------------------------------------------- + +WARN_FLAGS = [ + ("NoJoinPredicate", "No join predicate"), + ("SpatialGuess", "Spatial index selectivity guessed"), + ("UnmatchedIndexes", "Unmatched indexes (parameterization)"), + ("FullUpdateForOnlineIndexBuild", "Full update for online index build"), +] + + +def parse_warnings(parent_el): + w = parent_el.find(NS + "Warnings") + if w is None: + return [] + out = [] + + for attr, text in WARN_FLAGS: + if w.get(attr) in ("1", "true"): + out.append(text) + + for c in w.findall(NS + "PlanAffectingConvert"): + out.append( + f"Implicit conversion [{c.get('ConvertIssue', '?')}]: {c.get('Expression', '')}" + ) + + spill = w.find(NS + "SpillToTempDb") + level = spill.get("SpillLevel", "?") if spill is not None else None + threads = spill.get("SpilledThreadCount", "?") if spill is not None else None + + for kind, el_name in (("Sort", "SortSpillDetails"), ("Hash", "HashSpillDetails")): + for s in w.findall(NS + el_name): + prefix = f"{kind} spill" + if level is not None: + prefix += f" level {level}, {threads} thread(s)" + out.append( + f"{prefix} - granted {num(s, 'GrantedMemoryKb'):,.0f} KB, " + f"used {num(s, 'UsedMemoryKb'):,.0f} KB, " + f"{num(s, 'WritesToTempDb'):,.0f} writes, " + f"{num(s, 'ReadsFromTempDb'):,.0f} reads" + ) + + if spill is not None and not w.findall(NS + "SortSpillDetails") and not w.findall(NS + "HashSpillDetails"): + out.append(f"Spill to tempdb, level {level}, {threads} thread(s)") + + for s in w.findall(NS + "ExchangeSpillDetails"): + out.append(f"Exchange spill - {num(s, 'WritesToTempDb'):,.0f} writes to tempdb") + + if w.find(NS + "SpillOccurred") is not None: + out.append("Spill occurred during execution") + + m = w.find(NS + "MemoryGrantWarning") + if m is not None: + out.append( + f"Memory grant [{m.get('GrantWarningKind', '?')}]: " + f"requested {num(m, 'RequestedMemory') / 1024:,.0f} MB, " + f"granted {num(m, 'GrantedMemory') / 1024:,.0f} MB, " + f"used {num(m, 'MaxUsedMemory') / 1024:,.0f} MB" + ) + + for el_name, text in ( + ("ColumnsWithNoStatistics", "No statistics on"), + ("ColumnsWithStaleStatistics", "Stale statistics on"), + ): + e = w.find(NS + el_name) + if e is not None: + cols = [c.get("Column", "") for c in e.findall(NS + "ColumnReference")] + out.append(f"{text}: {', '.join(filter(None, cols))}") + + for wait in w.findall(NS + "Wait"): + out.append(f"Wait {wait.get('WaitType')}: {wait.get('WaitTime')}ms") + + return out + + +# --------------------------------------------------------------------------- +# Cardinality estimator default-guess fingerprints +# --------------------------------------------------------------------------- + +CE_GUESSES = [ + (0.29, 0.31, "30% equality guess"), + (0.098, 0.102, "10% inequality guess"), + (0.088, 0.092, "9% LIKE/BETWEEN guess"), + (0.155, 0.175, "~16.4% compound predicate guess"), + (0.009, 0.011, "1% multi-inequality guess"), +] + + +def detect_ce_guess(est_rows, table_cardinality): + if table_cardinality <= 0: + return None + sel = est_rows / table_cardinality + for lo, hi, name in CE_GUESSES: + if lo <= sel <= hi: + return f"{name} ({sel * 100:.1f}% of {table_cardinality:,.0f})" + return None + + +# --------------------------------------------------------------------------- +# Digest +# --------------------------------------------------------------------------- + + +def flatten(node, acc=None): + acc = acc if acc is not None else [] + acc.append(node) + for c in node.children: + flatten(c, acc) + return acc + + +def fmt_rows(n): + return f"{n:,.0f}" if n >= 1 else f"{n:.4g}" + + +def render_tree(node, out, has_actual, depth=0, budget=None): + """ + Indented operator tree. This is the only view of plan SHAPE, and on an + estimated plan it is the only thing there is to reason about. + """ + if budget is not None: + if budget[0] <= 0: + return + budget[0] -= 1 + indent = " " + " " * depth + objs = node_objects(node) + obj = f" {objs[0]}" if objs else "" + if has_actual and node.has_actual: + execs = max(1.0, node.actual_executions) + detail = ( + f"est {fmt_rows(node.est_rows)}/exec vs " + f"actual {fmt_rows(node.actual_rows / execs)}/exec" + ) + else: + detail = f"est {fmt_rows(node.est_rows)} rows, cost {own_cost(node):,.2f}" + out.append(f"{indent}[{node.node_id}] {node.label} ({detail}){obj}") + for c in node.children: + render_tree(c, out, has_actual, depth + 1, budget) + + +def statement_text(stmt_el): + return " ".join((stmt_el.get("StatementText") or "").strip().split()) + + +def describe_statement(stmt_el, out, top_n, full_sql=False): + text = statement_text(stmt_el) + stmt_id = stmt_el.get("StatementId", "?") + if not full_sql and len(text) > 1500: + text = text[:1500] + f" ... [truncated; see --sql {stmt_id} for the full text]" + + out.append("=" * 78) + out.append(f"STATEMENT {stmt_id} [{stmt_el.get('StatementType', '?')}]") + out.append("=" * 78) + out.append(f" {text}") + out.append("") + + qp = stmt_el.find(NS + "QueryPlan") + if qp is None: + out.append(" (no query plan on this statement)") + out.append("") + return + + # --- 1. What kind of plan is this? ------------------------------------- + root_el = qp.find(NS + "RelOp") + if root_el is None: + out.append(" (no operators)") + out.append("") + return + root = Node(root_el) + nodes = flatten(root) + has_actual = any(n.has_actual for n in nodes) + + qts = qp.find(NS + "QueryTimeStats") + out.append("-- PLAN TYPE ------------------------------------------------") + out.append(f" Runtime stats present : {'YES (actual plan)' if has_actual else 'NO (ESTIMATED plan)'}") + out.append(f" CE model version : {stmt_el.get('CardinalityEstimationModelVersion', '?')}") + out.append(f" Optimization level : {stmt_el.get('StatementOptmLevel', '?')}") + early_abort = stmt_el.get("StatementOptmEarlyAbortReason") + if early_abort: + out.append(f" Early abort reason : {early_abort}") + out.append(f" Estimated subtree cost: {num(stmt_el, 'StatementSubTreeCost'):,.2f} (ALWAYS an estimate)") + dop = qp.get("DegreeOfParallelism") + if dop: + out.append(f" Degree of parallelism : {dop}") + npr = qp.get("NonParallelPlanReason") + if npr: + out.append(f" Non-parallel reason : {npr}") + if qts is not None: + total_elapsed = num(qts, "ElapsedTime") + out.append( + f" Query time : {fmt_duration(total_elapsed)} elapsed, " + f"{fmt_duration(num(qts, 'CpuTime'))} CPU" + ) + udf_cpu = num(qts, "UdfCpuTime") + udf_elapsed = num(qts, "UdfElapsedTime") + if udf_cpu > 0 or udf_elapsed > 0: + out.append( + f" UDF time : {fmt_duration(udf_elapsed)} elapsed, " + f"{fmt_duration(udf_cpu)} CPU" + ) + if total_elapsed > 0: + pct = udf_elapsed / total_elapsed * 100 + out.append( + f" -> scalar UDFs account for {pct:.2f}% of elapsed time. " + f"{'This is the query.' if pct > 50 else ''}".rstrip() + ) + # Per-invocation cost is the most persuasive number available, and the + # UDF runs once per row of whichever operator computes it. + udf_rows = max( + (n.actual_rows for n in nodes if n.physical == "Compute Scalar" and n.has_actual), + default=0, + ) + if udf_rows > 0 and udf_elapsed > 0: + out.append( + f" -> ~{udf_elapsed / udf_rows:,.1f} ms elapsed per invocation " + f"across {udf_rows:,.0f} rows" + ) + out.append("") + + # --- 2. What did SQL Server already tell you? -------------------------- + out.append("-- WARNINGS -------------------------------------------------") + plan_warnings = parse_warnings(qp) + any_warning = bool(plan_warnings) + for w in plan_warnings: + out.append(f" [plan] {w}") + for n in nodes: + for w in n.warnings: + any_warning = True + out.append(f" [node {n.node_id} {n.label}] {w}") + if not any_warning: + out.append(" (none)") + out.append("") + + # --- Memory grant ------------------------------------------------------ + mg = qp.find(NS + "MemoryGrantInfo") + if mg is not None and (mg.get("GrantedMemory") or mg.get("RequestedMemory")): + out.append("-- MEMORY GRANT (KB) ----------------------------------------") + for a in ( + "SerialRequiredMemory", + "SerialDesiredMemory", + "RequestedMemory", + "GrantedMemory", + "MaxUsedMemory", + "MaxQueryMemory", + "GrantWaitTime", + ): + if mg.get(a) is not None: + out.append(f" {a:22}: {num(mg, a):,.0f}") + granted, used = num(mg, "GrantedMemory"), num(mg, "MaxUsedMemory") + if granted > 0 and used > 0: + out.append(f" -> used {used / granted * 100:.1f}% of the grant") + out.append("") + + # --- Parameters -------------------------------------------------------- + params = qp.find(NS + "ParameterList") + if params is not None: + rows = [] + for c in params.findall(NS + "ColumnReference"): + compiled = c.get("ParameterCompiledValue") + runtime = c.get("ParameterRuntimeValue") + if compiled is None and runtime is None: + continue + flag = "" + if compiled is None: + flag = " (no compiled value: not sniffed - local variable, or RECOMPILE)" + elif runtime is not None and compiled != runtime: + flag = " <-- compiled for a different value than it ran with" + rows.append( + f" {c.get('Column', '?')}: compiled={compiled or '(none)'} " + f"runtime={runtime or '(none)'}{flag}" + ) + if rows: + out.append("-- PARAMETERS -----------------------------------------------") + out.extend(rows) + out.append("") + + # --- 3. Where did time actually go? ------------------------------------ + hot = [] + if has_actual: + out.append(f"-- TOP {top_n} OPERATORS BY SELF ELAPSED TIME (not cost) -----") + out.append(" 'self' = this operator's own work, children subtracted out.") + out.append(" Sorted by self elapsed. Self CPU is a SEPARATE clock: it sums across") + out.append(" threads while elapsed takes the slowest thread, so CPU exceeding") + out.append(" elapsed means parallelism, not a problem. Never quote one as the other.") + out.append("") + out.append(f" {'self elapsed':>14} {'self CPU':>12} {'rows out':>14} node operator") + timed = [(own_elapsed_ms(n), n) for n in nodes] + timed = [(ms, n) for ms, n in timed if ms > 0] + timed.sort(key=lambda x: -x[0]) + if not timed: + out.append(" (no operator elapsed times recorded)") + for ms, n in timed[:top_n]: + hot.append(n) + note = " [exchange: raw times unreliable]" if n.is_exchange else "" + out.append( + f" {ms:11,.0f} ms {own_cpu_ms(n):9,.0f} ms {fmt_rows(n.actual_rows):>14} " + f"{n.node_id:>4} {n.label}{note}" + ) + # Rows read vs rows emitted: the tell for a predicate applied as a + # filter instead of a seek. Only meaningful when SQL Server recorded it. + if n.actual_rows_read > 0 and n.actual_rows > 0: + ratio = n.actual_rows_read / n.actual_rows + if ratio >= 2: + if n.row_goal: + flag = " [row goal: stopped early, did not read the table]" + elif ratio >= 100: + flag = " <-- reads far more than it returns" + else: + flag = "" + out.append( + f" {'':>14} {'':>12} read {fmt_rows(n.actual_rows_read)} rows " + f"to emit {fmt_rows(n.actual_rows)} ({ratio:,.0f}x){flag}" + ) + out.append("") + + else: + # No runtime data, so shape and estimated cost are all there is. Rank by + # SELF cost, since subtree cost is cumulative and always crowns the root. + out.append(f"-- TOP {top_n} OPERATORS BY ESTIMATED SELF COST ---------------") + out.append(" ESTIMATES, not measurements. Nothing ran. Cost cannot tell you") + out.append(" what was slow - it can only tell you what the optimizer feared.") + out.append("") + costed = sorted(((own_cost(n), n) for n in nodes), key=lambda x: -x[0]) + for c, n in costed[:top_n]: + if c <= 0: + continue + objs = node_objects(n) + out.append( + f" {c:12,.2f} node {n.node_id:>3} {n.label} " + f"(est {fmt_rows(n.est_rows)} rows)" + + (f" {objs[0]}" if objs else "") + ) + out.append("") + + # --- Plan shape -------------------------------------------------------- + out.append("-- OPERATOR TREE -------------------------------------------") + out.append(" Children are indented. The FIRST child of a join is its outer input.") + budget = [80] + render_tree(root, out, has_actual, budget=budget) + if budget[0] <= 0: + out.append(f" ... tree truncated at 80 operators of {len(nodes)}") + out.append("") + + # Operators the digest names elsewhere; their predicates get printed below so + # nobody has to open the raw XML to follow up on a node we pointed them at. + cited = list(hot) + + # --- 4. Where are the estimates wrong? --------------------------------- + if has_actual: + out.append("-- CARDINALITY SKEW (per execution) -------------------------") + skewed = [] + for n in nodes: + if not n.has_actual or n.is_exchange: + continue + execs = max(1.0, n.actual_executions) + actual_per_exec = n.actual_rows / execs + est = n.est_rows # already per-execution in showplan + if est <= 0 and actual_per_exec <= 0: + continue + ratio = (actual_per_exec + 1) / (est + 1) + if ratio >= 10 or ratio <= 0.1: + skewed.append((abs(ratio if ratio >= 1 else 1 / ratio), n, est, actual_per_exec, execs, ratio)) + skewed.sort(key=lambda x: -x[0]) + if not skewed: + out.append(" (no operator off by 10x or more)") + for _, n, est, act, execs, ratio in skewed[:top_n]: + cited.append(n) + direction = "under" if ratio > 1 else "over" + out.append( + f" node {n.node_id:>3} {n.label}: est {fmt_rows(est)}/exec vs actual " + f"{fmt_rows(act)}/exec over {fmt_rows(execs)} exec(s) -> {direction}estimated " + f"{(ratio if ratio >= 1 else 1 / ratio):,.1f}x" + ) + guess = detect_ce_guess(n.est_rows, n.table_cardinality) + if guess: + out.append(f" estimate {guess} - the optimizer had no useful statistics") + out.append("") + + # --- 5. Thread skew ------------------------------------------------ + skewed_nodes = [] + for n in nodes: + if len(n.threads) <= 1: + continue + workers = [t["rows"] for t in n.threads if t["thread"] > 0] + if len(workers) < 2: + continue + hi, lo = max(workers), min(workers) + # Ignore trivial row counts; a 4x imbalance over 12 rows means nothing. + if hi < 100 or (lo > 0 and hi / lo < 4): + continue + idle = sum(1 for w in workers if w == 0) + skewed_nodes.append((hi, n, hi, lo, len(workers), idle)) + if skewed_nodes: + skewed_nodes.sort(key=lambda x: -x[0]) + out.append("-- PARALLEL THREAD SKEW ------------------------------------") + all_idle = [s for s in skewed_nodes if s[5] == s[4] - 1] + if len(all_idle) >= 3: + out.append( + f" {len(all_idle)} operators did ALL their work on a single thread " + f"(every other worker got 0 rows) - the parallel branch is effectively serial." + ) + for _, n, hi, lo, workers, idle in skewed_nodes[:top_n]: + cited.append(n) + out.append( + f" node {n.node_id:>3} {n.label}: busiest {hi:,.0f} rows, " + f"quietest {lo:,.0f} rows, {idle} of {workers} workers idle" + ) + if len(skewed_nodes) > top_n: + out.append(f" ... and {len(skewed_nodes) - top_n} more skewed operators") + out.append("") + + # --- Waits ------------------------------------------------------------- + ws = qp.find(NS + "WaitStats") + if ws is not None: + waits = ws.findall(NS + "Wait") + if waits: + out.append("-- TOP WAITS ------------------------------------------------") + for w in sorted(waits, key=lambda x: -num(x, "WaitTimeMs"))[:10]: + out.append( + f" {w.get('WaitType', '?'):32} {num(w, 'WaitTimeMs'):>9,.0f} ms " + f"({num(w, 'WaitCount'):,.0f} waits)" + ) + out.append("") + + # --- 6. Missing indexes (read as a hint, never as DDL) ----------------- + # --- Predicates for every operator the digest pointed at --------------- + # indexes.md says to design an index from the spool's SeekPredicate, and + # warnings.md says to diagnose a no-join-predicate from the join's INPUTS. + # Surface all of it so nobody has to open the raw XML. + interesting = list(cited) + for n in nodes: + if not (n.warnings or is_eager_index_spool(n)): + continue + if n not in interesting: + interesting.append(n) + # A warned join is diagnosed from its children: are both pinned to the + # same constant? Without them the reader sees half the discriminator. + for child in n.children: + if child not in interesting: + interesting.append(child) + seen_ids = set() + ordered = [] + for n in interesting: + if id(n) not in seen_ids: + seen_ids.add(id(n)) + ordered.append(n) + ordered.sort(key=lambda n: nodes.index(n)) + + detail_lines = [] + for n in ordered: + bits = [] + objs = node_objects(n) + if objs: + bits.append(f" object : {', '.join(dict.fromkeys(objs))}") + order = node_scan_order(n) + if order: + bits.append(f" scan : {order}") + for sp in node_seek_predicates(n): + bits.append(f" seek : {sp}") + pred = node_predicate(n) + if pred: + bits.append(f" predicate : {pred}") + outer = node_outer_references(n) + if outer: + bits.append( + f" outer refs: {', '.join(outer)} " + f"(correlated - a join here needs no predicate)" + ) + if n.row_goal: + bits.append( + " row goal : active (TOP/FAST/EXISTS) - a scan may stop early, so a " + "large rows-read count does not mean it read the whole table" + ) + # For a no-join-predicate warning: did the output actually multiply? + if any("No join predicate" in w for w in n.warnings) and n.has_actual: + inputs = [c.actual_rows for c in n.children if c.has_actual] + if len(inputs) == 2: + a, b = inputs + product = a * b + emitted = n.actual_rows + bits.append( + f" row check : inputs {fmt_rows(a)} and {fmt_rows(b)}; a cross join " + f"would emit {fmt_rows(product)}; this join emitted {fmt_rows(emitted)}" + ) + # Only a product meaningfully larger than either input can discriminate. + if product <= max(a, b) or min(a, b) <= 1: + bits.append( + " INCONCLUSIVE - an input has <=1 row (often a row " + "goal), so multiplication cannot be observed. Judge from the " + "predicates above instead." + ) + elif emitted < product / 2: + bits.append( + " Output did not multiply, so this is NOT an " + "accidental cross join." + ) + else: + bits.append( + " Output is close to the product: consistent with a " + "GENUINE cross join. Check the predicates above." + ) + if bits: + detail_lines.append(f" node {n.node_id} {n.label}") + detail_lines.extend(bits) + if detail_lines: + out.append("-- PREDICATES ON CITED OPERATORS ----------------------------") + out.extend(detail_lines) + out.append("") + + out.append("-- MISSING INDEX REQUESTS (hints, NOT ready-to-run DDL) -----") + mi_root = qp.find(NS + "MissingIndexes") + seen_requests = {} + if mi_root is not None: + for group in mi_root.findall(NS + "MissingIndexGroup"): + impact = num(group, "Impact") + for mi in group.findall(NS + "MissingIndex"): + table = unbracket(f"{mi.get('Schema', '')}.{mi.get('Table', '')}") + cols = [] + for cg in mi.findall(NS + "ColumnGroup"): + names = [c.get("Name", "") for c in cg.findall(NS + "Column")] + cols.append((cg.get("Usage", "?"), tuple(names))) + key = (table, tuple(cols)) + # Near-identical requests differing only in impact are noise. + seen_requests[key] = max(seen_requests.get(key, 0.0), impact) + if not seen_requests: + out.append(" (none)") + spools = [n for n in nodes if is_eager_index_spool(n)] + if spools: + ids = ", ".join(n.node_id for n in spools) + out.append( + f" NOTE: an eager INDEX spool is present (node {ids}). Index spools" + ) + out.append( + " suppress the missing-index request, so 'none' here does NOT mean no" + ) + out.append( + " index is needed. Build the index from the spool's seek predicate." + ) + else: + for (table, cols), impact in sorted(seen_requests.items(), key=lambda x: -x[1]): + out.append(f" {table} (claimed impact {impact:.1f}%, of an ESTIMATED cost)") + for usage, names in cols: + out.append(f" {usage:10}: {', '.join(names)}") + out.append(" NOTE: equality column order is arbitrary; existing indexes are ignored.") + out.append("") + + +def load_plan(path): + """ + Parse a showplan file, ignoring the encoding declared in the XML prolog. + + SSMS writes .sqlplan as UTF-16, but a plan that has been opened and re-saved + in an editor is often UTF-8 bytes still carrying encoding="utf-16". Trusting + the declaration makes those files unparseable, so detect from the bytes and + strip the prolog before handing a str to ElementTree. + """ + with open(path, "rb") as f: + raw = f.read() + + if raw.startswith(b"\xff\xfe"): + text = raw.decode("utf-16-le", errors="replace")[1:] + elif raw.startswith(b"\xfe\xff"): + text = raw.decode("utf-16-be", errors="replace")[1:] + elif raw.startswith(b"\xef\xbb\xbf"): + text = raw.decode("utf-8-sig", errors="replace") + elif len(raw) > 1 and raw[1] == 0: + text = raw.decode("utf-16-le", errors="replace") # UTF-16 LE, no BOM + elif len(raw) > 1 and raw[0] == 0: + text = raw.decode("utf-16-be", errors="replace") # UTF-16 BE, no BOM + else: + text = raw.decode("utf-8", errors="replace") + + text = re.sub(r"^\s*<\?xml.*?\?>", "", text, count=1, flags=re.DOTALL) + return ET.fromstring(text.strip()) + + +def describe_node(node, out): + """Everything known about one operator. The sanctioned alternative to + opening the raw XML.""" + out.append("=" * 78) + out.append(f"NODE {node.node_id}: {node.label}") + out.append("=" * 78) + out.append(f" execution mode : {node.mode or '(unspecified)'}") + if node.parallel: + out.append(" parallel : yes") + for label, value in ( + ("object", ", ".join(dict.fromkeys(node_objects(node)))), + ("scan order", node_scan_order(node)), + ("predicate", node_predicate(node)), + ("outer references", ", ".join(node_outer_references(node))), + ): + if value: + out.append(f" {label:17}: {value}") + for sp in node_seek_predicates(node): + out.append(f" seek predicate : {sp}") + outputs = node_output_list(node) + if outputs: + out.append(f" output columns : {', '.join(outputs)}") + out.append("") + out.append(" ESTIMATES") + out.append(f" rows per execution : {fmt_rows(node.est_rows)}") + if node.table_cardinality: + out.append(f" table cardinality : {fmt_rows(node.table_cardinality)}") + guess = detect_ce_guess(node.est_rows, node.table_cardinality) + if guess: + out.append(f" !! estimate {guess}") + out.append(f" subtree cost : {node.subtree_cost:,.4f} (an estimate, always)") + + if not node.has_actual: + out.append("") + out.append(" No runtime statistics on this operator.") + return + out.append("") + out.append(" ACTUALS") + out.append(f" executions : {fmt_rows(node.actual_executions)}") + out.append(f" rows emitted : {fmt_rows(node.actual_rows)} (total, all executions)") + if node.actual_executions > 0: + out.append(f" rows per execution : {fmt_rows(node.actual_rows / node.actual_executions)}") + if node.actual_rows_read: + out.append(f" rows READ : {fmt_rows(node.actual_rows_read)}") + if node.logical_reads: + out.append(f" logical reads : {fmt_rows(node.logical_reads)}") + out.append(f" self elapsed : {fmt_duration(own_elapsed_ms(node))}") + out.append(f" self CPU : {fmt_duration(own_cpu_ms(node))}") + out.append(f" cumulative elapsed : {fmt_duration(node.elapsed_ms)} (includes children in row mode)") + if len(node.threads) > 1: + out.append("") + out.append(" PER THREAD (thread 0 is the coordinator, not a worker)") + for t in sorted(node.threads, key=lambda x: x["thread"]): + out.append( + f" thread {t['thread']:>2}: {t['rows']:>14,.0f} rows " + f"{t['elapsed']:>10,.0f} ms elapsed {t['cpu']:>10,.0f} ms CPU" + ) + if node.warnings: + out.append("") + out.append(" WARNINGS") + for w in node.warnings: + out.append(f" {w}") + + +def main(): + ap = argparse.ArgumentParser(description="Flatten a .sqlplan into a text digest.") + ap.add_argument("plan", help="path to a .sqlplan / showplan XML file") + ap.add_argument("--top", type=int, default=10, help="rows to show in ranked sections") + ap.add_argument( + "--node", + metavar="ID", + help="print full detail for one operator (predicates, per-thread stats) " + "instead of the digest. NodeIds repeat across statements; every match is " + "printed, each tagged with its statement.", + ) + ap.add_argument( + "--sql", + nargs="?", + const="*", + metavar="STMT", + help="print the full, untruncated statement text (optionally for one " + "StatementId) and exit", + ) + args = ap.parse_args() + + try: + root = load_plan(args.plan) + except OSError as e: + print(f"error: could not read {args.plan}: {e}", file=sys.stderr) + return 1 + except ET.ParseError as e: + print( + f"error: {args.plan} is not a valid showplan XML document: {e}\n" + f" (a .sqlplan must have a root element)", + file=sys.stderr, + ) + return 1 + + if tag(root) != "ShowPlanXML": + print( + f"error: {args.plan} parsed as <{tag(root)}>, not . " + f"This is not a query plan.", + file=sys.stderr, + ) + return 1 + + out = [] + header = f"PLAN DIGEST: {args.plan}" + out.append(header) + out.append( + f"SQL Server build {root.get('Build', '?')}, showplan schema {root.get('Version', '?')}" + ) + out.append("") + + # Only statements that carry a plan. SET NOCOUNT ON and friends have none. + stmts = [el for el in root.iter() if tag(el) == "StmtSimple" and el.find(NS + "QueryPlan") is not None] + if not stmts: + print(f"error: {args.plan} contains no statements with a query plan", file=sys.stderr) + return 1 + if args.sql is not None: + lines = [] + for stmt in stmts: + sid = stmt.get("StatementId", "?") + if args.sql != "*" and sid != args.sql: + continue + lines.append(f"-- StatementId {sid} [{stmt.get('StatementType', '?')}]") + lines.append(statement_text(stmt)) + lines.append("") + if not lines: + print(f"error: no statement with StatementId {args.sql}", file=sys.stderr) + return 1 + print("\n".join(lines)) + return 0 + + if args.node is not None: + detail = [] + for stmt in stmts: + root_el = stmt.find(NS + "QueryPlan").find(NS + "RelOp") + if root_el is None: + continue + sid = stmt.get("StatementId", "?") + for n in flatten(Node(root_el)): + if n.node_id != args.node: + continue + # NodeIds are unique per statement, not per plan. Say which one. + detail.append(f"### StatementId {sid}: {statement_text(stmt)[:110]}") + describe_node(n, detail) + detail.append("") + if not detail: + print(f"error: no operator with NodeId {args.node} in {args.plan}", file=sys.stderr) + return 1 + print("\n".join(detail)) + return 0 + + if len(stmts) > 1: + out.append(f"{len(stmts)} statements carry a plan. Each is analyzed separately below.") + out.append("") + + for stmt in stmts: + describe_statement(stmt, out, args.top) + + print("\n".join(out)) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) From 6464e23141667fee2c86bef1d8b76965514c4ddb Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 9 Jul 2026 22:05:46 -0400 Subject: [PATCH 2/6] Remove inert skills/ copy of query-plan-analysis Claude Code never discovered this directory. Skills are only loaded from ~/.claude/skills/, .claude/skills/, or a plugin bundle -- a bare skills/ path at a repo root does nothing. The copy added in #385 was therefore nine files of documentation that no agent could load, and it had already drifted: its SKILL.md still resolves scripts/extract.py against a repo path, which is wrong once the skill is installed as a plugin and its directory is unguessable. The skill now ships from erikdarlingdata/claude-plugins as a Claude Code plugin: /plugin marketplace add erikdarlingdata/claude-plugins /plugin install query-plan-analysis@erikdarling It was moved out rather than promoted here because reaching this repo's default branch requires a dev -> main PR, which auto-fires release.yml and demands a version bump -- shipping a Velopack auto-update to every user for a change containing no application code. One coupling to keep in mind: the skill's references/timing.md is transcribed from src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs and NodeTimeAttribution.cs (row-mode cumulative vs batch-mode standalone times, exchange operators accumulating downstream waits, per-thread rather than cross-thread subtraction). If those semantics change, update the skill repo; nothing will catch the drift. Co-Authored-By: Claude Opus 4.8 (1M context) --- skills/query-plan-analysis/SKILL.md | 231 ---- .../references/cardinality.md | 127 -- .../references/extracting-without-python.md | 92 -- .../query-plan-analysis/references/indexes.md | 139 --- .../references/operators.md | 138 -- .../references/parallelism.md | 106 -- .../query-plan-analysis/references/timing.md | 149 --- .../references/warnings.md | 207 --- skills/query-plan-analysis/scripts/extract.py | 1108 ----------------- 9 files changed, 2297 deletions(-) delete mode 100644 skills/query-plan-analysis/SKILL.md delete mode 100644 skills/query-plan-analysis/references/cardinality.md delete mode 100644 skills/query-plan-analysis/references/extracting-without-python.md delete mode 100644 skills/query-plan-analysis/references/indexes.md delete mode 100644 skills/query-plan-analysis/references/operators.md delete mode 100644 skills/query-plan-analysis/references/parallelism.md delete mode 100644 skills/query-plan-analysis/references/timing.md delete mode 100644 skills/query-plan-analysis/references/warnings.md delete mode 100644 skills/query-plan-analysis/scripts/extract.py diff --git a/skills/query-plan-analysis/SKILL.md b/skills/query-plan-analysis/SKILL.md deleted file mode 100644 index 39e2ad4..0000000 --- a/skills/query-plan-analysis/SKILL.md +++ /dev/null @@ -1,231 +0,0 @@ ---- -name: query-plan-analysis -description: Analyze a SQL Server execution plan (.sqlplan / showplan XML) and explain what is actually slow and why. Use whenever a user shares a query plan, asks why a query is slow, asks what an operator means, asks whether an index would help, or asks you to interpret estimated vs actual rows, spills, memory grants, or parallelism. Prevents the standard wrong conclusions - reading cost percentages as measurements, calling scans bad, or pasting missing-index DDL verbatim. ---- - -# Reading a SQL Server execution plan - -A query plan tells you what SQL Server *decided* to do and, if it's an actual -plan, what happened when it did. Most bad plan analysis comes from confusing -those two things, or from reaching for the most visually obvious number rather -than the one that means something. - -Work through the triage order below. It exists to establish ground truth before -you form an opinion, because almost every wrong conclusion about a plan comes -from forming the opinion first. - -## Step 0: extract the plan before you read it - -**Never read a `.sqlplan` file directly into context, and never `grep` one.** - -- They are large. A trivial two-table join runs 120 KB; real plans run into - megabytes. Reading one wastes your context and you will still miss things, - because the interesting attributes are scattered across thousands of lines. -- They are usually **UTF-16**, so `grep`, `rg`, and friends silently match - nothing. Finding no `PlanAffectingConvert` in a UTF-16 plan tells you - nothing at all about whether the plan contains one. -- Some plans lie about their own encoding: SSMS writes UTF-16, but a plan - that has been opened and re-saved is often UTF-8 bytes still declaring - `encoding="utf-16"`. Strict XML parsers reject those. - -Run the bundled extractor, which handles all of this and prints a digest ordered -to match the steps below. Use the **absolute path** to `extract.py` — your -working directory is not necessarily the skill root: - -``` -python /absolute/path/to/skills/query-plan-analysis/scripts/extract.py /path/to/plan.sqlplan -``` - -Add `--top 20` to widen the ranked sections on a large plan. - -When you need more detail about one operator — its predicates, its seek keys, its -per-thread numbers — do **not** open the raw XML. Ask the extractor: - -``` -python .../scripts/extract.py /path/to/plan.sqlplan --node 16 -``` - -That prints everything known about node 16: object and index, predicate, seek -predicate, outer references, output columns, estimates, actuals, and per-thread -stats. The digest already surfaces predicates for the hot and warned operators, -so you will often not need it. - -If Python is genuinely unavailable, see `references/extracting-without-python.md`. - -## Step 1: is this an actual plan or an estimated plan? - -The digest says so explicitly. It decides what you are allowed to conclude. - -An **estimated plan** contains no runtime information whatsoever. Every row -count in it is a guess, nothing ran, and you cannot say anything about what -was slow. You can reason about plan *shape*, index usage, obvious type -mismatches, and estimates that are self-evidently wrong. You cannot say "this -operator took the longest" because no operator took any time. - -An **actual plan** has runtime counters. Now you can talk about time. - -If someone asks why a query is slow and hands you an estimated plan, say that -you need an actual plan and explain how to capture one, rather than guessing -from cost percentages. - -## Step 2: read the warnings SQL Server already gave you - -These are free. They require no inference, and they are the highest -signal-to-noise content in the entire plan. The digest lists them all, tagged -with the node they came from. - -Spills, implicit conversions, missing statistics, memory grant problems, and -no-join-predicate warnings all appear here. Read `references/warnings.md` for -what each one means and what to do about it. Several are more subtle than they -look, and at least one (no join predicate) is frequently a false alarm. - -## Step 3: find where the time went, never where the cost went - -This is the single most important rule in this document. - -**Cost is always an estimate. Always.** The "Query cost (relative to batch): -97%" figure that SSMS puts at the top of a plan is computed from the -optimizer's guesses. It is present in actual plans. It is *not* a measurement, -it does not get updated with what really happened, and the highest-cost -operator in a plan is routinely not the slow one. A plan can show an operator -at 0% cost that consumed the entire query's runtime. - -Never say "this operator is 97% of the cost, so it's the problem." Instead: - -- Use the digest's **TOP OPERATORS BY SELF TIME** section. -- Or read `QueryTimeStats` for total elapsed and CPU, and per-operator - `RunTimeCountersPerThread` for the breakdown. - -Self time is not the number printed on the operator. In row mode, an operator's -elapsed and CPU are **cumulative** — they include everything beneath it — so -sorting operators by their raw `ActualElapsedms` always crowns the root node. -Batch mode reports each operator standalone. Exchange operators report times -that are nearly meaningless. Getting this wrong produces confident, precise, -completely inverted answers, which is the worst failure mode available to you. - -Two things the operator list will not tell you, and both are commonly the answer: - -- **`UdfCpuTime`.** A scalar UDF's time is not attributed to any operator. If - `` reports a large `UdfCpuTime` or `UdfElapsedTime`, that is the - query, whatever the operators say. The digest prints it as a percentage of - elapsed and as a per-invocation cost. -- **Self times need not sum to the total.** In a parallel plan they legitimately - exceed it, because elapsed is the max across threads and branches overlap. Do - not second-guess a correct answer because the arithmetic looks off. - -Read `references/timing.md` before you say anything about where time went. It -is short and it is the part most likely to embarrass you. - -## Step 4: find where the estimates went wrong - -Compare estimated rows to actual rows — but **per execution**, not in total. - -On the inner side of a nested loop join, an operator runs once per outer row. -Showplan reports `EstimateRows` per execution and `ActualRows` as the sum -across all executions. Dividing is mandatory: - -``` -actual per execution = ActualRows / ActualExecutions -``` - -An operator showing "estimated 1 row, actual 4,000,000 rows" that ran 4,000,000 -times estimated perfectly. Announcing a four-million-times underestimate there -is the most common way to be loudly wrong about a plan. The digest does this -division for you. - -Large skew in either direction is worth investigating; see -`references/cardinality.md`, which also covers the optimizer's default guess -selectivities. When an estimate lands on exactly 30% of table cardinality, the -optimizer had no useful statistics and guessed — that is a fingerprint, and it -points at a different fix than a merely stale histogram. - -## Step 5: check for skew before you trust a parallel plan - -A parallel plan that ran DOP 8 but did all its work on one thread is a serial -plan that also paid for coordination. The digest reports per-thread row -distribution. Idle workers mean the rows did not distribute, and the usual -cause is upstream — an uneven partition key or a serial zone feeding the -exchange. See `references/parallelism.md`. - -Also: high CPU relative to elapsed is normal and expected in a parallel plan. -It is not evidence of a problem by itself. Eight threads working for one second -burn eight CPU-seconds. - -## Step 6: parameters, then memory grants - -The digest prints `ParameterCompiledValue` against `ParameterRuntimeValue`. If -they differ, the plan was built for one value and executed with another. That -is parameter sniffing, sitting in plain sight, and it explains a large share of -"the same query is sometimes fast and sometimes slow" reports. - -For memory grants, compare `GrantedMemory` to `MaxUsedMemory`. A query granted -9 GB that used 200 MB is stealing memory from everything else on the server and -may be waiting to get it (`GrantWaitTime`). A query that spilled despite a large -grant usually has skew, not a grant sizing problem. - -## Step 7: only now, missing indexes - -The `` element is a hint about which predicates went unserved. -It is **not** DDL to hand to a user. - -- The equality columns come out in arbitrary order. Key order is the single - most important decision in index design and SQL Server does not make it. -- It ignores every index that already exists, so it will happily ask for a - near-duplicate of one you have. -- It ignores the rest of the workload. -- Its `Impact` percentage is relative to the estimated cost of a plan you have - already established is estimated. -- `INCLUDE` lists are frequently enormous, because it includes every column the - query touches. - -Read the request as "a seek on these columns would have helped." Then design the -index yourself, considering existing indexes and column selectivity. See -`references/indexes.md`. - -## Things that are not evidence - -Say none of these: - -- **"There's a scan, that's bad."** A scan of a small table is optimal. A seek - executed four million times is not. Scans of a 200-row lookup table are fine - forever. Judge by rows touched and time spent, not operator name. -- **"The thick arrow is the problem."** Arrow thickness is row count, and in an - estimated plan it is *guessed* row count. Rows are not time. -- **"Cost is 97% here."** See step 3. -- **"Key lookups are always bad."** A key lookup on 12 rows is nothing. On 12 - million it is the whole query. The count is what matters. -- **"The optimizer chose a bad plan."** Usually the optimizer chose the correct - plan for the row counts it was given, and the row counts were wrong. Fix the - estimate and the plan often fixes itself. Diagnose the estimate first. -- **"This query needs `OPTION (RECOMPILE)` / `MAXDOP 1` / a hint."** Hints - suppress symptoms. Reach for them after you understand the cause, and say - what the cause was. - -## Writing the answer - -Lead with what is actually slow and why, in one sentence, before any detail. -Quote the numbers you used and name their source, so the reader can check you: -name the operator, its node id, its self elapsed time, and the query's total -elapsed time, in that form. Precision about *which* number you are citing — self -time versus cumulative, per-execution versus total, estimated versus actual — is -the difference between a useful answer and a plausible one. - -Then say what you ruled out, and why. "The memory grant used 17% of what it -asked for, so this is not a grant problem" is worth a line, because it stops the -reader from chasing it next. - -If the plan does not support a conclusion, say so. "This is an estimated plan, -so I can tell you the shape looks wrong but not what was slow" is a good -answer. Inventing a bottleneck from cost percentages is not. - -## Reference files - -| File | Read it when | -|---|---| -| `references/timing.md` | Before making any claim about where time went | -| `references/cardinality.md` | Estimates disagree with actuals | -| `references/warnings.md` | The plan carries any warning | -| `references/parallelism.md` | The plan is parallel | -| `references/indexes.md` | You are about to recommend an index | -| `references/operators.md` | You need to explain a specific operator | -| `references/extracting-without-python.md` | Python is unavailable | diff --git a/skills/query-plan-analysis/references/cardinality.md b/skills/query-plan-analysis/references/cardinality.md deleted file mode 100644 index 3abff6d..0000000 --- a/skills/query-plan-analysis/references/cardinality.md +++ /dev/null @@ -1,127 +0,0 @@ -# Estimates versus actuals - -Most bad plans are good plans built on bad row counts. Diagnose the estimate -before you blame the optimizer. - -## Always normalize per execution - -Showplan reports these on different bases: - -- `EstimateRows` — rows the optimizer expects **per execution** of the operator. -- `ActualRows` — rows actually emitted, **summed over every execution and every - thread**. -- `ActualExecutions` — how many times the operator ran, summed over threads. - -So the only valid comparison is: - -``` -actual per execution = ActualRows / ActualExecutions -skew = (actual per execution) / EstimateRows -``` - -An index seek on the inner side of a nested loop that shows `EstimateRows="1"` -and `ActualRows="4000000"` over `ActualExecutions="4000000"` estimated -**perfectly**. Reporting a 4-million-times underestimate there is the single most -common way to be loudly wrong about a plan, and it is instantly recognizable to -anyone who knows plans. - -`EstimateExecutions` (or `EstimateRebinds` + `EstimateRewinds`) tells you what -the optimizer expected the execution count to be. When the row estimate per -execution is right but the *execution count* is badly wrong, the problem is on -the outer side of the join, not at the operator you are looking at. - -## The optimizer's default guesses - -When statistics are missing or unusable, the optimizer applies fixed selectivity -guesses. Estimates that land on these fractions of `TableCardinality` are a -fingerprint: they mean the optimizer had nothing to work with, and the fix is to -give it information, not to hint the query. - -| Guess | Selectivity | Typical trigger | -|---|---|---| -| Equality | 30% | `col = @var` with no usable statistic; table variable | -| Inequality | 10% | `col > @var`, `col < @var` | -| `LIKE` / `BETWEEN` | 9% | `col LIKE @pattern` | -| Compound predicate | ~16.4% | two filters combined under the new CE | -| Multiple inequalities | 1% | `col > @a AND col < @b` | - -The new cardinality estimator (`CardinalityEstimationModelVersion` 120 and -above) also uses *exponential backoff* when combining predicates, rather than the -legacy CE's independence assumption. Two predicates each 10% selective estimate -at roughly 3.2% under the old model and roughly 5.6% under the new one. Neither -is right when the columns are correlated. - -`scripts/extract.py` flags estimates that match these fingerprints. - -## Common causes, in rough order of frequency - -**Table variables.** Before SQL Server 2019 (or under compatibility level below -150), a table variable always estimates 1 row regardless of contents, because it -has no statistics. Deferred compilation in 2019+ fixes the *initial* estimate but -not subsequent modifications. A table variable feeding a nested loop join is the -classic cause of a plan that works on a laptop and dies in production. - -**Implicit conversion on a predicate.** If the column's type must be converted to -match the literal or parameter, the optimizer cannot use the histogram and falls -back to a guess. See `warnings.md`. - -**A function wrapping the column.** `WHERE YEAR(OrderDate) = 2024` is not -SARGable. The optimizer has no statistic on `YEAR(OrderDate)` and guesses. Rewrite -as a range: `WHERE OrderDate >= '2024-01-01' AND OrderDate < '2025-01-01'`. - -**Stale statistics.** The histogram describes data that no longer exists. Check -whether the estimate matches what the table *used to* look like. Auto-update -triggers at roughly `SQRT(1000 * rowcount)` modifications for large tables, which -on a billion-row table is a million rows — a table can drift very far while -statistics still count as fresh. - -**Correlated predicates.** `WHERE City = 'Chicago' AND State = 'IL'` — the -optimizer multiplies the two selectivities as if independent, and badly -underestimates. Multi-column statistics or a filtered index can help. - -**Parameter sniffing.** The estimate is correct for the value the plan was -compiled with and wrong for the value it ran with. Check -`ParameterCompiledValue` against `ParameterRuntimeValue`. This is not a bad -estimate in the usual sense — the histogram was fine — so the fix is different. - -**Local variables and `OPTIMIZE FOR UNKNOWN`.** A local variable's value is not -known at compile time, so the optimizer uses the density vector (average rows per -distinct value) rather than the histogram. This produces a stable, mediocre -estimate rather than a good one. - -**Multi-statement table-valued functions.** Fixed estimate of 1 row before 2014, -100 rows from 2014 on, regardless of what the function returns. Interleaved -execution in 2017+ fixes this for the first execution. Inline TVFs do not have the -problem at all. - -## Which direction matters - -**Underestimate** — the optimizer thinks fewer rows than there are. It picks -nested loops, key lookups, serial plans, and too-small memory grants. The result -is spills, and joins that repeat millions of times. Underestimates usually -present as a query that is much slower than it should be. - -**Overestimate** — the optimizer thinks more rows than there are. It picks hash -joins, sorts, parallelism, and enormous memory grants. The result is memory -pressure, `RESOURCE_SEMAPHORE` waits, and concurrency collapse across the -instance. Overestimates often present as one query that is fine alone and a -server that falls over under load. - -An overestimate can also cause an eager index spool: the optimizer decides that -building a temporary index at runtime will pay for itself over the many rows it -expects, then builds it for a handful of rows. If you see one, look for a large -overestimate on the operator feeding it. - -## What to do about it - -In order of preference: - -1. Fix the estimate. Update statistics, remove the implicit conversion, make the - predicate SARGable, replace the table variable with a temp table. -2. Give the optimizer information it does not have. Multi-column statistics, - filtered statistics, a filtered index. -3. Restructure the query so the bad estimate does not matter. Materializing an - intermediate result into a `#temp` table gives the optimizer real statistics - at the cost of a write. -4. Only then, hints. And when you use one, say what estimate it is compensating - for. diff --git a/skills/query-plan-analysis/references/extracting-without-python.md b/skills/query-plan-analysis/references/extracting-without-python.md deleted file mode 100644 index cd89656..0000000 --- a/skills/query-plan-analysis/references/extracting-without-python.md +++ /dev/null @@ -1,92 +0,0 @@ -# Getting at a plan without the extractor - -Use `scripts/extract.py` when you can. This file is the fallback. - -## The encoding problem comes first - -`.sqlplan` files written by SSMS are **UTF-16**. Text tools see a null byte -between every character: - -- `grep PlanAffectingConvert plan.sqlplan` matches nothing, even when the plan is - full of implicit conversions. It reports no match rather than an error, so a - negative result is worthless. -- `head`, `cat`, and `wc -l` produce garbage. - -Convert first: - -``` -iconv -f UTF-16 -t UTF-8 plan.sqlplan > plan.utf8.xml -``` - -Some plans are UTF-8 bytes that still declare `encoding="utf-16"` in the XML -prolog, because someone opened and re-saved them. `iconv` will fail on those and -strict XML parsers will reject them. Check the first bytes: if the file starts -with the literal characters `` records which predicates the optimizer could not serve with an -existing index. That is genuinely useful information. The `CREATE INDEX` -statement people paste out of it is not a recommendation, and shipping it -verbatim is the fastest way to look like you do not know what you are doing. - -What is wrong with it: - -- **Equality column order is arbitrary.** Showplan emits them in column-id order, - not selectivity order. Key column order is the most consequential decision in - index design. SQL Server does not make it for you. -- **Existing indexes are ignored.** The optimizer asks for what would help *this* - query, with no regard for the eleven indexes already on the table. Following the - requests one at a time produces near-duplicate indexes that all have to be - maintained on every write. -- **The `INCLUDE` list is every other column the query touches.** On a wide - `SELECT` this can be most of the table, producing an index nearly as large as - the table itself. -- **`Impact` is a percentage of an estimated cost.** It is an estimate of the - improvement to an estimate. It is not a promise, and a 99% impact figure on a - query with bad cardinality means nothing. -- **It never suggests a clustered index, a filtered index, or a columnstore**, - and it never suggests *dropping* anything. - -## Reading it properly - -Take the column groups as evidence about the query's access pattern: - -- `EQUALITY` columns — predicates of the form `col = something`. These belong at - the front of the key. -- `INEQUALITY` columns — `>`, `<`, `BETWEEN`, `LIKE 'x%'`. These belong after all - the equality columns. Everything after the first inequality column in a key can - only be used as a residual filter, not for seeking, so there is rarely a reason - to have more than one. -- `INCLUDE` columns — columns the query needs to return but does not filter or - join on. Adding them avoids a key lookup at the cost of index size. - -Order the equality columns by selectivity, most selective first, unless you know -the workload wants otherwise. Then check what indexes already exist: an existing -index whose key is a prefix of what you want should usually be *modified* rather -than joined by a new one. - -## Key lookups - -A `Key Lookup` (or `RID Lookup` on a heap) means a nonclustered index found the -rows but did not contain every column the query needed, so SQL Server went back -to the clustered index once per row. - -Whether it matters is entirely about the row count. Look at `ActualExecutions` on -the lookup: that is how many times it ran. Twelve is free. Twelve million is the -whole query. - -Two fixes: - -- Add the missing columns to the nonclustered index's `INCLUDE` list. Cheap, - effective, and grows the index. -- Return fewer columns. Frequently the query is selecting columns nobody uses. - -A lookup with a **residual predicate** — a `Predicate` element on the lookup -operator itself — is worse than it looks. It means the filter could not be applied -until after the lookup, so SQL Server paid for the lookup on rows it then -discarded. Compare `ActualRows` on the lookup against `ActualRows` on its parent. -The gap is wasted work, and moving that predicate's column into the index key -eliminates it. - -## Scans are not the enemy - -A `Clustered Index Scan` is a table scan. That is not automatically a defect. - -- Scanning a 200-row table is optimal. An index seek would be slower. -- Scanning is correct when the query genuinely needs most of the table. -- The optimizer chooses a scan over a seek when it estimates the seek plus - lookups would cost more. Above roughly 1% selectivity for a wide row, that is - usually correct arithmetic. - -What makes a scan a problem is a *selective predicate* that the scan had to apply -itself. Check the operator's `ActualRowsRead` against `ActualRows`. Reading 17 -million rows to emit 200 means the predicate ran as a filter instead of a seek. -*That* is worth fixing — and the fix is an index, or making the predicate -SARGable, not "avoiding the scan." - -`ActualRowsRead` is only present when a predicate is pushed into the scan. Its -absence, with `ActualRows` equal to `TableCardinality`, means the query really did -want the whole table. - -## Non-SARGable predicates - -SQL Server cannot seek on an expression it does not have an index for. These force -a scan and, worse, a cardinality guess: - -| Non-SARGable | Rewrite | -|---|---| -| `WHERE YEAR(d) = 2024` | `WHERE d >= '20240101' AND d < '20250101'` | -| `WHERE ISNULL(c, 0) = 5` | `WHERE c = 5` (handle NULL separately if needed) | -| `WHERE c LIKE '%foo'` | Full-text, or store a reversed computed column | -| `WHERE CAST(c AS VARCHAR) = '5'` | Fix the type on the other side | -| `WHERE c + 0 = 5` | `WHERE c = 5` | -| `WHERE ABS(c) = 5` | `WHERE c IN (5, -5)` | - -A leading wildcard `LIKE '%foo'` cannot seek under any index and never will. -`LIKE 'foo%'` seeks fine. - -An `OR` across different columns often defeats index usage entirely; the optimizer -may expand it into a union of seeks, or may give up and scan. Check whether it -did. `UNION ALL` of two well-indexed queries is frequently faster and always more -predictable. - -## Eager index spool - -An `Index Spool` with logical operation `Eager Spool` means the optimizer decided -to build a temporary index in tempdb, at runtime, because no suitable permanent -index existed. It builds it from scratch on every execution. - -This is the optimizer telling you, in the loudest voice it has, exactly which -index to create. Take the spool's `SeekPredicate` for the key columns and its -`OutputList` for the includes. The digest prints both under `PREDICATES ON HOT / -WARNED OPERATORS`; `extract.py --node N` prints the full detail. - -An eager spool is *eager*: it fully materializes before returning any rows. -Combined with a large overestimate on its input, it can dominate a query's -runtime entirely — building a temporary index over millions of rows to serve a -handful of seeks. - -**An eager index spool usually suppresses the missing-index request.** The plan -will contain no `` element, and the request will not appear in -`sys.dm_db_missing_index_details` either. So "SQL Server didn't suggest an index" -is not evidence that no index is needed — when a spool is present, it is evidence -of the opposite. Nothing will prompt you. You have to recognize the spool as the -request. - -In a parallel plan the spool build runs on a single thread while the others block -on it, which surfaces as `EXECSYNC` near the top of ``. That wait and -the spool are one finding, not two. - -Eager spools also appear legitimately in update plans, where they protect against -the Halloween Problem. Those are not defects. diff --git a/skills/query-plan-analysis/references/operators.md b/skills/query-plan-analysis/references/operators.md deleted file mode 100644 index 51d2d7a..0000000 --- a/skills/query-plan-analysis/references/operators.md +++ /dev/null @@ -1,138 +0,0 @@ -# Operators worth understanding - -Not a catalogue. These are the ones whose presence changes what you should -conclude. - -## Reading order - -Plans display right to left, and data flows that way: leaves produce rows, the -root consumes them. But *logical* execution order is a depth-first walk from the -root — the root asks its first child for a row, which asks its first child, and so -on. Nested loops joins make this matter: the outer input (first child) drives, and -the inner input (second child) runs once per outer row. - -In the XML, child `RelOp` elements appear nested inside the operator-specific -element (``, ``, ``). **The first child `RelOp` is the -outer input.** Confusing outer and inner inputs inverts your entire analysis of a -nested loop. - -## Joins - -**Nested Loops** — for each row from the outer input, probe the inner. Optimal -when the outer is small and the inner has a supporting index. Catastrophic when -the outer input is large, because the inner runs once per row. Check -`ActualExecutions` on the inner side. The presence of `` means -the join correlates by passing values in, which is why a `NoJoinPredicate` -warning on a nested loop is often noise. - -**Hash Match** — builds a hash table from the build input (first child), probes -with the second. Needs a memory grant. Blocking on the build side: no rows come -out until the build input is fully consumed. Spills when the grant is too small, -which is nearly always an underestimate on the build input. Fine for large, -unsorted, unindexed joins. Its presence is not a defect. - -**Merge Join** — both inputs must be sorted on the join key. Very cheap when they -already are, because indexes provide the order. Expensive when the optimizer has -to add a `Sort` to make it work. A merge join with a sort beneath it is often a -worse choice than the hash join the optimizer rejected. A `many-to-many` merge -join uses a worktable in tempdb and is materially slower. - -**Adaptive Join** (2017+, batch mode) — defers the hash-versus-loop decision until -runtime based on actual row count. `ActualJoinType` tells you what it picked. - -## Spools - -Spools materialize rows into a hidden temporary object in tempdb. - -**Eager Spool** — reads its entire input before returning a single row. See -`indexes.md`. An eager *index* spool is the optimizer asking for an index. - -**Lazy Spool** — reads on demand, returning rows as it goes. Cheaper. - -**Table Spool / Row Count Spool** — caches a result for reuse. - -An eager spool also appears legitimately in update plans, protecting against the -Halloween Problem. Do not report those as defects. - -## Filter - -A `Filter` operator applies a predicate that could not be pushed down into a scan -or seek. Its position matters: everything below it did work on rows the filter -then discarded. Compare its `ActualRows` to its child's — the difference is -wasted. - -`Filter` with a `StartupExpression` is a startup filter guarding a branch that may -not execute at all. That is an optimization, not a problem. - -## Compute Scalar - -Usually free, and usually carries **no runtime statistics at all**. Do not -conclude that a Compute Scalar took zero time from its absent numbers; the work is -generally deferred and attributed to the operator that consumes its output. This -absence breaks naive self-time arithmetic (see `timing.md`). - -A Compute Scalar invoking a scalar UDF is a very different animal. See below. - -## Scalar UDFs - -Before SQL Server 2019, a scalar UDF in a query: - -- Runs once per row, as an interpreted call -- Is costed by the optimizer at essentially zero -- Forces the **entire plan serial** (`NonParallelPlanReason` = - `TSQLUserDefinedFunctionsNotParallelizable`) -- Does not appear as its own operator, so its time hides inside whatever calls it - -This combination — invisible in the plan, free according to cost, catastrophic in -reality — makes it the single most common cause of a query whose plan looks fine -and runs for minutes. Check ``. If it is -present and large, that is your answer regardless of what the operators say. - -SQL Server 2019 introduced Froid, which inlines many scalar UDFs into the calling -query. When inlining happens, the UDF's work becomes visible as real operators and -the plan may go parallel. Inlining is disabled by various constructs -(`WHILE` loops, time-dependent functions, `@@ROWCOUNT`, and others), so a 2019+ -plan can still contain a non-inlined UDF. - -## Sort - -Blocking — nothing comes out until everything has gone in. Needs a memory grant. -Spills to tempdb when the grant is short. - -A sort you did not ask for is the optimizer meeting a requirement of something -else: a merge join, a stream aggregate, a `DISTINCT`, an order-preserving -exchange. Removing the requirement removes the sort. An index that provides the -order removes it entirely. - -`Sort (Top N Sort)` with a small N is cheap and does not need a full sort. - -## Aggregates - -**Stream Aggregate** — requires sorted input, aggregates as it goes, no memory -grant. Cheap when an index provides the order. - -**Hash Match (Aggregate)** — no ordering requirement, needs a grant, can spill. - -**Hash Match (Partial Aggregate)** — a pre-aggregation below an exchange in a -parallel plan, reducing rows before they cross threads. Its presence is good. - -## Key Lookup / RID Lookup - -See `indexes.md`. Judge by `ActualExecutions`, never by presence. - -## Table Valued Function - -A multi-statement TVF appears as a single operator with a fixed row estimate (1 -before 2014, 100 after) regardless of what it returns. An inline TVF does not -appear at all — it is expanded into the calling query, which is why inline TVFs -are almost always preferable. - -## Constant Scan - -Produces a fixed set of rows, often zero or one. Common under `Nested Loops` for -`OR` expansion, and above an `Index Seek` in a `MERGE`. Rarely interesting. - -## Parallelism - -See `parallelism.md`. Its timings are unreliable and it is almost never the actual -problem, even when it looks expensive. diff --git a/skills/query-plan-analysis/references/parallelism.md b/skills/query-plan-analysis/references/parallelism.md deleted file mode 100644 index 78842fe..0000000 --- a/skills/query-plan-analysis/references/parallelism.md +++ /dev/null @@ -1,106 +0,0 @@ -# Parallel plans - -## CPU exceeding elapsed is normal - -Eight threads working for one second burn eight CPU-seconds. `CpuTime` several -times `ElapsedTime` in `` is what parallelism *is*. It is not -evidence of a problem, and saying "CPU time is 5x elapsed time, something is -wrong" is a tell that you do not read plans. - -What is worth noting is CPU *close to* elapsed in a plan running at DOP 8: the -plan went parallel and got no benefit, so it paid coordination costs for nothing. - -## Thread skew - -`` has one entry per thread. **Thread 0 is the -coordinator**, not a worker. It generally shows zero rows for most operators, and -for exchange operators its elapsed time is the wall clock of the whole branch. -Exclude it when assessing distribution. - -Compare `ActualRows` across worker threads. Healthy is roughly even. Unhealthy: - -- **One worker has everything, the rest have zero.** The branch is effectively - serial and paid for parallelism anyway. Usually an exchange upstream failed to - distribute, or the branch sits on the inner side of a nested loop and runs on - one thread per outer row by design. -- **Distribution follows a skewed key.** `Repartition Streams` hashing on a - column where one value dominates. Every row with that value lands on one - thread. Repartition on a more selective column, or restructure. -- **Some workers idle entirely.** Fewer distinct hash values than threads. - -Skew is the usual reason a parallel plan is slower than its serial version. It is -also the usual reason for a hash spill on one thread while the grant looks -generous: memory is divided evenly across threads, so the thread with all the -rows spills while the others sit on unused memory. - -## Exchange operators - -`Parallelism` is the physical operator. The logical operator says what it does: - -- **Distribute Streams** — serial input, parallel output. One thread to many. -- **Repartition Streams** — parallel in, parallel out, rows reshuffled across - threads. The `PartitionColumns` element says on what. -- **Gather Streams** — parallel input, serial output. Many threads to one. - -Their timings are unreliable. An exchange accumulates the time it spends waiting -for whatever is downstream, so a spilling sort above a Gather Streams inflates the -gather's numbers. Never point at an exchange and say it is slow. See -`timing.md`. - -An **order-preserving exchange** (`Gather Streams` with an ``) is a merge -of sorted streams and is materially more expensive than an unordered one. It also -serializes on the slowest thread. Usually appears under a merge join or above a -sort feeding an `ORDER BY`. It is a common cause of exchange spills and, in older -builds, intra-query parallel deadlocks. - -## Why a plan did not go parallel - -`` tells you directly. Common values: - -- `MaxDOPSetToOne` -- `EstimatedDOPIsOne` — the optimizer costed a parallel plan and did not want it -- `NoParallelPlansInDesktopOrExpressEdition` -- `NoParallelWithRemoteQuery` -- `TSQLUserDefinedFunctionsNotParallelizable` — a scalar UDF anywhere in the - query forced the entire plan serial. -- `CouldNotGenerateValidParallelPlan` — **also very commonly a scalar UDF.** - -Do not treat `TSQLUserDefinedFunctionsNotParallelizable` as the only UDF tell. -Real plans containing a serial-forcing scalar UDF frequently report -`CouldNotGenerateValidParallelPlan` instead. Whenever a large query is stubbornly -serial, check `` regardless of which reason -string the plan gives. Before SQL Server 2019 this is a very common and very -expensive silent penalty. - -A serial plan whose dominant wait is `CXPACKET` looks self-contradictory and is -not. The outer statement is serial; the UDF's internal queries went parallel, once -per row, and their waits aggregate into the plan. Large `UdfCpuTime` alongside -serial DOP and heavy `CXPACKET` is a scalar UDF, not a puzzle. - -## DOP and the cost threshold - -`` is the DOP actually used. A plan goes -parallel only if its *estimated* serial cost exceeds `cost threshold for -parallelism` (default 5, which was calibrated in 1997 and is far too low). So the -decision to parallelize rests entirely on estimates — an overestimate can produce -a parallel plan for a query that returns four rows. - -Also: `DegreeOfParallelism` is what the optimizer requested. The query may have -run with fewer threads if none were available. Count distinct worker threads in -`RunTimeCountersPerThread` to see what it actually got. - -## Serial zones inside a parallel plan - -A parallel plan is not parallel everywhere. Between exchange operators the plan is -divided into branches, and each branch has its own DOP. Some operators force a -serial zone: - -- Scalar UDFs (pre-2019) -- `TOP` in certain positions -- Backward scans -- Global aggregates above a `Gather Streams` -- Sequence functions like `ROW_NUMBER()` over an unpartitioned window, which - must serialize - -If the expensive operator sits in a serial zone, DOP is irrelevant to it and -raising MAXDOP will not help. diff --git a/skills/query-plan-analysis/references/timing.md b/skills/query-plan-analysis/references/timing.md deleted file mode 100644 index b9cc5c2..0000000 --- a/skills/query-plan-analysis/references/timing.md +++ /dev/null @@ -1,149 +0,0 @@ -# Where the time actually went - -The numbers on a plan operator do not mean what they look like they mean. This -file is the one that keeps you from being confidently, precisely wrong. - -## Cost is not time - -`EstimatedTotalSubtreeCost`, `StatementSubTreeCost`, and SSMS's "Query cost -(relative to batch): 97%" are all derived from the optimizer's row estimates and -a fixed hardware model from the late 1990s. They are **estimates in every plan, -including actual plans**. Nothing recomputes them after execution. - -Consequences: - -- The highest-cost operator is frequently not the slow one. -- An operator can show 0% cost and consume the entire runtime. A scalar UDF is - the classic case: pre-2019 the optimizer costs it at essentially nothing while - it runs once per row. -- Two plans' cost numbers are only comparable if their estimates were equally - good, which is exactly what you are trying to determine. - -Use cost to understand *why the optimizer chose what it chose*. Never use it to -say what was slow. - -## Row mode reports cumulative time; batch mode does not - -Every `RelOp` in an actual plan carries `` with one -`` per thread. The attributes you care about: - -| Attribute | Meaning | Aggregate across threads by | -|---|---|---| -| `ActualRows` | rows emitted | **sum** | -| `ActualRowsRead` | rows examined before the predicate | **sum** | -| `ActualExecutions` | times this operator started | **sum** | -| `ActualCPUms` | CPU consumed | **sum** | -| `ActualElapsedms` | wall clock | **max** | -| `ActualLogicalReads` | pages read from buffer pool | **sum** | - -Elapsed takes the max because threads run concurrently; the operator finished -when its slowest thread finished. CPU sums because every thread burned its own. - -Now the trap. In **row mode**, `ActualElapsedms` and `ActualCPUms` are -**cumulative**: an operator's numbers include everything in its subtree. The -root node's elapsed time is therefore the whole query's elapsed time. Sorting -operators by raw `ActualElapsedms` sorts them by depth, and always crowns the -root. This is meaningless and it looks authoritative. - -In **batch mode**, operators pipeline, and each reports its own standalone time. -No subtraction needed. Check `ActualExecutionMode` (falling back to -`EstimatedExecutionMode`) per operator — a single plan can mix both. - -## Computing self time - -For a row-mode operator: - -``` -self elapsed = ActualElapsedms - sum(effective elapsed of each child) -self CPU = ActualCPUms - sum(effective CPU of each child) -``` - -For a batch-mode operator, self time is the reported time. Do not subtract. - -Three complications make "effective elapsed of each child" more than a lookup: - -**Pass-through operators carry no runtime stats.** Compute Scalar is the usual -one. Its `ActualElapsedms` is absent or zero, not because it was instant but -because SQL Server does not record it. Subtracting zero for it makes its parent -absorb the whole subtree below. When a child has no runtime stats, look *through* -it and sum its children instead. - -**Exchange operators lie.** `Parallelism` (Gather Streams, Repartition Streams, -Distribute Streams) accumulates time spent waiting on whatever is downstream. A -spilling sort above an exchange inflates the exchange's numbers. Worse, thread 0 -of an exchange is the coordinator, and its elapsed time is the wall clock for the -entire parallel branch, not the operator's own work. - -When computing an exchange's own time, ignore thread 0 and use the slowest worker -thread. When an exchange is a *child* and you need its contribution to a parent, -take the max over its children rather than its own reported number. Treat any -self time you compute for an exchange as advisory. Do not build a conclusion on -it. - -**Parallel plans must subtract within a thread, never across threads.** For each -thread *t*: - -``` -self[t] = parent_elapsed[t] - sum(child_elapsed[t]) -self = max over t of self[t] -``` - -Subtracting an aggregate child total from an aggregate parent total mixes threads -that never ran together and produces garbage, frequently negative, which then -clamps to zero and hides the real hotspot. - -`scripts/extract.py` implements all of this. Prefer it to doing the arithmetic -by hand. - -## Batch-mode subtrees under a row-mode parent - -If a row-mode operator sits above a contiguous batch-mode region, that region's -operators each reported standalone times. To subtract the region's contribution -from the row-mode parent, **sum** the batch operators' elapsed times across the -region, stopping at any `Parallelism` boundary. Taking just the topmost batch -operator's time undercounts and inflates the parent's apparent self time. - -## Statement-level totals - -`` on the `QueryPlan` element gives the authoritative totals: - -- `ElapsedTime` — wall clock, milliseconds -- `CpuTime` — CPU, milliseconds -- `UdfElapsedTime` / `UdfCpuTime` — time inside scalar UDFs, when present - -`UdfCpuTime` is worth checking whenever it exists. It is time the plan's -operators mostly do not attribute to themselves, and it is often the answer. - -CPU far exceeding elapsed means parallelism, which is expected. Elapsed far -exceeding CPU means the query spent its life waiting — check ``, and -`GrantWaitTime` in ``. - -## Self times need not sum to the total in a parallel plan - -In a **serial row-mode** plan, per-operator self elapsed times should roughly sum -to `QueryTimeStats/@ElapsedTime`. If they sum to several times the total, you -forgot to subtract children. - -In a **parallel** plan they legitimately exceed it, sometimes substantially. Each -operator's elapsed is the max across its threads, and separate branches of the -plan run concurrently, so overlapping work is counted more than once. Two hot -operators showing 69.6s and 25.5s in a query that took 71.1s is not an arithmetic -error and does not mean you double-counted. Do not talk yourself out of a correct -answer because the numbers do not add up — in a parallel plan, they should not. - -Self **CPU** behaves differently again: it sums across threads, so total CPU -routinely exceeds total elapsed by roughly the degree of parallelism. That is what -parallelism is. - -## Sanity checks before you publish a number - -- Is your top operator by self time the root node? Then you almost certainly - computed cumulative time, not self time. -- Did you compute a negative self time and clamp it? That is a signal you - subtracted across threads or through an exchange, not a signal the operator - took zero time. -- Are you quoting a self elapsed time next to a *cumulative* CPU number? They are - not comparable and the pairing is nonsense. Self elapsed and self CPU are both - fine to quote, as long as you say which is which. -- Did you check `UdfCpuTime`? If it is large, the operators are lying to you by - omission and the answer is the scalar UDF. diff --git a/skills/query-plan-analysis/references/warnings.md b/skills/query-plan-analysis/references/warnings.md deleted file mode 100644 index 0d45a31..0000000 --- a/skills/query-plan-analysis/references/warnings.md +++ /dev/null @@ -1,207 +0,0 @@ -# Warnings SQL Server puts in the plan - -These require no inference. They are the highest signal-to-noise content in a -plan. They appear in a `` element, which can hang off the `QueryPlan` -(statement-level) or off any `RelOp` (operator-level). The location matters — -"a spill happened" is much less useful than "the hash join at node 3 spilled." - -Some are attributes on ``; some are child elements. Both are listed -below. - -## Implicit conversion — `` - -Attributes: `ConvertIssue`, `Expression`. - -Two distinct issues share this element, and they are not equally serious: - -- **`ConvertIssue="Seek Plan"`** — the conversion prevented an index seek. The - query is scanning where it could have sought. This is usually the expensive - one. -- **`ConvertIssue="Cardinality Estimate"`** — the conversion did not block the - seek but did prevent the optimizer from using the histogram, so the estimate - is a guess. Bad plan shape downstream. - -Cause: comparing columns of different types, so SQL Server converts one side. -The conversion happens on whichever side has *lower datatype precedence*. If the -column loses, the index on it becomes unusable for seeking. - -Most common in practice: - -- `NVARCHAR` parameter compared to a `VARCHAR` column. `NVARCHAR` has higher - precedence, so the *column* gets converted. Very common with ORMs, which - default to sending Unicode. This one blocks seeks. -- `VARCHAR` parameter against an `NVARCHAR` column converts the *parameter*, - which is harmless. -- Numeric types against string columns, always bad. -- A `DATE` column compared against a `DATETIME` literal. - -Fix by making the types match — change the parameter's type, or the column's. -Do not fix it by wrapping the column in `CAST`, which makes the predicate -non-SARGable and achieves nothing. - -Note that SQL Server does not always emit this warning even when an implicit -conversion is present. Its absence is not proof. - -## Spills — ``, ``, ``, `` - -The operator asked for memory, got less than it needed, and wrote to tempdb. - -`SpillLevel` matters. Level 1 is a single pass. Higher levels mean recursive -spilling — the spilled partition itself did not fit and spilled again — and cost -grows sharply. Level 3 and above is pathological and usually indicates severe -skew in the hash key rather than an undersized grant. - -`SpilledThreadCount` against the plan's DOP tells you whether the spill was -uniform or a skew problem. One thread of eight spilling is a data distribution -problem, not a memory problem. - -`GrantedMemoryKb` versus `UsedMemoryKb` on the spill detail elements shows -whether the grant was even close. - -The root cause of most spills is an **underestimate** upstream: the memory grant -is sized from estimated rows. Fix the estimate and the spill usually disappears. -Granting more memory treats the symptom, and takes memory from other queries. - -An **exchange spill** is different in character. It usually means a -`Repartition Streams` or `Gather Streams` deadlocked on its buffers and is -frequently caused by an order-preserving exchange under a merge join. It is -worth treating as its own problem rather than as "another spill." - -## Missing statistics — `` - -The optimizer wanted a histogram on a column and there wasn't one. Every estimate -involving that column is a default guess (see `cardinality.md`). - -Common causes: `AUTO_CREATE_STATISTICS` is off; the column is in a table variable; -the predicate is against a column of a type that cannot have statistics. - -Not always actionable, but when present alongside a large cardinality skew on the -same table it is very likely the cause. - -## Stale statistics — `` - -Newer builds only. Says exactly what it says. Update the statistics and recompile. - -## Memory grant — `` - -Attributes: `GrantWarningKind`, `RequestedMemory`, `GrantedMemory`, -`MaxUsedMemory` (all KB). - -`GrantWarningKind` is one of `ExcessiveGrant`, `GrantIncrease`, or -`UsedMoreThanGranted`. - -An excessive grant is a server-wide problem, not a query problem. The query may -run fine while starving everything else. Look at -`GrantedMemory / MaxUsedMemory` — a ratio above about 10x deserves attention, and -above 50x is severe. - -Grants are sized from estimated rows *and* estimated row size. A query selecting -`VARCHAR(MAX)` or wide `NVARCHAR` columns gets a grant based on **half the -declared maximum width**, not actual data length. `SELECT` of a `VARCHAR(8000)` -column that always contains 20 characters still reserves 4000 bytes per row. This -is why "just select fewer columns" is real advice and not a platitude. - -## No join predicate — `` - -**Frequently a false alarm.** Read this one skeptically. - -It genuinely fires for an accidental cross join. But it also fires when the -optimizer removed a redundant join predicate during simplification, and when an -`APPLY` correlates via an outer reference rather than a join predicate — both of -which are completely fine. - -Three cases, each with a positive tell. Check them in this order. The digest's -`PREDICATES ON HOT / WARNED OPERATORS` section prints everything you need, and -`extract.py --node N` gives you the full detail for the joining operator. - -**Correlated APPLY or outer reference (benign).** The join operator has an -`` list. Values are passed into the inner side rather than -compared by a predicate, so there is nothing for the warning to find. - -**Transitive predicate elimination (benign, and the most common false alarm).** -This one has *neither* an `` list *nor* a join predicate, so it -superficially resembles the bad case. The tell is on the join's **inputs**, not -the join. If both children are independently filtered to the same constant — each -carrying a `Predicate` or `SeekPredicate` against the same literal — then the -optimizer proved the join predicate redundant and dropped it. - -It happens any time you filter a join column by a constant: - -```sql -SELECT TOP (1) c.Id -FROM dbo.Posts AS p -JOIN dbo.Comments AS c ON p.OwnerUserId = c.UserId -WHERE p.OwnerUserId = 22656; -``` - -Given `p.OwnerUserId = 22656` and `p.OwnerUserId = c.UserId`, it follows that -`c.UserId = 22656`. SQL Server pushes `= 22656` into both tables and discards the -join condition, which trips the warning. Both inputs are pinned to the same -value, so the "cross join" emits exactly the right rows. Confirm by checking that -the join's output row count did not multiply. - -**Genuine cross join (bad).** No outer references, no join predicate, and the -inputs are *not* both pinned to the same constant. The output row count is -roughly the product of the input row counts. That multiplication is the -signature — an accidental cartesian product is loud. - -## Unmatched indexes — `` - -A filtered index could not be used because the query was parameterized and the -optimizer cannot prove at compile time that the parameter satisfies the filter -predicate. The child `` elements name the index. - -Fixes: add `OPTION (RECOMPILE)`, or write the filter predicate explicitly into -the query's `WHERE` clause so the optimizer can match it. - -## Wait stats — `` / `` - -Present in actual plans on reasonably modern builds. `WaitType`, `WaitTimeMs`, -`WaitCount`. - -The ones worth naming: - -- `RESOURCE_SEMAPHORE` — waiting for a memory grant. Somebody's grant is too big, - possibly this query's. -- `PAGEIOLATCH_SH` — reading data pages from disk. Either the working set does not - fit in memory or the query is reading far more than it needs. -- `CXPACKET` / `CXCONSUMER` — parallelism coordination. `CXCONSUMER` is generally - benign. High `CXPACKET` with thread skew points at the skew, not at parallelism. -- `EXECSYNC` — threads blocked waiting for a serial phase of a parallel plan, - classically the build of an **eager spool**. When `EXECSYNC` is near the top and - an eager index spool is present, it is the same finding twice: the other threads - sat idle while one built the spool. It corroborates, it is not a separate - problem. -- `LCK_M_*` — blocking. The plan cannot tell you who blocked you. -- `SOS_SCHEDULER_YIELD` — CPU pressure, or a spinlock. Rarely the query's fault. -- `ASYNC_NETWORK_IO` — the client is not consuming results fast enough. Not a plan - problem at all, and no amount of tuning fixes it. - -**A serial plan showing heavy `CXPACKET` is not a contradiction.** If -`DegreeOfParallelism` is 0 or 1 and `NonParallelPlanReason` is set, but `CXPACKET` -dominates the waits and `UdfCpuTime` is large, the outer statement ran serially -while the scalar UDF's *own internal queries* each went parallel. The waits are -aggregated from those inner executions. Do not let the apparent contradiction talk -you out of a correct scalar-UDF diagnosis. - -Waits are cumulative across threads, so a parallel query shows inflated wait -times. Compare against `QueryTimeStats/@ElapsedTime` before concluding anything. - -## Spill occurred / spatial guess / full update for online index build - -`` appears in lightweight profiling output and only tells you that -*something* spilled. `` and `` are -informational and rarely the story. - -## What is NOT in the warnings - -Absence of a warning proves nothing. SQL Server does not warn about: - -- Non-SARGable predicates (a function on a column) -- Key lookups, however many rows they run over -- Scalar UDFs running once per row -- Row goals gone wrong -- Eager index spools -- Nested loops joins over enormous outer inputs - -Those you find by reading the plan. diff --git a/skills/query-plan-analysis/scripts/extract.py b/skills/query-plan-analysis/scripts/extract.py deleted file mode 100644 index 7ce9523..0000000 --- a/skills/query-plan-analysis/scripts/extract.py +++ /dev/null @@ -1,1108 +0,0 @@ -#!/usr/bin/env python3 -""" -Flatten a SQL Server .sqlplan / showplan XML file into a compact text digest. - -Reads nothing but the standard library. Handles UTF-16 (the default encoding -SSMS writes) and UTF-8 plans transparently. - - python extract.py plan.sqlplan - python extract.py plan.sqlplan --top 15 - -The digest is ordered to match the triage procedure in SKILL.md: what kind of -plan this is, what SQL Server already told you, where time actually went, where -the estimates went wrong, and only then indexes. -""" - -import argparse -import re -import sys -import xml.etree.ElementTree as ET - -NS = "{http://schemas.microsoft.com/sqlserver/2004/07/showplan}" - -EXCHANGE_LOGICAL = {"Gather Streams", "Distribute Streams", "Repartition Streams"} - - -def tag(el): - """Local name of an element, namespace stripped.""" - return el.tag.split("}")[-1] if "}" in el.tag else el.tag - - -def num(el, name, default=0.0): - v = el.get(name) - if v is None: - return default - try: - return float(v) - except ValueError: - return default - - -class Node: - """One RelOp, with per-thread runtime stats folded to node level.""" - - def __init__(self, el, parent=None): - self.el = el - self.parent = parent - self.node_id = el.get("NodeId", "?") - self.physical = el.get("PhysicalOp", "") - self.logical = el.get("LogicalOp", "") - self.est_rows = num(el, "EstimateRows") - self.est_exec = num(el, "EstimateExecutions", 1.0) - self.est_rebinds = num(el, "EstimateRebinds") - self.est_rewinds = num(el, "EstimateRewinds") - self.subtree_cost = num(el, "EstimatedTotalSubtreeCost") - self.table_cardinality = num(el, "TableCardinality") - self.parallel = el.get("Parallel") in ("1", "true") - self.est_mode = el.get("EstimatedExecutionMode", "") - # Present only when a row goal is in effect (TOP, FAST N, EXISTS...). - self.row_goal = el.get("EstimateRowsWithoutRowGoal") is not None - - self.threads = [] - self.actual_mode = "" - self.has_actual = False - self.actual_rows = 0.0 - self.actual_rows_read = 0.0 - self.actual_executions = 0.0 - self.elapsed_ms = 0.0 - self.cpu_ms = 0.0 - self.logical_reads = 0.0 - - rti = el.find(NS + "RunTimeInformation") - if rti is not None: - for t in rti.findall(NS + "RunTimeCountersPerThread"): - self.threads.append( - { - "thread": int(num(t, "Thread")), - "rows": num(t, "ActualRows"), - "rows_read": num(t, "ActualRowsRead"), - "executions": num(t, "ActualExecutions"), - "elapsed": num(t, "ActualElapsedms"), - "cpu": num(t, "ActualCPUms"), - "reads": num(t, "ActualLogicalReads"), - } - ) - if not self.actual_mode: - self.actual_mode = t.get("ActualExecutionMode", "") - if self.threads: - self.has_actual = True - # Rows, CPU, reads SUM across threads. Elapsed takes the MAX. - self.actual_rows = sum(t["rows"] for t in self.threads) - self.actual_rows_read = sum(t["rows_read"] for t in self.threads) - self.actual_executions = sum(t["executions"] for t in self.threads) - self.cpu_ms = sum(t["cpu"] for t in self.threads) - self.logical_reads = sum(t["reads"] for t in self.threads) - self.elapsed_ms = max(t["elapsed"] for t in self.threads) - - self.children = [Node(c, self) for c in child_relops(el)] - self.warnings = parse_warnings(el) - - @property - def mode(self): - return self.actual_mode or self.est_mode - - @property - def is_exchange(self): - return self.physical == "Parallelism" or self.logical in EXCHANGE_LOGICAL - - @property - def label(self): - if self.logical and self.logical != self.physical: - return f"{self.physical} ({self.logical})" - return self.physical - - -def child_relops(el): - """ - Direct child RelOps. RelOps nest inside operator-specific elements - (, , ...), so descend until we hit the next RelOp - and stop there. - """ - found = [] - - def walk(e): - for c in e: - if tag(c) == "RelOp": - found.append(c) - else: - walk(c) - - walk(el) - return found - - -def local_elements(relop_el): - """Descendants of a RelOp that belong to it, not crossing into child RelOps.""" - out = [] - - def walk(e): - for c in e: - if tag(c) == "RelOp": - continue - out.append(c) - walk(c) - - walk(relop_el) - return out - - -def unbracket(s): - return (s or "").replace("[", "").replace("]", "") - - -def colref(c): - parts = [c.get("Table"), c.get("Column")] - return unbracket(".".join(p for p in parts if p)) - - -def node_objects(node): - """Tables/indexes this operator touches.""" - out = [] - for e in local_elements(node.el): - if tag(e) != "Object": - continue - name = unbracket(f"{e.get('Schema', '')}.{e.get('Table', '')}").strip(".") - idx = unbracket(e.get("Index", "")) - alias = unbracket(e.get("Alias", "")) - label = name - if idx: - label += f".{idx}" - if alias: - label += f" AS {alias}" - out.append(label) - return out - - -def node_predicate(node): - for e in local_elements(node.el): - if tag(e) == "Predicate": - so = e.find(NS + "ScalarOperator") - if so is not None and so.get("ScalarString"): - return so.get("ScalarString") - return None - - -def node_seek_predicates(node): - """Reconstruct 'column op expression' for each seek key.""" - out = [] - for e in local_elements(node.el): - if tag(e) != "SeekPredicateNew": - continue - for keys in e.findall(NS + "SeekKeys"): - for part in keys: - rc = part.find(NS + "RangeColumns") - rx = part.find(NS + "RangeExpressions") - cols = [colref(c) for c in rc] if rc is not None else [] - exprs = [so.get("ScalarString", "") for so in rx] if rx is not None else [] - scan_type = part.get("ScanType", "=") - if cols: - out.append(f"{tag(part)}: {', '.join(cols)} {scan_type} {', '.join(exprs)}".strip()) - return out - - -def node_outer_references(node): - for e in local_elements(node.el): - if tag(e) == "OuterReferences": - return [colref(c) for c in e.findall(NS + "ColumnReference")] - return [] - - -def node_output_list(node): - ol = node.el.find(NS + "OutputList") - if ol is None: - return [] - return [colref(c) for c in ol.findall(NS + "ColumnReference")] - - -def node_scan_order(node): - for e in local_elements(node.el): - if e.get("Ordered") is not None: - ordered = e.get("Ordered") in ("1", "true") - direction = e.get("ScanDirection", "") - return f"Ordered={'yes' if ordered else 'no'}" + (f" {direction}" if direction else "") - return None - - -def is_eager_index_spool(node): - """ - Index Spool specifically, NOT Table Spool. An eager *table* spool is ordinary - Halloween protection in an update plan and is not a defect; only the eager - *index* spool means "the optimizer built an index because you lack one," and - only it suppresses the missing-index request. - """ - return node.physical == "Index Spool" and "Eager" in node.logical - - -def own_cost(node): - """ - Estimated cost attributable to this operator alone. Subtree cost is cumulative, - so ranking by it always crowns the root. Still an ESTIMATE, in every plan. - """ - return max(0.0, node.subtree_cost - sum(c.subtree_cost for c in node.children)) - - -def fmt_duration(ms): - """Raw ms is hard to feel above about a minute.""" - if ms < 60_000: - return f"{ms:,.0f} ms" - secs = ms / 1000.0 - h, rem = divmod(int(secs), 3600) - m, s = divmod(rem, 60) - human = f"{h}h{m:02d}m{s:02d}s" if h else f"{m}m{s:02d}s" - return f"{ms:,.0f} ms ({human})" - - -# --------------------------------------------------------------------------- -# Self-time attribution. -# -# Row mode reports elapsed/CPU cumulatively: a node's number includes everything -# below it. Batch mode reports each operator standalone. Exchange operators -# accumulate downstream wait time, so their raw numbers mean little. -# --------------------------------------------------------------------------- - - -def sum_batch_subtree(node): - """Batch operators pipeline, so their elapsed times add rather than nest.""" - total = node.elapsed_ms - for c in node.children: - if c.physical == "Parallelism": - continue # zone boundary - if c.mode == "Batch" and c.has_actual: - total += sum_batch_subtree(c) - else: - total += effective_child_elapsed(c) - return total - - -def effective_child_elapsed(child): - """Elapsed time a child contributes to its parent's subtree total.""" - if child.physical == "Parallelism" and child.children: - return max(effective_child_elapsed(gc) for gc in child.children) - if child.mode == "Batch" and child.has_actual: - return sum_batch_subtree(child) - if child.elapsed_ms > 0: - return child.elapsed_ms - if not child.children: - return 0.0 - # Pass-through operator with no runtime stats (Compute Scalar and friends): - # look through it to the first descendants that have them. - return sum(effective_child_elapsed(gc) for gc in child.children) - - -def per_thread_self_elapsed(node): - """ - Parallel row mode: subtract within a thread, never across threads, then take - the slowest thread. Cross-thread subtraction produces nonsense. - """ - parent_by_thread = {t["thread"]: t["elapsed"] for t in node.threads} - child_by_thread = {} - for child in node.children: - target = child - if child.physical == "Parallelism" and child.children: - target = max(child.children, key=lambda c: c.elapsed_ms) - for t in target.threads: - child_by_thread[t["thread"]] = child_by_thread.get(t["thread"], 0.0) + t["elapsed"] - best = 0.0 - for thread_id, parent_ms in parent_by_thread.items(): - self_ms = max(0.0, parent_ms - child_by_thread.get(thread_id, 0.0)) - best = max(best, self_ms) - return best - - -def own_elapsed_ms(node): - if not node.has_actual or node.elapsed_ms <= 0: - return 0.0 - if node.mode == "Batch": - return node.elapsed_ms - if node.is_exchange: - # Thread 0 is the coordinator; its elapsed is wall clock for the whole - # branch, not this operator's work. - workers = [t["elapsed"] for t in node.threads if t["thread"] > 0] - if workers: - return max(0.0, max(workers) - sum(effective_child_elapsed(c) for c in node.children)) - return 0.0 - if len(node.threads) > 1: - return per_thread_self_elapsed(node) - return max(0.0, node.elapsed_ms - sum(effective_child_elapsed(c) for c in node.children)) - - -def effective_child_cpu(child): - if child.physical == "Parallelism" and child.children: - return max(effective_child_cpu(gc) for gc in child.children) - if child.cpu_ms > 0: - return child.cpu_ms - if not child.children: - return 0.0 - return sum(effective_child_cpu(gc) for gc in child.children) - - -def own_cpu_ms(node): - """ - Self CPU. Reported CPU is cumulative in row mode exactly like elapsed, so a - node's raw ActualCPUms includes every operator beneath it. Printing self - elapsed next to cumulative CPU produces gibberish. - """ - if not node.has_actual or node.cpu_ms <= 0: - return 0.0 - if node.mode == "Batch": - return node.cpu_ms # standalone, exactly like batch-mode elapsed - if len(node.threads) > 1: - parent_by_thread = {t["thread"]: t["cpu"] for t in node.threads} - child_by_thread = {} - for child in node.children: - target = child - if child.physical == "Parallelism" and child.children: - target = max(child.children, key=lambda c: c.cpu_ms) - for t in target.threads: - child_by_thread[t["thread"]] = child_by_thread.get(t["thread"], 0.0) + t["cpu"] - best = 0.0 - for thread_id, parent_cpu in parent_by_thread.items(): - best = max(best, max(0.0, parent_cpu - child_by_thread.get(thread_id, 0.0))) - return best - return max(0.0, node.cpu_ms - sum(effective_child_cpu(c) for c in node.children)) - - -# --------------------------------------------------------------------------- -# Warnings -# --------------------------------------------------------------------------- - -WARN_FLAGS = [ - ("NoJoinPredicate", "No join predicate"), - ("SpatialGuess", "Spatial index selectivity guessed"), - ("UnmatchedIndexes", "Unmatched indexes (parameterization)"), - ("FullUpdateForOnlineIndexBuild", "Full update for online index build"), -] - - -def parse_warnings(parent_el): - w = parent_el.find(NS + "Warnings") - if w is None: - return [] - out = [] - - for attr, text in WARN_FLAGS: - if w.get(attr) in ("1", "true"): - out.append(text) - - for c in w.findall(NS + "PlanAffectingConvert"): - out.append( - f"Implicit conversion [{c.get('ConvertIssue', '?')}]: {c.get('Expression', '')}" - ) - - spill = w.find(NS + "SpillToTempDb") - level = spill.get("SpillLevel", "?") if spill is not None else None - threads = spill.get("SpilledThreadCount", "?") if spill is not None else None - - for kind, el_name in (("Sort", "SortSpillDetails"), ("Hash", "HashSpillDetails")): - for s in w.findall(NS + el_name): - prefix = f"{kind} spill" - if level is not None: - prefix += f" level {level}, {threads} thread(s)" - out.append( - f"{prefix} - granted {num(s, 'GrantedMemoryKb'):,.0f} KB, " - f"used {num(s, 'UsedMemoryKb'):,.0f} KB, " - f"{num(s, 'WritesToTempDb'):,.0f} writes, " - f"{num(s, 'ReadsFromTempDb'):,.0f} reads" - ) - - if spill is not None and not w.findall(NS + "SortSpillDetails") and not w.findall(NS + "HashSpillDetails"): - out.append(f"Spill to tempdb, level {level}, {threads} thread(s)") - - for s in w.findall(NS + "ExchangeSpillDetails"): - out.append(f"Exchange spill - {num(s, 'WritesToTempDb'):,.0f} writes to tempdb") - - if w.find(NS + "SpillOccurred") is not None: - out.append("Spill occurred during execution") - - m = w.find(NS + "MemoryGrantWarning") - if m is not None: - out.append( - f"Memory grant [{m.get('GrantWarningKind', '?')}]: " - f"requested {num(m, 'RequestedMemory') / 1024:,.0f} MB, " - f"granted {num(m, 'GrantedMemory') / 1024:,.0f} MB, " - f"used {num(m, 'MaxUsedMemory') / 1024:,.0f} MB" - ) - - for el_name, text in ( - ("ColumnsWithNoStatistics", "No statistics on"), - ("ColumnsWithStaleStatistics", "Stale statistics on"), - ): - e = w.find(NS + el_name) - if e is not None: - cols = [c.get("Column", "") for c in e.findall(NS + "ColumnReference")] - out.append(f"{text}: {', '.join(filter(None, cols))}") - - for wait in w.findall(NS + "Wait"): - out.append(f"Wait {wait.get('WaitType')}: {wait.get('WaitTime')}ms") - - return out - - -# --------------------------------------------------------------------------- -# Cardinality estimator default-guess fingerprints -# --------------------------------------------------------------------------- - -CE_GUESSES = [ - (0.29, 0.31, "30% equality guess"), - (0.098, 0.102, "10% inequality guess"), - (0.088, 0.092, "9% LIKE/BETWEEN guess"), - (0.155, 0.175, "~16.4% compound predicate guess"), - (0.009, 0.011, "1% multi-inequality guess"), -] - - -def detect_ce_guess(est_rows, table_cardinality): - if table_cardinality <= 0: - return None - sel = est_rows / table_cardinality - for lo, hi, name in CE_GUESSES: - if lo <= sel <= hi: - return f"{name} ({sel * 100:.1f}% of {table_cardinality:,.0f})" - return None - - -# --------------------------------------------------------------------------- -# Digest -# --------------------------------------------------------------------------- - - -def flatten(node, acc=None): - acc = acc if acc is not None else [] - acc.append(node) - for c in node.children: - flatten(c, acc) - return acc - - -def fmt_rows(n): - return f"{n:,.0f}" if n >= 1 else f"{n:.4g}" - - -def render_tree(node, out, has_actual, depth=0, budget=None): - """ - Indented operator tree. This is the only view of plan SHAPE, and on an - estimated plan it is the only thing there is to reason about. - """ - if budget is not None: - if budget[0] <= 0: - return - budget[0] -= 1 - indent = " " + " " * depth - objs = node_objects(node) - obj = f" {objs[0]}" if objs else "" - if has_actual and node.has_actual: - execs = max(1.0, node.actual_executions) - detail = ( - f"est {fmt_rows(node.est_rows)}/exec vs " - f"actual {fmt_rows(node.actual_rows / execs)}/exec" - ) - else: - detail = f"est {fmt_rows(node.est_rows)} rows, cost {own_cost(node):,.2f}" - out.append(f"{indent}[{node.node_id}] {node.label} ({detail}){obj}") - for c in node.children: - render_tree(c, out, has_actual, depth + 1, budget) - - -def statement_text(stmt_el): - return " ".join((stmt_el.get("StatementText") or "").strip().split()) - - -def describe_statement(stmt_el, out, top_n, full_sql=False): - text = statement_text(stmt_el) - stmt_id = stmt_el.get("StatementId", "?") - if not full_sql and len(text) > 1500: - text = text[:1500] + f" ... [truncated; see --sql {stmt_id} for the full text]" - - out.append("=" * 78) - out.append(f"STATEMENT {stmt_id} [{stmt_el.get('StatementType', '?')}]") - out.append("=" * 78) - out.append(f" {text}") - out.append("") - - qp = stmt_el.find(NS + "QueryPlan") - if qp is None: - out.append(" (no query plan on this statement)") - out.append("") - return - - # --- 1. What kind of plan is this? ------------------------------------- - root_el = qp.find(NS + "RelOp") - if root_el is None: - out.append(" (no operators)") - out.append("") - return - root = Node(root_el) - nodes = flatten(root) - has_actual = any(n.has_actual for n in nodes) - - qts = qp.find(NS + "QueryTimeStats") - out.append("-- PLAN TYPE ------------------------------------------------") - out.append(f" Runtime stats present : {'YES (actual plan)' if has_actual else 'NO (ESTIMATED plan)'}") - out.append(f" CE model version : {stmt_el.get('CardinalityEstimationModelVersion', '?')}") - out.append(f" Optimization level : {stmt_el.get('StatementOptmLevel', '?')}") - early_abort = stmt_el.get("StatementOptmEarlyAbortReason") - if early_abort: - out.append(f" Early abort reason : {early_abort}") - out.append(f" Estimated subtree cost: {num(stmt_el, 'StatementSubTreeCost'):,.2f} (ALWAYS an estimate)") - dop = qp.get("DegreeOfParallelism") - if dop: - out.append(f" Degree of parallelism : {dop}") - npr = qp.get("NonParallelPlanReason") - if npr: - out.append(f" Non-parallel reason : {npr}") - if qts is not None: - total_elapsed = num(qts, "ElapsedTime") - out.append( - f" Query time : {fmt_duration(total_elapsed)} elapsed, " - f"{fmt_duration(num(qts, 'CpuTime'))} CPU" - ) - udf_cpu = num(qts, "UdfCpuTime") - udf_elapsed = num(qts, "UdfElapsedTime") - if udf_cpu > 0 or udf_elapsed > 0: - out.append( - f" UDF time : {fmt_duration(udf_elapsed)} elapsed, " - f"{fmt_duration(udf_cpu)} CPU" - ) - if total_elapsed > 0: - pct = udf_elapsed / total_elapsed * 100 - out.append( - f" -> scalar UDFs account for {pct:.2f}% of elapsed time. " - f"{'This is the query.' if pct > 50 else ''}".rstrip() - ) - # Per-invocation cost is the most persuasive number available, and the - # UDF runs once per row of whichever operator computes it. - udf_rows = max( - (n.actual_rows for n in nodes if n.physical == "Compute Scalar" and n.has_actual), - default=0, - ) - if udf_rows > 0 and udf_elapsed > 0: - out.append( - f" -> ~{udf_elapsed / udf_rows:,.1f} ms elapsed per invocation " - f"across {udf_rows:,.0f} rows" - ) - out.append("") - - # --- 2. What did SQL Server already tell you? -------------------------- - out.append("-- WARNINGS -------------------------------------------------") - plan_warnings = parse_warnings(qp) - any_warning = bool(plan_warnings) - for w in plan_warnings: - out.append(f" [plan] {w}") - for n in nodes: - for w in n.warnings: - any_warning = True - out.append(f" [node {n.node_id} {n.label}] {w}") - if not any_warning: - out.append(" (none)") - out.append("") - - # --- Memory grant ------------------------------------------------------ - mg = qp.find(NS + "MemoryGrantInfo") - if mg is not None and (mg.get("GrantedMemory") or mg.get("RequestedMemory")): - out.append("-- MEMORY GRANT (KB) ----------------------------------------") - for a in ( - "SerialRequiredMemory", - "SerialDesiredMemory", - "RequestedMemory", - "GrantedMemory", - "MaxUsedMemory", - "MaxQueryMemory", - "GrantWaitTime", - ): - if mg.get(a) is not None: - out.append(f" {a:22}: {num(mg, a):,.0f}") - granted, used = num(mg, "GrantedMemory"), num(mg, "MaxUsedMemory") - if granted > 0 and used > 0: - out.append(f" -> used {used / granted * 100:.1f}% of the grant") - out.append("") - - # --- Parameters -------------------------------------------------------- - params = qp.find(NS + "ParameterList") - if params is not None: - rows = [] - for c in params.findall(NS + "ColumnReference"): - compiled = c.get("ParameterCompiledValue") - runtime = c.get("ParameterRuntimeValue") - if compiled is None and runtime is None: - continue - flag = "" - if compiled is None: - flag = " (no compiled value: not sniffed - local variable, or RECOMPILE)" - elif runtime is not None and compiled != runtime: - flag = " <-- compiled for a different value than it ran with" - rows.append( - f" {c.get('Column', '?')}: compiled={compiled or '(none)'} " - f"runtime={runtime or '(none)'}{flag}" - ) - if rows: - out.append("-- PARAMETERS -----------------------------------------------") - out.extend(rows) - out.append("") - - # --- 3. Where did time actually go? ------------------------------------ - hot = [] - if has_actual: - out.append(f"-- TOP {top_n} OPERATORS BY SELF ELAPSED TIME (not cost) -----") - out.append(" 'self' = this operator's own work, children subtracted out.") - out.append(" Sorted by self elapsed. Self CPU is a SEPARATE clock: it sums across") - out.append(" threads while elapsed takes the slowest thread, so CPU exceeding") - out.append(" elapsed means parallelism, not a problem. Never quote one as the other.") - out.append("") - out.append(f" {'self elapsed':>14} {'self CPU':>12} {'rows out':>14} node operator") - timed = [(own_elapsed_ms(n), n) for n in nodes] - timed = [(ms, n) for ms, n in timed if ms > 0] - timed.sort(key=lambda x: -x[0]) - if not timed: - out.append(" (no operator elapsed times recorded)") - for ms, n in timed[:top_n]: - hot.append(n) - note = " [exchange: raw times unreliable]" if n.is_exchange else "" - out.append( - f" {ms:11,.0f} ms {own_cpu_ms(n):9,.0f} ms {fmt_rows(n.actual_rows):>14} " - f"{n.node_id:>4} {n.label}{note}" - ) - # Rows read vs rows emitted: the tell for a predicate applied as a - # filter instead of a seek. Only meaningful when SQL Server recorded it. - if n.actual_rows_read > 0 and n.actual_rows > 0: - ratio = n.actual_rows_read / n.actual_rows - if ratio >= 2: - if n.row_goal: - flag = " [row goal: stopped early, did not read the table]" - elif ratio >= 100: - flag = " <-- reads far more than it returns" - else: - flag = "" - out.append( - f" {'':>14} {'':>12} read {fmt_rows(n.actual_rows_read)} rows " - f"to emit {fmt_rows(n.actual_rows)} ({ratio:,.0f}x){flag}" - ) - out.append("") - - else: - # No runtime data, so shape and estimated cost are all there is. Rank by - # SELF cost, since subtree cost is cumulative and always crowns the root. - out.append(f"-- TOP {top_n} OPERATORS BY ESTIMATED SELF COST ---------------") - out.append(" ESTIMATES, not measurements. Nothing ran. Cost cannot tell you") - out.append(" what was slow - it can only tell you what the optimizer feared.") - out.append("") - costed = sorted(((own_cost(n), n) for n in nodes), key=lambda x: -x[0]) - for c, n in costed[:top_n]: - if c <= 0: - continue - objs = node_objects(n) - out.append( - f" {c:12,.2f} node {n.node_id:>3} {n.label} " - f"(est {fmt_rows(n.est_rows)} rows)" - + (f" {objs[0]}" if objs else "") - ) - out.append("") - - # --- Plan shape -------------------------------------------------------- - out.append("-- OPERATOR TREE -------------------------------------------") - out.append(" Children are indented. The FIRST child of a join is its outer input.") - budget = [80] - render_tree(root, out, has_actual, budget=budget) - if budget[0] <= 0: - out.append(f" ... tree truncated at 80 operators of {len(nodes)}") - out.append("") - - # Operators the digest names elsewhere; their predicates get printed below so - # nobody has to open the raw XML to follow up on a node we pointed them at. - cited = list(hot) - - # --- 4. Where are the estimates wrong? --------------------------------- - if has_actual: - out.append("-- CARDINALITY SKEW (per execution) -------------------------") - skewed = [] - for n in nodes: - if not n.has_actual or n.is_exchange: - continue - execs = max(1.0, n.actual_executions) - actual_per_exec = n.actual_rows / execs - est = n.est_rows # already per-execution in showplan - if est <= 0 and actual_per_exec <= 0: - continue - ratio = (actual_per_exec + 1) / (est + 1) - if ratio >= 10 or ratio <= 0.1: - skewed.append((abs(ratio if ratio >= 1 else 1 / ratio), n, est, actual_per_exec, execs, ratio)) - skewed.sort(key=lambda x: -x[0]) - if not skewed: - out.append(" (no operator off by 10x or more)") - for _, n, est, act, execs, ratio in skewed[:top_n]: - cited.append(n) - direction = "under" if ratio > 1 else "over" - out.append( - f" node {n.node_id:>3} {n.label}: est {fmt_rows(est)}/exec vs actual " - f"{fmt_rows(act)}/exec over {fmt_rows(execs)} exec(s) -> {direction}estimated " - f"{(ratio if ratio >= 1 else 1 / ratio):,.1f}x" - ) - guess = detect_ce_guess(n.est_rows, n.table_cardinality) - if guess: - out.append(f" estimate {guess} - the optimizer had no useful statistics") - out.append("") - - # --- 5. Thread skew ------------------------------------------------ - skewed_nodes = [] - for n in nodes: - if len(n.threads) <= 1: - continue - workers = [t["rows"] for t in n.threads if t["thread"] > 0] - if len(workers) < 2: - continue - hi, lo = max(workers), min(workers) - # Ignore trivial row counts; a 4x imbalance over 12 rows means nothing. - if hi < 100 or (lo > 0 and hi / lo < 4): - continue - idle = sum(1 for w in workers if w == 0) - skewed_nodes.append((hi, n, hi, lo, len(workers), idle)) - if skewed_nodes: - skewed_nodes.sort(key=lambda x: -x[0]) - out.append("-- PARALLEL THREAD SKEW ------------------------------------") - all_idle = [s for s in skewed_nodes if s[5] == s[4] - 1] - if len(all_idle) >= 3: - out.append( - f" {len(all_idle)} operators did ALL their work on a single thread " - f"(every other worker got 0 rows) - the parallel branch is effectively serial." - ) - for _, n, hi, lo, workers, idle in skewed_nodes[:top_n]: - cited.append(n) - out.append( - f" node {n.node_id:>3} {n.label}: busiest {hi:,.0f} rows, " - f"quietest {lo:,.0f} rows, {idle} of {workers} workers idle" - ) - if len(skewed_nodes) > top_n: - out.append(f" ... and {len(skewed_nodes) - top_n} more skewed operators") - out.append("") - - # --- Waits ------------------------------------------------------------- - ws = qp.find(NS + "WaitStats") - if ws is not None: - waits = ws.findall(NS + "Wait") - if waits: - out.append("-- TOP WAITS ------------------------------------------------") - for w in sorted(waits, key=lambda x: -num(x, "WaitTimeMs"))[:10]: - out.append( - f" {w.get('WaitType', '?'):32} {num(w, 'WaitTimeMs'):>9,.0f} ms " - f"({num(w, 'WaitCount'):,.0f} waits)" - ) - out.append("") - - # --- 6. Missing indexes (read as a hint, never as DDL) ----------------- - # --- Predicates for every operator the digest pointed at --------------- - # indexes.md says to design an index from the spool's SeekPredicate, and - # warnings.md says to diagnose a no-join-predicate from the join's INPUTS. - # Surface all of it so nobody has to open the raw XML. - interesting = list(cited) - for n in nodes: - if not (n.warnings or is_eager_index_spool(n)): - continue - if n not in interesting: - interesting.append(n) - # A warned join is diagnosed from its children: are both pinned to the - # same constant? Without them the reader sees half the discriminator. - for child in n.children: - if child not in interesting: - interesting.append(child) - seen_ids = set() - ordered = [] - for n in interesting: - if id(n) not in seen_ids: - seen_ids.add(id(n)) - ordered.append(n) - ordered.sort(key=lambda n: nodes.index(n)) - - detail_lines = [] - for n in ordered: - bits = [] - objs = node_objects(n) - if objs: - bits.append(f" object : {', '.join(dict.fromkeys(objs))}") - order = node_scan_order(n) - if order: - bits.append(f" scan : {order}") - for sp in node_seek_predicates(n): - bits.append(f" seek : {sp}") - pred = node_predicate(n) - if pred: - bits.append(f" predicate : {pred}") - outer = node_outer_references(n) - if outer: - bits.append( - f" outer refs: {', '.join(outer)} " - f"(correlated - a join here needs no predicate)" - ) - if n.row_goal: - bits.append( - " row goal : active (TOP/FAST/EXISTS) - a scan may stop early, so a " - "large rows-read count does not mean it read the whole table" - ) - # For a no-join-predicate warning: did the output actually multiply? - if any("No join predicate" in w for w in n.warnings) and n.has_actual: - inputs = [c.actual_rows for c in n.children if c.has_actual] - if len(inputs) == 2: - a, b = inputs - product = a * b - emitted = n.actual_rows - bits.append( - f" row check : inputs {fmt_rows(a)} and {fmt_rows(b)}; a cross join " - f"would emit {fmt_rows(product)}; this join emitted {fmt_rows(emitted)}" - ) - # Only a product meaningfully larger than either input can discriminate. - if product <= max(a, b) or min(a, b) <= 1: - bits.append( - " INCONCLUSIVE - an input has <=1 row (often a row " - "goal), so multiplication cannot be observed. Judge from the " - "predicates above instead." - ) - elif emitted < product / 2: - bits.append( - " Output did not multiply, so this is NOT an " - "accidental cross join." - ) - else: - bits.append( - " Output is close to the product: consistent with a " - "GENUINE cross join. Check the predicates above." - ) - if bits: - detail_lines.append(f" node {n.node_id} {n.label}") - detail_lines.extend(bits) - if detail_lines: - out.append("-- PREDICATES ON CITED OPERATORS ----------------------------") - out.extend(detail_lines) - out.append("") - - out.append("-- MISSING INDEX REQUESTS (hints, NOT ready-to-run DDL) -----") - mi_root = qp.find(NS + "MissingIndexes") - seen_requests = {} - if mi_root is not None: - for group in mi_root.findall(NS + "MissingIndexGroup"): - impact = num(group, "Impact") - for mi in group.findall(NS + "MissingIndex"): - table = unbracket(f"{mi.get('Schema', '')}.{mi.get('Table', '')}") - cols = [] - for cg in mi.findall(NS + "ColumnGroup"): - names = [c.get("Name", "") for c in cg.findall(NS + "Column")] - cols.append((cg.get("Usage", "?"), tuple(names))) - key = (table, tuple(cols)) - # Near-identical requests differing only in impact are noise. - seen_requests[key] = max(seen_requests.get(key, 0.0), impact) - if not seen_requests: - out.append(" (none)") - spools = [n for n in nodes if is_eager_index_spool(n)] - if spools: - ids = ", ".join(n.node_id for n in spools) - out.append( - f" NOTE: an eager INDEX spool is present (node {ids}). Index spools" - ) - out.append( - " suppress the missing-index request, so 'none' here does NOT mean no" - ) - out.append( - " index is needed. Build the index from the spool's seek predicate." - ) - else: - for (table, cols), impact in sorted(seen_requests.items(), key=lambda x: -x[1]): - out.append(f" {table} (claimed impact {impact:.1f}%, of an ESTIMATED cost)") - for usage, names in cols: - out.append(f" {usage:10}: {', '.join(names)}") - out.append(" NOTE: equality column order is arbitrary; existing indexes are ignored.") - out.append("") - - -def load_plan(path): - """ - Parse a showplan file, ignoring the encoding declared in the XML prolog. - - SSMS writes .sqlplan as UTF-16, but a plan that has been opened and re-saved - in an editor is often UTF-8 bytes still carrying encoding="utf-16". Trusting - the declaration makes those files unparseable, so detect from the bytes and - strip the prolog before handing a str to ElementTree. - """ - with open(path, "rb") as f: - raw = f.read() - - if raw.startswith(b"\xff\xfe"): - text = raw.decode("utf-16-le", errors="replace")[1:] - elif raw.startswith(b"\xfe\xff"): - text = raw.decode("utf-16-be", errors="replace")[1:] - elif raw.startswith(b"\xef\xbb\xbf"): - text = raw.decode("utf-8-sig", errors="replace") - elif len(raw) > 1 and raw[1] == 0: - text = raw.decode("utf-16-le", errors="replace") # UTF-16 LE, no BOM - elif len(raw) > 1 and raw[0] == 0: - text = raw.decode("utf-16-be", errors="replace") # UTF-16 BE, no BOM - else: - text = raw.decode("utf-8", errors="replace") - - text = re.sub(r"^\s*<\?xml.*?\?>", "", text, count=1, flags=re.DOTALL) - return ET.fromstring(text.strip()) - - -def describe_node(node, out): - """Everything known about one operator. The sanctioned alternative to - opening the raw XML.""" - out.append("=" * 78) - out.append(f"NODE {node.node_id}: {node.label}") - out.append("=" * 78) - out.append(f" execution mode : {node.mode or '(unspecified)'}") - if node.parallel: - out.append(" parallel : yes") - for label, value in ( - ("object", ", ".join(dict.fromkeys(node_objects(node)))), - ("scan order", node_scan_order(node)), - ("predicate", node_predicate(node)), - ("outer references", ", ".join(node_outer_references(node))), - ): - if value: - out.append(f" {label:17}: {value}") - for sp in node_seek_predicates(node): - out.append(f" seek predicate : {sp}") - outputs = node_output_list(node) - if outputs: - out.append(f" output columns : {', '.join(outputs)}") - out.append("") - out.append(" ESTIMATES") - out.append(f" rows per execution : {fmt_rows(node.est_rows)}") - if node.table_cardinality: - out.append(f" table cardinality : {fmt_rows(node.table_cardinality)}") - guess = detect_ce_guess(node.est_rows, node.table_cardinality) - if guess: - out.append(f" !! estimate {guess}") - out.append(f" subtree cost : {node.subtree_cost:,.4f} (an estimate, always)") - - if not node.has_actual: - out.append("") - out.append(" No runtime statistics on this operator.") - return - out.append("") - out.append(" ACTUALS") - out.append(f" executions : {fmt_rows(node.actual_executions)}") - out.append(f" rows emitted : {fmt_rows(node.actual_rows)} (total, all executions)") - if node.actual_executions > 0: - out.append(f" rows per execution : {fmt_rows(node.actual_rows / node.actual_executions)}") - if node.actual_rows_read: - out.append(f" rows READ : {fmt_rows(node.actual_rows_read)}") - if node.logical_reads: - out.append(f" logical reads : {fmt_rows(node.logical_reads)}") - out.append(f" self elapsed : {fmt_duration(own_elapsed_ms(node))}") - out.append(f" self CPU : {fmt_duration(own_cpu_ms(node))}") - out.append(f" cumulative elapsed : {fmt_duration(node.elapsed_ms)} (includes children in row mode)") - if len(node.threads) > 1: - out.append("") - out.append(" PER THREAD (thread 0 is the coordinator, not a worker)") - for t in sorted(node.threads, key=lambda x: x["thread"]): - out.append( - f" thread {t['thread']:>2}: {t['rows']:>14,.0f} rows " - f"{t['elapsed']:>10,.0f} ms elapsed {t['cpu']:>10,.0f} ms CPU" - ) - if node.warnings: - out.append("") - out.append(" WARNINGS") - for w in node.warnings: - out.append(f" {w}") - - -def main(): - ap = argparse.ArgumentParser(description="Flatten a .sqlplan into a text digest.") - ap.add_argument("plan", help="path to a .sqlplan / showplan XML file") - ap.add_argument("--top", type=int, default=10, help="rows to show in ranked sections") - ap.add_argument( - "--node", - metavar="ID", - help="print full detail for one operator (predicates, per-thread stats) " - "instead of the digest. NodeIds repeat across statements; every match is " - "printed, each tagged with its statement.", - ) - ap.add_argument( - "--sql", - nargs="?", - const="*", - metavar="STMT", - help="print the full, untruncated statement text (optionally for one " - "StatementId) and exit", - ) - args = ap.parse_args() - - try: - root = load_plan(args.plan) - except OSError as e: - print(f"error: could not read {args.plan}: {e}", file=sys.stderr) - return 1 - except ET.ParseError as e: - print( - f"error: {args.plan} is not a valid showplan XML document: {e}\n" - f" (a .sqlplan must have a root element)", - file=sys.stderr, - ) - return 1 - - if tag(root) != "ShowPlanXML": - print( - f"error: {args.plan} parsed as <{tag(root)}>, not . " - f"This is not a query plan.", - file=sys.stderr, - ) - return 1 - - out = [] - header = f"PLAN DIGEST: {args.plan}" - out.append(header) - out.append( - f"SQL Server build {root.get('Build', '?')}, showplan schema {root.get('Version', '?')}" - ) - out.append("") - - # Only statements that carry a plan. SET NOCOUNT ON and friends have none. - stmts = [el for el in root.iter() if tag(el) == "StmtSimple" and el.find(NS + "QueryPlan") is not None] - if not stmts: - print(f"error: {args.plan} contains no statements with a query plan", file=sys.stderr) - return 1 - if args.sql is not None: - lines = [] - for stmt in stmts: - sid = stmt.get("StatementId", "?") - if args.sql != "*" and sid != args.sql: - continue - lines.append(f"-- StatementId {sid} [{stmt.get('StatementType', '?')}]") - lines.append(statement_text(stmt)) - lines.append("") - if not lines: - print(f"error: no statement with StatementId {args.sql}", file=sys.stderr) - return 1 - print("\n".join(lines)) - return 0 - - if args.node is not None: - detail = [] - for stmt in stmts: - root_el = stmt.find(NS + "QueryPlan").find(NS + "RelOp") - if root_el is None: - continue - sid = stmt.get("StatementId", "?") - for n in flatten(Node(root_el)): - if n.node_id != args.node: - continue - # NodeIds are unique per statement, not per plan. Say which one. - detail.append(f"### StatementId {sid}: {statement_text(stmt)[:110]}") - describe_node(n, detail) - detail.append("") - if not detail: - print(f"error: no operator with NodeId {args.node} in {args.plan}", file=sys.stderr) - return 1 - print("\n".join(detail)) - return 0 - - if len(stmts) > 1: - out.append(f"{len(stmts)} statements carry a plan. Each is analyzed separately below.") - out.append("") - - for stmt in stmts: - describe_statement(stmt, out, args.top) - - print("\n".join(out)) - return 0 - - -if __name__ == "__main__": - sys.exit(main()) From 0b689880ebc5c72ed7685596da438d38f1beea2b Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Fri, 10 Jul 2026 00:35:30 -0400 Subject: [PATCH 3/6] Fix operator self-time: exclude coordinator thread, look through batch subtrees Two bugs in self-time attribution, both of which inflate an operator until it is reported as the hottest in its plan. Found while building a portable query-plan skill that mirrored this code, and confirmed against the fixture set. 1. THREAD 0 IS THE COORDINATOR. In a parallel plan thread 0 carries no rows, and its ActualElapsedms is the wall clock of the whole parallel branch. GetPerThreadOwnElapsed iterated every thread including it, so any operator near the top of a parallel branch was handed the branch's entire duration as its own work, and its self CPU underflowed to zero because the coordinator burns none. ShowPlanParser also took the node-level elapsed as the max across all threads, including the coordinator. Measured across the .internal/examples corpus: of 1,014 non-exchange parallel operators, the coordinator reports rows in 0 cases and elapsed in 65. Those 65 are precisely the operators that win a ranking by self time. Serial plans have a single thread numbered 0, which IS a worker, so thread 0 is only excluded when other threads exist. 2. THE PARALLEL PATH DID NOT LOOK THROUGH BATCH SUBTREES OR PASS-THROUGHS. GetSerialOwnElapsed subtracts GetEffectiveChildElapsedMs, which looks through Compute Scalar pass-throughs and sums contiguous batch zones. GetPerThreadOwnElapsed subtracted each child's raw per-thread value instead, handling only Parallelism children. So: - a batch-mode child reports STANDALONE time, so only its topmost value came off and the rest of the zone stayed inside the parent; - a pass-through child carries no runtime stats, so zero came off and the parent absorbed the entire subtree beneath it. On cross-apply-point-in-time-slow.sqlplan a row-mode Nested Loops above a batch Compute Scalar (0ms) hiding a batch Hash Aggregate (45,683ms) reported 45,737ms of self time and led the ranking. Its real self time is 1ms, and the aggregate's time was double-counted into both rows. The same helpers now serve both paths, for elapsed and CPU. NodeTimeAttribution (the display path) gets the matching batch-subtree summation so the graphical plan and the analyzer agree. TESTS New OperatorSelfTimeTests, with a small synthetic fixture that encodes both traps in one shape. Three of the six fail against the unfixed code, including ParallelPassThroughChildDoesNotInflateItsParent, which uses the EXISTING join_or_clause_plan fixture -- this was live on real plans. PlanViewer.Core.csproj now grants InternalsVisibleTo the test project; PlanAnalyzer.Timing is internal but is the source of every operator timing the UI and BenefitScorer report, and it was untested. Warning baseline: one line changes. join_or_clause_plan's Sort drops from 19,602ms to 18,580ms of self time -- the Compute Scalar subtree it had absorbed. The warning still fires; the number is now correct. No warnings appear or disappear on any other plan. Co-Authored-By: Claude Opus 4.8 (1M context) --- src/PlanViewer.Core/PlanViewer.Core.csproj | 6 + .../Services/NodeTimeAttribution.cs | 28 ++++ .../Services/PlanAnalyzer.Timing.cs | 152 ++++++++++++------ .../Services/ShowPlanParser.RelOp.cs | 17 +- .../OperatorSelfTimeTests.cs | 134 +++++++++++++++ .../parallel_row_over_batch_plan.sqlplan | 85 ++++++++++ .../PlanViewer.Core.Tests/WarningBaseline.txt | 6 +- 7 files changed, 377 insertions(+), 51 deletions(-) create mode 100644 tests/PlanViewer.Core.Tests/OperatorSelfTimeTests.cs create mode 100644 tests/PlanViewer.Core.Tests/Plans/parallel_row_over_batch_plan.sqlplan diff --git a/src/PlanViewer.Core/PlanViewer.Core.csproj b/src/PlanViewer.Core/PlanViewer.Core.csproj index b0dc1c1..e4f0a76 100644 --- a/src/PlanViewer.Core/PlanViewer.Core.csproj +++ b/src/PlanViewer.Core/PlanViewer.Core.csproj @@ -19,4 +19,10 @@ + + + + + diff --git a/src/PlanViewer.Core/Services/NodeTimeAttribution.cs b/src/PlanViewer.Core/Services/NodeTimeAttribution.cs index 5e30d1c..67f2821 100644 --- a/src/PlanViewer.Core/Services/NodeTimeAttribution.cs +++ b/src/PlanViewer.Core/Services/NodeTimeAttribution.cs @@ -100,6 +100,13 @@ private static long GetChildElapsedMsSum(PlanNode node) .DefaultIfEmpty(0) .Max(); } + else if ((child.ActualExecutionMode ?? child.ExecutionMode) == "Batch") + { + // Batch operators report STANDALONE times, so the zone's times add + // rather than nest. Taking only this child's value would leave the + // rest of the zone inside the parent's "own" time. + sum += SumBatchSubtreeElapsedMs(child); + } else if (child.ActualElapsedMs > 0) { sum += child.ActualElapsedMs; @@ -111,4 +118,25 @@ private static long GetChildElapsedMsSum(PlanNode node) } return sum; } + + /// + /// Sums elapsed across a contiguous batch-mode zone, stopping at exchange + /// boundaries. Mirrors the analysis path in PlanAnalyzer.Timing. + /// + private static long SumBatchSubtreeElapsedMs(PlanNode node) + { + long sum = node.ActualElapsedMs; + foreach (var child in node.Children) + { + if (child.PhysicalOp == "Parallelism") continue; // zone boundary + + if ((child.ActualExecutionMode ?? child.ExecutionMode) == "Batch") + sum += SumBatchSubtreeElapsedMs(child); + else if (child.ActualElapsedMs > 0) + sum += child.ActualElapsedMs; // row mode: already cumulative + else + sum += GetChildElapsedMsSum(child); // pass-through, no stats + } + return sum; + } } diff --git a/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs b/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs index 7d4aaa3..386d188 100644 --- a/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs +++ b/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs @@ -64,36 +64,41 @@ internal static long GetOperatorOwnElapsedMs(PlanNode node) return GetSerialOwnElapsed(node); } + /// + /// Threads that actually did work. In a parallel plan thread 0 is the + /// coordinator: it carries no rows, and its ActualElapsedms is the wall clock + /// of the whole parallel branch. Including it in a per-thread self-time + /// calculation hands the operator the branch's entire duration. + /// A serial plan has a single thread numbered 0, which IS a worker, so only + /// exclude thread 0 when other threads exist. + /// + private static List WorkThreads(PlanNode node) + { + var workers = node.PerThreadStats.Where(t => t.ThreadId > 0).ToList(); + return workers.Count > 0 ? workers : node.PerThreadStats; + } + /// /// Per-thread self-time calculation for parallel row mode operators. - /// For each thread: self = parent_elapsed[t] - sum(children_elapsed[t]). - /// Returns max across threads. + /// For each worker thread: self = parent[t] - sum(effective children[t]). + /// Returns max across worker threads. /// - private static long GetPerThreadOwnElapsed(PlanNode node) + private static long GetPerThreadOwnElapsed(PlanNode node) => + GetPerThreadOwn(node, t => t.ActualElapsedMs, n => n.ActualElapsedMs); + + private static long GetPerThreadOwn( + PlanNode node, + Func pick, + Func nodeTotal) { - // Build lookup: threadId -> parent elapsed for this node var parentByThread = new Dictionary(); - foreach (var ts in node.PerThreadStats) - parentByThread[ts.ThreadId] = ts.ActualElapsedMs; + foreach (var ts in WorkThreads(node)) + parentByThread[ts.ThreadId] = pick(ts); - // Build lookup: threadId -> sum of all direct children's elapsed var childSumByThread = new Dictionary(); foreach (var child in node.Children) - { - var childNode = child; + AddEffectiveChildByThread(child, pick, nodeTotal, childSumByThread); - // Exchange operators have unreliable times — look through to their child - if (child.PhysicalOp == "Parallelism" && child.Children.Count > 0) - childNode = child.Children.OrderByDescending(c => c.ActualElapsedMs).First(); - - foreach (var ts in childNode.PerThreadStats) - { - childSumByThread.TryGetValue(ts.ThreadId, out var existing); - childSumByThread[ts.ThreadId] = existing + ts.ActualElapsedMs; - } - } - - // Self-time per thread = parent - children, take max across threads var maxSelf = 0L; foreach (var (threadId, parentMs) in parentByThread) { @@ -105,6 +110,83 @@ private static long GetPerThreadOwnElapsed(PlanNode node) return maxSelf; } + /// + /// What a child contributes to its parent's per-thread total. The per-thread + /// mirror of GetEffectiveChildElapsedMs, and it must look through the same two + /// things the serial path does, or the parent absorbs the subtree beneath them: + /// + /// - A batch-mode child reports STANDALONE time, so only its own value would + /// come off and the rest of the batch zone would stay in the parent. + /// - A pass-through child (Compute Scalar) carries no runtime stats at all, + /// so zero would come off. + /// + /// Together these crowned a row-mode Nested Loops above a batch Hash Aggregate + /// as the hottest operator in its plan, with the aggregate's time counted twice. + /// + private static void AddEffectiveChildByThread( + PlanNode child, + Func pick, + Func nodeTotal, + Dictionary acc) + { + // Exchange operators have unreliable times — look through to their child. + if (child.PhysicalOp == "Parallelism" && child.Children.Count > 0) + { + var dominant = child.Children.OrderByDescending(nodeTotal).First(); + AddEffectiveChildByThread(dominant, pick, nodeTotal, acc); + return; + } + + var mode = child.ActualExecutionMode ?? child.ExecutionMode; + if (mode == "Batch" && child.HasActualStats) + { + AddBatchSubtreeByThread(child, pick, nodeTotal, acc); + return; + } + + if (child.HasActualStats && nodeTotal(child) > 0) + { + foreach (var ts in WorkThreads(child)) + { + acc.TryGetValue(ts.ThreadId, out var existing); + acc[ts.ThreadId] = existing + pick(ts); + } + return; + } + + // No runtime stats: look through to the descendants that have them. + foreach (var grandchild in child.Children) + AddEffectiveChildByThread(grandchild, pick, nodeTotal, acc); + } + + /// + /// Per-thread sum across a contiguous batch-mode zone, stopping at exchanges. + /// Batch operators pipeline, so their times add rather than nest. + /// + private static void AddBatchSubtreeByThread( + PlanNode node, + Func pick, + Func nodeTotal, + Dictionary acc) + { + foreach (var ts in WorkThreads(node)) + { + acc.TryGetValue(ts.ThreadId, out var existing); + acc[ts.ThreadId] = existing + pick(ts); + } + + foreach (var child in node.Children) + { + if (child.PhysicalOp == "Parallelism") continue; // zone boundary + + var childMode = child.ActualExecutionMode ?? child.ExecutionMode; + if (childMode == "Batch" && child.HasActualStats) + AddBatchSubtreeByThread(child, pick, nodeTotal, acc); + else + AddEffectiveChildByThread(child, pick, nodeTotal, acc); + } + } + /// /// Max per-thread self-CPU for this operator. /// Parallel: for each thread, self_cpu = thread_cpu - Σ same-thread child cpu; take max. @@ -116,33 +198,7 @@ internal static long GetOperatorMaxThreadOwnCpuMs(PlanNode node) if (!node.HasActualStats || node.ActualCPUMs <= 0) return 0; if (node.PerThreadStats.Count > 1) - { - var parentByThread = new Dictionary(); - foreach (var ts in node.PerThreadStats) - parentByThread[ts.ThreadId] = ts.ActualCPUMs; - - var childSumByThread = new Dictionary(); - foreach (var child in node.Children) - { - var childNode = child; - if (child.PhysicalOp == "Parallelism" && child.Children.Count > 0) - childNode = child.Children.OrderByDescending(c => c.ActualCPUMs).First(); - foreach (var ts in childNode.PerThreadStats) - { - childSumByThread.TryGetValue(ts.ThreadId, out var existing); - childSumByThread[ts.ThreadId] = existing + ts.ActualCPUMs; - } - } - - var maxSelf = 0L; - foreach (var (threadId, parentCpu) in parentByThread) - { - childSumByThread.TryGetValue(threadId, out var childCpu); - var self = Math.Max(0, parentCpu - childCpu); - if (self > maxSelf) maxSelf = self; - } - return maxSelf; - } + return GetPerThreadOwn(node, t => t.ActualCPUMs, n => n.ActualCPUMs); // Serial: operator_cpu - Σ effective child cpu var totalChildCpu = 0L; diff --git a/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs b/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs index 0842010..e47bf19 100644 --- a/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs +++ b/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs @@ -675,7 +675,13 @@ private static void ParseRuntimeInformation(PlanNode node, XElement relOpEl) node.HasActualStats = true; long totalRows = 0, totalExecutions = 0, totalRowsRead = 0; long totalRebinds = 0, totalRewinds = 0; - long maxElapsed = 0, totalCpu = 0; + // Elapsed takes the max across threads, but thread 0 is the coordinator + // in a parallel plan: no rows, and an elapsed equal to the whole parallel + // branch's wall clock. Taking the max over it makes every operator in the + // branch look like it took the branch's entire duration. A serial plan has + // one thread numbered 0, which is a worker, so fall back to it. + long maxElapsed = 0, maxWorkerElapsed = 0, totalCpu = 0; + var sawWorkerThread = false; long totalLogicalReads = 0, totalPhysicalReads = 0; long totalScans = 0, totalReadAheads = 0; long totalLobLogicalReads = 0, totalLobPhysicalReads = 0, totalLobReadAheads = 0; @@ -721,6 +727,13 @@ private static void ParseRuntimeInformation(PlanNode node, XElement relOpEl) var elapsed = ParseLong(thread.Attribute("ActualElapsedms")?.Value); if (elapsed > maxElapsed) maxElapsed = elapsed; + + var threadId = (int)ParseDouble(thread.Attribute("Thread")?.Value); + if (threadId > 0) + { + sawWorkerThread = true; + if (elapsed > maxWorkerElapsed) maxWorkerElapsed = elapsed; + } } node.ActualRows = totalRows; @@ -728,7 +741,7 @@ private static void ParseRuntimeInformation(PlanNode node, XElement relOpEl) node.ActualRowsRead = totalRowsRead; node.ActualRebinds = totalRebinds; node.ActualRewinds = totalRewinds; - node.ActualElapsedMs = maxElapsed; + node.ActualElapsedMs = sawWorkerThread ? maxWorkerElapsed : maxElapsed; node.ActualCPUMs = totalCpu; node.ActualLogicalReads = totalLogicalReads; node.ActualPhysicalReads = totalPhysicalReads; diff --git a/tests/PlanViewer.Core.Tests/OperatorSelfTimeTests.cs b/tests/PlanViewer.Core.Tests/OperatorSelfTimeTests.cs new file mode 100644 index 0000000..2fd184e --- /dev/null +++ b/tests/PlanViewer.Core.Tests/OperatorSelfTimeTests.cs @@ -0,0 +1,134 @@ +using System.Linq; +using PlanViewer.Core.Models; +using PlanViewer.Core.Services; + +namespace PlanViewer.Core.Tests; + +/// +/// Self-time attribution for parallel operators. +/// +/// Two traps, both of which inflated a parent operator until it was reported as +/// the hottest in its plan: +/// +/// 1. Thread 0 is the coordinator. It carries no rows, and its ActualElapsedms +/// is the wall clock of the whole parallel branch. +/// 2. A row-mode parent above a batch-mode subtree, or above a pass-through +/// operator with no runtime stats, subtracted too little from itself. +/// +public class OperatorSelfTimeTests +{ + private static PlanNode? TryFindNode(PlanNode root, int nodeId) + { + if (root.NodeId == nodeId) return root; + foreach (var child in root.Children) + { + var found = TryFindNode(child, nodeId); + if (found is not null) return found; + } + return null; + } + + /// + /// The statement's RootNode is a synthetic wrapper (NodeId -1). The plan's + /// real root operator is its first child. + /// + private static PlanNode RootOf(string planFile) + { + var plan = PlanTestHelper.LoadAndAnalyze(planFile); + var wrapper = plan.Batches[0].Statements[0].RootNode!; + return wrapper.NodeId < 0 ? wrapper.Children[0] : wrapper; + } + + [Fact] + public void CoordinatorThreadIsNotCountedAsOperatorElapsedTime() + { + var root = RootOf("parallel_row_over_batch_plan.sqlplan"); + + // Thread 0 reports 1000ms (the branch's wall clock) with zero rows. The + // slowest worker also reports 1000ms here, so the node-level number is the + // same -- what matters is that we source it from a worker, not the + // coordinator, and that the coordinator never wins a max on its own. + var coordinator = root.PerThreadStats.Single(t => t.ThreadId == 0); + Assert.Equal(0, coordinator.ActualRows); + Assert.Equal(1000, coordinator.ActualElapsedMs); + + // The Columnstore scan's coordinator row is 0ms while its workers are 0ms + // too, but the Hash Match's coordinator is 0ms and workers are 900/890. + var hashMatch = TryFindNode(root, 2)!; + Assert.Equal(900, hashMatch.ActualElapsedMs); // max over WORKERS, not thread 0 + } + + [Fact] + public void RowModeParentAboveBatchSubtreeDoesNotAbsorbIt() + { + var root = RootOf("parallel_row_over_batch_plan.sqlplan"); + + // Node 0 is a parallel row-mode Nested Loops. Slowest worker: 1000ms. + // Beneath it: a batch Compute Scalar (0ms) hiding a batch Hash Match + // (900ms), plus a row-mode Index Seek (50ms). + // + // Correct self time = 1000 - (0 + 900) - 50 = 50ms. + // Before the fix this reported 1000ms: the pass-through contributed + // nothing, the batch zone contributed only its topmost value, and the + // coordinator's 1000ms won the per-thread max outright. + var own = PlanAnalyzer.GetOperatorOwnElapsedMs(root); + Assert.InRange(own, 40, 60); + } + + [Fact] + public void RowModeParentAboveBatchSubtreeDoesNotAbsorbItsCpu() + { + var root = RootOf("parallel_row_over_batch_plan.sqlplan"); + + // Busiest worker CPU on node 0 is 30ms. Beneath it, per that same thread: + // batch zone 0 + 12 = 12ms, row seek 6ms. Self CPU = 30 - 18 = 12ms. + var ownCpu = PlanAnalyzer.GetOperatorMaxThreadOwnCpuMs(root); + Assert.InRange(ownCpu, 8, 16); + } + + [Fact] + public void BatchOperatorKeepsItsStandaloneTime() + { + var root = RootOf("parallel_row_over_batch_plan.sqlplan"); + var hashMatch = TryFindNode(root, 2)!; + + // Batch mode reports self time directly. Subtracting children would + // underflow it. + Assert.Equal(900, PlanAnalyzer.GetOperatorOwnElapsedMs(hashMatch)); + } + + [Fact] + public void ParallelPassThroughChildDoesNotInflateItsParent() + { + // join_or_clause_plan has a parallel row-mode TopN Sort above a Compute + // Scalar that carries no runtime statistics. Subtracting zero for it made + // the sort absorb everything below. + var root = RootOf("join_or_clause_plan.sqlplan"); + var sort = TryFindNode(root, 8); + Assert.NotNull(sort); + + var own = PlanAnalyzer.GetOperatorOwnElapsedMs(sort!); + var cumulative = sort!.ActualElapsedMs; + + // Self time must be strictly less than cumulative: the subtree below it + // did real work, and that work is not the sort's own. + Assert.True( + own < cumulative, + $"sort reported {own}ms self of {cumulative}ms cumulative -- it absorbed its subtree"); + } + + [Fact] + public void SerialPlanStillUsesItsOnlyThread() + { + // A serial plan has a single thread numbered 0. It is a worker, not a + // coordinator, and excluding it would zero out every operator. + var root = RootOf("key_lookup_plan.sqlplan"); + var withStats = TryFindNode(root, 0); + Assert.NotNull(withStats); + if (withStats!.HasActualStats && withStats.PerThreadStats.Count == 1) + { + Assert.Equal(0, withStats.PerThreadStats[0].ThreadId); + Assert.True(withStats.ActualElapsedMs >= 0); + } + } +} diff --git a/tests/PlanViewer.Core.Tests/Plans/parallel_row_over_batch_plan.sqlplan b/tests/PlanViewer.Core.Tests/Plans/parallel_row_over_batch_plan.sqlplan new file mode 100644 index 0000000..ff47cd9 --- /dev/null +++ b/tests/PlanViewer.Core.Tests/Plans/parallel_row_over_batch_plan.sqlplan @@ -0,0 +1,85 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/tests/PlanViewer.Core.Tests/WarningBaseline.txt b/tests/PlanViewer.Core.Tests/WarningBaseline.txt index 5640f74..322cf24 100644 --- a/tests/PlanViewer.Core.Tests/WarningBaseline.txt +++ b/tests/PlanViewer.Core.Tests/WarningBaseline.txt @@ -93,7 +93,7 @@ Filter Operator | Warning | Filter operator discarding rows late in the plan.\n Nested Loops High Executions | Critical | Nested Loops inner side executed 17,091,572 times (DOP 8). Inner side total: 93,279,732 logical reads. Inner side time: 30,655ms (93% of statement). Consider whether a hash or merge join would be more appropriate for this row count. Scan With Predicate | Warning | Scan with residual predicate — SQL Server is reading every row and filtering after the fact. Check that you have appropriate indexes.\nPredicate: [StackOverflow2013].[dbo].[Posts].[PostTypeId] as [p].[PostTypeId]=(1) OR [StackOverflow2013].[dbo].[Posts].[PostTypeId] as [p].[PostTypeId]=(2) Nested Loops High Executions | Critical | Nested Loops inner side executed 30,700,008 times (DOP 8). Inner side total: 93,279,732 logical reads. Inner side time: 14,355ms (43% of statement). Consider whether a hash or merge join would be more appropriate for this row count. -Expensive Operator | Critical | Sort took 19,602ms (59.3% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be? +Expensive Operator | Critical | Sort took 18,580ms (56.2% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be? Join OR Clause | Warning | OR in a join predicate. SQL Server rewrote the OR as 2 separate lookups, each evaluated independently — this multiplies the work on the inner side. Rewrite as separate queries joined with UNION ALL. For example, change "FROM a JOIN b ON a.x = b.x OR a.y = b.y" to "FROM a JOIN b ON a.x = b.x UNION ALL FROM a JOIN b ON a.y = b.y". Expensive Operator | Warning | Clustered Index Seek took 14,355ms (43.4% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be? @@ -210,6 +210,10 @@ Row Estimate Mismatch | Critical | Estimated 5,292,870 vs Actual 53,946 (13,486 Parallel Skew | Warning | Thread 3 processed 100% of rows (53,946/53,946). Work is heavily skewed to one thread, so parallelism isn't helping much. Common causes: uneven data distribution across partitions or hash buckets, or a scan/seek whose predicate sends most rows to one range. Reducing DOP or rewriting the query to avoid the skewed operation may help. Bare Scan | Warning | Clustered index scan reads the full table with no predicate, outputting 1 column(s): Votes.PostId. Consider a nonclustered index on the output columns (as key or INCLUDE) so SQL Server can read a narrower structure. For analytical workloads, a columnstore index may be a better fit. +### parallel_row_over_batch_plan.sqlplan +Standard Edition DOP Limitation | Info | DOP is limited to 2 and the plan uses batch mode operators. This may be caused by the SQL Server Standard Edition limitation, which caps parallelism at 2 when batch mode is in use. If this server runs Standard Edition, Developer or Enterprise Edition would allow higher DOP. +Expensive Operator | Critical | Hash Match took 900ms (90.0% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be? + ### param-sniffing-posttypeid2.sqlplan Wait: RESERVED_MEMORY_ALLOCATION_EXT | Info | RESERVED_MEMORY_ALLOCATION_EXT Observed 1,051 ms across 2,052,049 waits. Wait: SOS_SCHEDULER_YIELD | Info | SOS_SCHEDULER_YIELD Observed 6 ms across 4,481 waits. From efff98c7339eb3037f538916c1a408c41f43b580 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 16 Jul 2026 18:28:53 -0400 Subject: [PATCH 4/6] Add Query Store query-text search filter (#389) - QueryStoreFilter.QueryTextSearch + shared BuildQueryTextSearchPattern helper (sp_QuickieStore default semantics: trim, auto-wrap %, wildcards stay live) - Parameterized EXISTS predicate applied pre-TOP-N in all three Query Store SQL builders (flat, grouped-by-hash, grouped-by-module) - Desktop: Query Text option in the Search-by combo - MCP: additive query_text_search param on get_query_store_top - CLI: additive --query-text-search option - Tests: helper pattern matrix + ParseExecutionType backfill (22 new cases) Co-Authored-By: Claude Fable 5 --- .../Controls/QueryStoreGridControl.Filters.cs | 3 + .../Controls/QueryStoreGridControl.axaml | 1 + src/PlanViewer.App/Mcp/McpQueryStoreTools.cs | 6 +- .../Commands/QueryStoreCommand.cs | 11 +++- src/PlanViewer.Core/Models/QueryStorePlan.cs | 18 +++++ .../Services/QueryStoreService.Grouped.cs | 24 +++++++ .../Services/QueryStoreService.cs | 13 ++++ .../QueryTextSearchPatternTests.cs | 65 +++++++++++++++++++ 8 files changed, 137 insertions(+), 4 deletions(-) create mode 100644 tests/PlanViewer.Core.Tests/QueryTextSearchPatternTests.cs diff --git a/src/PlanViewer.App/Controls/QueryStoreGridControl.Filters.cs b/src/PlanViewer.App/Controls/QueryStoreGridControl.Filters.cs index 0275553..6cdec19 100644 --- a/src/PlanViewer.App/Controls/QueryStoreGridControl.Filters.cs +++ b/src/PlanViewer.App/Controls/QueryStoreGridControl.Filters.cs @@ -84,6 +84,9 @@ private void SearchType_SelectionChanged(object? sender, SelectionChangedEventAr // Default to dbo schema if no schema specified, following sp_QuickieStore pattern filter.ModuleName = searchValue.Contains('.') ? searchValue : $"dbo.{searchValue}"; break; + case "query-text": + filter.QueryTextSearch = searchValue; + break; default: return null; } diff --git a/src/PlanViewer.App/Controls/QueryStoreGridControl.axaml b/src/PlanViewer.App/Controls/QueryStoreGridControl.axaml index b33aa0c..5fe534b 100644 --- a/src/PlanViewer.App/Controls/QueryStoreGridControl.axaml +++ b/src/PlanViewer.App/Controls/QueryStoreGridControl.axaml @@ -86,6 +86,7 @@ + diff --git a/src/PlanViewer.App/Mcp/McpQueryStoreTools.cs b/src/PlanViewer.App/Mcp/McpQueryStoreTools.cs index 015b839..28d4f46 100644 --- a/src/PlanViewer.App/Mcp/McpQueryStoreTools.cs +++ b/src/PlanViewer.App/Mcp/McpQueryStoreTools.cs @@ -55,7 +55,7 @@ public static async Task CheckQueryStore( "Each fetched plan is automatically loaded into the application for further analysis " + "with analyze_plan, get_plan_warnings, etc. Returns summary stats and session IDs. " + "Optional filters narrow results server-side by query_id, plan_id, query_hash, " + - "plan_hash, or module name (schema.name, supports % wildcards).")] + "plan_hash, module name (schema.name, supports % wildcards), or query text (query_text_search).")] public static async Task GetQueryStoreTop( PlanSessionManager sessionManager, ConnectionStore connectionStore, @@ -72,6 +72,7 @@ public static async Task GetQueryStoreTop( [Description("Filter by query hash (hex, e.g. 0x1AB2C3D4).")] string? query_hash = null, [Description("Filter by query plan hash (hex, e.g. 0x1AB2C3D4).")] string? plan_hash = null, [Description("Filter by module name (schema.name, supports % wildcards).")] string? module = null, + [Description("Filter to queries whose SQL text contains this string. Matched with SQL LIKE (auto-wrapped in %); % _ [ ] act as wildcards.")] string? query_text_search = null, [Description("Filter by execution type: regular, aborted, exception, or failed (= aborted + exception).")] string? execution_type = null) { try @@ -98,7 +99,7 @@ public static async Task GetQueryStoreTop( QueryStoreFilter? filter = null; if (query_id != null || plan_id != null || - query_hash != null || plan_hash != null || module != null || + query_hash != null || plan_hash != null || module != null || query_text_search != null || executionTypes != null) { filter = new QueryStoreFilter @@ -108,6 +109,7 @@ public static async Task GetQueryStoreTop( QueryHash = query_hash, QueryPlanHash = plan_hash, ModuleName = module, + QueryTextSearch = query_text_search, ExecutionTypeDescs = executionTypes, }; } diff --git a/src/PlanViewer.Cli/Commands/QueryStoreCommand.cs b/src/PlanViewer.Cli/Commands/QueryStoreCommand.cs index da6aed5..3371112 100644 --- a/src/PlanViewer.Cli/Commands/QueryStoreCommand.cs +++ b/src/PlanViewer.Cli/Commands/QueryStoreCommand.cs @@ -129,6 +129,11 @@ public static Command Create(ICredentialService? credentialService = null) Description = "Filter by module name (schema.name, supports % wildcards)" }; + var queryTextSearchOption = new Option("--query-text-search") + { + Description = "Filter to queries whose text contains this string (SQL LIKE match, auto-wrapped in %; % _ [ ] are wildcards)" + }; + var executionTypeOption = new Option("--execution-type") { Description = "Filter by execution type: regular, aborted, exception, or failed (= aborted + exception)" @@ -140,7 +145,7 @@ public static Command Create(ICredentialService? credentialService = null) outputDirOption, outputOption, compactOption, warningsOnlyOption, configOption, authOption, trustCertOption, loginOption, passwordOption, passwordStdinOption, queryIdOption, planIdOption, queryHashOption, planHashOption, moduleOption, - executionTypeOption + queryTextSearchOption, executionTypeOption }; cmd.SetAction(async (parseResult, ct) => @@ -165,6 +170,7 @@ public static Command Create(ICredentialService? credentialService = null) var filterQueryHash = parseResult.GetValue(queryHashOption); var filterPlanHash = parseResult.GetValue(planHashOption); var filterModule = parseResult.GetValue(moduleOption); + var filterQueryTextSearch = parseResult.GetValue(queryTextSearchOption); var filterExecutionType = parseResult.GetValue(executionTypeOption); // Load .env file if present (CLI args take precedence) @@ -211,7 +217,7 @@ public static Command Create(ICredentialService? credentialService = null) QueryStoreFilter? filter = null; if (filterQueryId != null || filterPlanId != null || - filterQueryHash != null || filterPlanHash != null || filterModule != null || + filterQueryHash != null || filterPlanHash != null || filterModule != null || filterQueryTextSearch != null || executionTypes != null) { filter = new QueryStoreFilter @@ -221,6 +227,7 @@ public static Command Create(ICredentialService? credentialService = null) QueryHash = filterQueryHash, QueryPlanHash = filterPlanHash, ModuleName = filterModule, + QueryTextSearch = filterQueryTextSearch, ExecutionTypeDescs = executionTypes, }; } diff --git a/src/PlanViewer.Core/Models/QueryStorePlan.cs b/src/PlanViewer.Core/Models/QueryStorePlan.cs index 60df844..f7d759a 100644 --- a/src/PlanViewer.Core/Models/QueryStorePlan.cs +++ b/src/PlanViewer.Core/Models/QueryStorePlan.cs @@ -19,6 +19,8 @@ public class QueryStoreFilter /// public string[]? ExecutionTypeDescs { get; set; } + public string? QueryTextSearch { get; set; } + /// /// Parses a user-friendly execution-type string into the matching SQL execution_type_desc values. /// Accepts (case-insensitive): regular, aborted, exception, failed (= aborted + exception), any. @@ -38,6 +40,22 @@ public class QueryStoreFilter $"Unknown execution type '{input}'. Valid values: regular, aborted, exception, failed, any."), }; } + + /// + /// Builds the LIKE pattern for a query-text search, mirroring sp_QuickieStore's + /// @query_text_search default behavior: trims, then wraps the term in leading/ + /// trailing % wildcards when not already present. %, _, [, ] remain LIKE + /// wildcards (sp_QuickieStore's default @escape_brackets = 0). Returns null for + /// null/whitespace input (no filter), matching ParseExecutionType's contract. + /// + public static string? BuildQueryTextSearchPattern(string? input) + { + if (string.IsNullOrWhiteSpace(input)) return null; + var s = input.Trim(); + if (!s.StartsWith('%')) s = "%" + s; + if (!s.EndsWith('%')) s += "%"; + return s; + } } public class QueryStorePlan diff --git a/src/PlanViewer.Core/Services/QueryStoreService.Grouped.cs b/src/PlanViewer.Core/Services/QueryStoreService.Grouped.cs index 251b297..abb18ff 100644 --- a/src/PlanViewer.Core/Services/QueryStoreService.Grouped.cs +++ b/src/PlanViewer.Core/Services/QueryStoreService.Grouped.cs @@ -60,6 +60,18 @@ public static async Task FetchGroupedByQueryHashAsync( filterClauses.Add("AND OBJECT_SCHEMA_NAME(q.object_id) + N'.' + OBJECT_NAME(q.object_id) = @filterModule"); parameters.Add(new SqlParameter("@filterModule", moduleVal)); } + var queryTextPattern = QueryStoreFilter.BuildQueryTextSearchPattern(filter?.QueryTextSearch); + if (queryTextPattern != null) + { + filterClauses.Add(@"AND EXISTS ( + SELECT 1 + FROM sys.query_store_query AS qsq + JOIN sys.query_store_query_text AS qsqt + ON qsqt.query_text_id = qsq.query_text_id + WHERE qsq.query_id = p.query_id + AND qsqt.query_sql_text LIKE @filterQueryText)"); + parameters.Add(new SqlParameter("@filterQueryText", queryTextPattern)); + } var filterSql = filterClauses.Count > 0 ? "\n" + string.Join("\n", filterClauses) : ""; var phase2ExecutionTypeClause = ""; if (filter?.ExecutionTypeDescs?.Length > 0) @@ -340,6 +352,18 @@ public static async Task FetchGroupedByModuleAsync( filterClauses.Add("AND q.query_hash = CONVERT(binary(8), @filterQueryHash, 1)"); parameters.Add(new SqlParameter("@filterQueryHash", filter.QueryHash.Trim())); } + var queryTextPattern = QueryStoreFilter.BuildQueryTextSearchPattern(filter?.QueryTextSearch); + if (queryTextPattern != null) + { + filterClauses.Add(@"AND EXISTS ( + SELECT 1 + FROM sys.query_store_query AS qsq + JOIN sys.query_store_query_text AS qsqt + ON qsqt.query_text_id = qsq.query_text_id + WHERE qsq.query_id = p.query_id + AND qsqt.query_sql_text LIKE @filterQueryText)"); + parameters.Add(new SqlParameter("@filterQueryText", queryTextPattern)); + } var filterSql = filterClauses.Count > 0 ? "\n" + string.Join("\n", filterClauses) : ""; var phase2ExecutionTypeClause = ""; if (filter?.ExecutionTypeDescs?.Length > 0) diff --git a/src/PlanViewer.Core/Services/QueryStoreService.cs b/src/PlanViewer.Core/Services/QueryStoreService.cs index cc00de1..70eb3c3 100644 --- a/src/PlanViewer.Core/Services/QueryStoreService.cs +++ b/src/PlanViewer.Core/Services/QueryStoreService.cs @@ -163,6 +163,19 @@ public static async Task> FetchTopPlansAsync( needsQueryJoin = true; } + var queryTextPattern = QueryStoreFilter.BuildQueryTextSearchPattern(filter?.QueryTextSearch); + if (queryTextPattern != null) + { + filterClauses.Add(@"AND EXISTS ( + SELECT 1 + FROM sys.query_store_query AS qsq + JOIN sys.query_store_query_text AS qsqt + ON qsqt.query_text_id = qsq.query_text_id + WHERE qsq.query_id = p.query_id + AND qsqt.query_sql_text LIKE @filterQueryText)"); + parameters.Add(new SqlParameter("@filterQueryText", queryTextPattern)); + } + var rnClause = filter?.PlanId != null ? "" : "AND r.rn = 1"; var filterSql = filterClauses.Count > 0 ? "\n " + string.Join("\n ", filterClauses) diff --git a/tests/PlanViewer.Core.Tests/QueryTextSearchPatternTests.cs b/tests/PlanViewer.Core.Tests/QueryTextSearchPatternTests.cs new file mode 100644 index 0000000..876f964 --- /dev/null +++ b/tests/PlanViewer.Core.Tests/QueryTextSearchPatternTests.cs @@ -0,0 +1,65 @@ +using PlanViewer.Core.Models; + +namespace PlanViewer.Core.Tests; + +// Locks in the two static helpers on QueryStoreFilter that back the Query Store +// query-text search filter (feature/qs-query-text-search). +// BuildQueryTextSearchPattern mirrors sp_QuickieStore's @query_text_search default: +// trim, then wrap the term in leading/trailing % when not already present. With +// sp_QuickieStore's default @escape_brackets = 0, the LIKE metacharacters %, _, [ +// and ] are left live (this is the documented phase-1 wildcard behavior). +// ParseExecutionType is a sibling helper on the same model; its mapping and error +// contract are backfilled here. +public class QueryTextSearchPatternTests +{ + [Theory] + // Bare term gets wrapped on both sides. + [InlineData("SELECT", "%SELECT%")] + // A % already on one end is kept, not doubled. + [InlineData("%SELECT", "%SELECT%")] + [InlineData("SELECT%", "%SELECT%")] + // Fully wrapped term is returned unchanged. + [InlineData("%SELECT%", "%SELECT%")] + // Interior wildcards survive; only the ends are padded. + [InlineData("a%b", "%a%b%")] + // A lone % already starts and ends with %, so it stays match-anything. + [InlineData("%", "%")] + // Surrounding whitespace is trimmed before wrapping. + [InlineData(" foo ", "%foo%")] + // Phase-1 wildcard semantics: brackets and underscore are NOT escaped. + [InlineData("[dbo]", "%[dbo]%")] + [InlineData("a_b", "%a_b%")] + // Null / empty / whitespace -> no filter. + [InlineData(null, null)] + [InlineData("", null)] + [InlineData(" ", null)] + public void BuildQueryTextSearchPattern_WrapsTermInWildcards(string? input, string? expected) + { + Assert.Equal(expected, QueryStoreFilter.BuildQueryTextSearchPattern(input)); + } + + [Theory] + // Single friendly value -> single execution_type_desc. + [InlineData("regular", new[] { "Regular" })] + [InlineData("aborted", new[] { "Aborted" })] + [InlineData("exception", new[] { "Exception" })] + // "failed" fans out to both failure descs. + [InlineData("failed", new[] { "Aborted", "Exception" })] + // "any" and null / empty / whitespace mean no filter. + [InlineData("any", null)] + [InlineData(null, null)] + [InlineData("", null)] + [InlineData(" ", null)] + // Matching is case-insensitive (Trim().ToLowerInvariant()). + [InlineData("REGULAR", new[] { "Regular" })] + public void ParseExecutionType_MapsFriendlyValues(string? input, string[]? expected) + { + Assert.Equal(expected, QueryStoreFilter.ParseExecutionType(input)); + } + + [Fact] + public void ParseExecutionType_ThrowsOnUnknownValue() + { + Assert.Throws(() => QueryStoreFilter.ParseExecutionType("garbage")); + } +} From 5913a3a5652ef9981529d30c186a838eff2746fe Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 16 Jul 2026 20:35:48 -0400 Subject: [PATCH 5/6] Add Query Store server-side filter panel, chips, and pre-filters (#391) Core: - QueryStoreFilter: MinExecutions, MinDurationMs, MinCpuMs (window-wide per-plan averages), QueryTextSearchNot, EscapeBrackets, and four include/ignore query-id/plan-id lists; strict ParseIdList (ordered dedupe, throws on garbage); BuildQueryTextSearchPattern escapeBrackets overload (escapes [ ] _ for ESCAPE '\', % stays live) - All three SQL builders (flat, grouped-by-hash, grouped-by-module) gain the new clauses pre-TOP-N, fully parameterized; rn=1 relaxed when plans are explicitly included; unset path renders byte-identical SQL - QueryStoreServerFilterState: UI-free, unit-testable filter model (typed setters, ordered chips, 1:1 BuildFilter projection) Desktop: - Collapsible Server Filters panel (thresholds, text include/exclude, escape toggle, id lists) with transactional Apply - Chip strip showing every criterion that shaped the fetch; chips are removable and re-fetch - Column-filter popups gain 'Search server' promotion on mapped columns (Executions/AvgCpu/AvgDuration/ids/hashes/text) with operator validation at click; totals deliberately not promotable - Search-by commits become chips; Clear clears all server filters; panel expanded state persisted MCP/CLI: - Nine additive get_query_store_top params and query-store options Tests: 59 new (escape-mode matrix, ParseIdList contract, filter-state model) - 182 total passing Co-Authored-By: Claude Fable 5 --- .../Controls/ColumnFilterPopup.axaml | 5 +- .../Controls/ColumnFilterPopup.axaml.cs | 24 +- .../Controls/QueryStoreGridControl.Fetch.cs | 7 +- .../Controls/QueryStoreGridControl.Filters.cs | 63 +-- .../QueryStoreGridControl.ServerFilters.cs | 230 +++++++++++ .../Controls/QueryStoreGridControl.axaml | 119 +++++- .../Controls/QueryStoreGridControl.axaml.cs | 6 + src/PlanViewer.App/Mcp/McpQueryStoreTools.cs | 35 +- .../Services/AppSettingsService.cs | 6 + .../Commands/QueryStoreCommand.cs | 79 +++- src/PlanViewer.Core/Models/QueryStorePlan.cs | 46 ++- .../Models/QueryStoreServerFilterState.cs | 259 ++++++++++++ .../Services/QueryStoreService.Grouped.cs | 142 ++++++- .../Services/QueryStoreService.cs | 75 +++- .../QueryStoreFilterStateTests.cs | 381 ++++++++++++++++++ .../QueryStoreIdListParseTests.cs | 51 +++ .../QueryTextSearchPatternTests.cs | 26 ++ 17 files changed, 1502 insertions(+), 52 deletions(-) create mode 100644 src/PlanViewer.App/Controls/QueryStoreGridControl.ServerFilters.cs create mode 100644 src/PlanViewer.Core/Models/QueryStoreServerFilterState.cs create mode 100644 tests/PlanViewer.Core.Tests/QueryStoreFilterStateTests.cs create mode 100644 tests/PlanViewer.Core.Tests/QueryStoreIdListParseTests.cs diff --git a/src/PlanViewer.App/Controls/ColumnFilterPopup.axaml b/src/PlanViewer.App/Controls/ColumnFilterPopup.axaml index 5a54155..c4f5649 100644 --- a/src/PlanViewer.App/Controls/ColumnFilterPopup.axaml +++ b/src/PlanViewer.App/Controls/ColumnFilterPopup.axaml @@ -1,7 +1,7 @@ + Width="280"> @@ -20,6 +20,9 @@ Height="28" FontSize="12" Margin="0,0,0,12" KeyDown="ValueTextBox_KeyDown"/> +