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())