From 08078e6666b95d102f5b385fc6fa607821df241f Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Sat, 22 Aug 2026 03:31:25 +0100 Subject: [PATCH] Descend into stored procedure bodies when analyzing a plan (#455) An EXEC plan analyzed as one statement, no warnings, cost 0, exit 0, on a file carrying dozens of statement plans. Reproduced against SQL Server 2025 before touching anything: six StmtSimple, four QueryPlan, summed cost 1.88, and `analyze` reported total_statements 1 and max_estimated_cost 0. The reported diagnosis was that the parse never descends into the procedure. It is subtler than that, and the distinction is the fix. ShowPlanParser has ALWAYS read StoredProc sub-plans - but that code sits below an early return taken when a statement carries no QueryPlan of its own, and an EXEC statement is precisely a statement with no plan of its own, because every plan lives in the body. The descent existed and was unreachable in the only case it was written for. The same was true of a UDF call whose calling statement carries no plan. So the sub-plan parsing moves above that early return. That alone fixes it. Two more places had the same blind spot and are now sharing one traversal, because the traversal was never the missing part - PlanOperations.ValidateComplexity has always descended, which is how the complexity limit counted statements the analysis never saw: - PlanAnalyzer walked batch.Statements, so no rule ever ran on a procedure body. - ResultMapper walked batch.Statements, which is where total_statements 1 and max_estimated_cost 0 came from. And a third, which is the one worth pausing on: PlanTestHelper.AllWarnings walked batch.Statements too. The golden master and the analyzer shared a blind spot, so the characterization test could not have caught the analyzer skipping procedure bodies no matter how many procedure plans were committed. A test that cannot see what the code cannot see is not covering it. It now uses the same traversal. What this does NOT change: no committed plan's verdict moves. Regenerating WarningBaseline.txt across the corpus produces additions only - the new fixture and nothing else - because the fix only ever adds statements that were being dropped. The CLI output hash is unchanged for the same reason: a plain batch enumerates exactly as before. Also caught on the way in, and worth knowing: PlanViewer.Web compiles Core sources through an explicit file list rather than a glob, so a new Core file breaks the solution build until it is added there. It is the same shape of trap as the call sites in #438 and #439 - something you must remember at a second location - and I walked into it. Tested: 327 passing, 0 failed. The new tests fail against the original parser - three of them, exactly the three asserting the body is reached, while the ordering test and the unchanged-plan cases correctly still pass. Verified by reverting the parser rather than assumed. Reported by samplesty, with a genuinely good writeup: file statistics, the contrast against StmtCond working correctly, and the observation that the output is plausible rather than obviously broken, which is what makes it worth fixing rather than documenting. Co-Authored-By: Claude Opus 5 (1M context) --- src/PlanViewer.Core/Output/ResultMapper.cs | 11 +- src/PlanViewer.Core/Services/PlanAnalyzer.cs | 7 +- .../Services/PlanStatements.cs | 68 +++++++++++ .../Services/ShowPlanParser.cs | 86 +++++++------- src/PlanViewer.Web/PlanViewer.Web.csproj | 1 + tests/PlanViewer.Core.Tests/PlanTestHelper.cs | 14 +-- .../Plans/exec_stored_procedure_plan.sqlplan | 2 + .../StoredProcedurePlanTests.cs | 106 ++++++++++++++++++ .../PlanViewer.Core.Tests/WarningBaseline.txt | 11 ++ 9 files changed, 250 insertions(+), 56 deletions(-) create mode 100644 src/PlanViewer.Core/Services/PlanStatements.cs create mode 100644 tests/PlanViewer.Core.Tests/Plans/exec_stored_procedure_plan.sqlplan create mode 100644 tests/PlanViewer.Core.Tests/StoredProcedurePlanTests.cs diff --git a/src/PlanViewer.Core/Output/ResultMapper.cs b/src/PlanViewer.Core/Output/ResultMapper.cs index 83ac5fd..1343688 100644 --- a/src/PlanViewer.Core/Output/ResultMapper.cs +++ b/src/PlanViewer.Core/Output/ResultMapper.cs @@ -24,14 +24,13 @@ internal static AnalysisResult MapCancellable( SqlServerBuild = plan.Build }; - foreach (var batch in plan.Batches) + /* #455: includes statements nested inside a stored procedure or UDF body. Without this the + summary counted the EXEC and nothing else, so a procedure carrying dozens of statement + plans reported total_statements 1 and max_estimated_cost 0. */ + foreach (var stmt in PlanStatements.EnumerateAll(plan)) { cancellationToken.ThrowIfCancellationRequested(); - foreach (var stmt in batch.Statements) - { - cancellationToken.ThrowIfCancellationRequested(); - result.Statements.Add(MapStatement(stmt, cancellationToken)); - } + result.Statements.Add(MapStatement(stmt, cancellationToken)); } result.Summary = BuildSummary(result, cancellationToken); diff --git a/src/PlanViewer.Core/Services/PlanAnalyzer.cs b/src/PlanViewer.Core/Services/PlanAnalyzer.cs index eb6a3f6..2d06444 100644 --- a/src/PlanViewer.Core/Services/PlanAnalyzer.cs +++ b/src/PlanViewer.Core/Services/PlanAnalyzer.cs @@ -45,10 +45,11 @@ internal static void AnalyzeCancellable( CancellationToken cancellationToken) { var cfg = config ?? AnalyzerConfig.Default; - foreach (var batch in plan.Batches) { - cancellationToken.ThrowIfCancellationRequested(); - foreach (var stmt in batch.Statements) + /* #455: every statement, including the ones inside a stored procedure or UDF body. This + used to walk batch.Statements alone, so an EXEC plan analyzed as a single + statement with nothing to say about it. */ + foreach (var stmt in PlanStatements.EnumerateAll(plan)) { cancellationToken.ThrowIfCancellationRequested(); AnalyzeStatement(stmt, cfg, serverMetadata); diff --git a/src/PlanViewer.Core/Services/PlanStatements.cs b/src/PlanViewer.Core/Services/PlanStatements.cs new file mode 100644 index 0000000..97390a5 --- /dev/null +++ b/src/PlanViewer.Core/Services/PlanStatements.cs @@ -0,0 +1,68 @@ +using System.Collections.Generic; +using PlanViewer.Core.Models; + +namespace PlanViewer.Core.Services; + +/// +/// Walks every statement in a plan, including the ones nested inside a stored procedure or a +/// user-defined function (#455). +/// +/// Why this exists. A plan captured around EXEC <procedure> puts the +/// procedure's statements under a StoredProc element, and the parser has always read them — +/// into . Nothing downstream looked there. The analyzer and +/// the result mapper both walked batch.Statements only, so a plan with eighty-seven statement +/// plans inside a procedure analyzed as one statement, zero warnings, zero cost, and exited 0. The +/// output was well-formed and entirely wrong, which is the worst way for this to fail. +/// +/// The traversal itself was not missing — PlanOperations.ValidateComplexity has always +/// descended, which is how the complexity limit counted statements the analysis never saw. This puts +/// that same walk in one place so the two cannot disagree again. +/// +public static class PlanStatements +{ + /// + /// Every statement in the plan, outermost first, each nested body following the statement that + /// owns it. + /// + public static IEnumerable EnumerateAll(ParsedPlan plan) + { + foreach (var batch in plan.Batches) + { + foreach (var statement in EnumerateAll(batch.Statements)) + yield return statement; + } + } + + /// + /// and everything nested beneath them. + /// + /// An explicit stack rather than recursion, because procedure bodies nest — a procedure + /// calling a procedure calling a function — and #430 was a crash caused by assuming a plan's + /// shapes are shallow. + /// + public static IEnumerable EnumerateAll(IReadOnlyList statements) + { + var pending = new Stack(); + for (var i = statements.Count - 1; i >= 0; i--) + pending.Push(statements[i]); + + while (pending.TryPop(out var statement)) + { + yield return statement; + + /* Pushed in reverse so the bodies come back out in source order, and pushed AFTER the + statement is yielded so a body follows the EXEC that owns it rather than preceding it. */ + for (var i = statement.UdfPlans.Count - 1; i >= 0; i--) + PushAll(statement.UdfPlans[i].Statements, pending); + + if (statement.StoredProcPlan is not null) + PushAll(statement.StoredProcPlan.Statements, pending); + } + } + + private static void PushAll(IReadOnlyList statements, Stack pending) + { + for (var i = statements.Count - 1; i >= 0; i--) + pending.Push(statements[i]); + } +} diff --git a/src/PlanViewer.Core/Services/ShowPlanParser.cs b/src/PlanViewer.Core/Services/ShowPlanParser.cs index 35a66f3..453d209 100644 --- a/src/PlanViewer.Core/Services/ShowPlanParser.cs +++ b/src/PlanViewer.Core/Services/ShowPlanParser.cs @@ -278,6 +278,52 @@ private static List ParseStatementAndChildren( } } + /* #455: sub-plans are read BEFORE the no-QueryPlan early return below, because an + EXEC statement has no QueryPlan of its own - every plan lives in the body - + so it took that early return and never reached this code, seventy lines further down. The + parser looked like it descended into procedures and in the one case that matters never + did. The same was true of a UDF call whose statement carries no plan of its own. */ + // XSD gap: UDF sub-plans + foreach (var udfEl in stmtEl.Elements(Ns + "UDF")) + { + var udfInfo = new FunctionPlanInfo + { + ProcName = udfEl.Attribute("ProcName")?.Value ?? "", + IsNativelyCompiled = udfEl.Attribute("IsNativelyCompiled")?.Value is "true" or "1" + }; + var udfStmts = udfEl.Element(Ns + "Statements"); + if (udfStmts != null) + { + foreach (var childStmt in udfStmts.Elements()) + { + var parsed = ParseStatementAndChildren(childStmt, cancellationToken: cancellationToken); + udfInfo.Statements.AddRange(parsed); + } + } + stmt.UdfPlans.Add(udfInfo); + } + + // XSD gap: StoredProc sub-plan + var storedProcEl = stmtEl.Element(Ns + "StoredProc"); + if (storedProcEl != null) + { + var spInfo = new FunctionPlanInfo + { + ProcName = storedProcEl.Attribute("ProcName")?.Value ?? "", + IsNativelyCompiled = storedProcEl.Attribute("IsNativelyCompiled")?.Value is "true" or "1" + }; + var spStmts = storedProcEl.Element(Ns + "Statements"); + if (spStmts != null) + { + foreach (var childStmt in spStmts.Elements()) + { + var parsed = ParseStatementAndChildren(childStmt, cancellationToken: cancellationToken); + spInfo.Statements.AddRange(parsed); + } + } + stmt.StoredProcPlan = spInfo; + } + if (queryPlanEl == null) { // Statements with no QueryPlan (e.g., DECLARE/ASSIGN) still get a synthetic @@ -333,46 +379,6 @@ private static List ParseStatementAndChildren( stmt.RootNode = stmtNode; } - // XSD gap: UDF sub-plans - foreach (var udfEl in stmtEl.Elements(Ns + "UDF")) - { - var udfInfo = new FunctionPlanInfo - { - ProcName = udfEl.Attribute("ProcName")?.Value ?? "", - IsNativelyCompiled = udfEl.Attribute("IsNativelyCompiled")?.Value is "true" or "1" - }; - var udfStmts = udfEl.Element(Ns + "Statements"); - if (udfStmts != null) - { - foreach (var childStmt in udfStmts.Elements()) - { - var parsed = ParseStatementAndChildren(childStmt, cancellationToken: cancellationToken); - udfInfo.Statements.AddRange(parsed); - } - } - stmt.UdfPlans.Add(udfInfo); - } - - // XSD gap: StoredProc sub-plan - var storedProcEl = stmtEl.Element(Ns + "StoredProc"); - if (storedProcEl != null) - { - var spInfo = new FunctionPlanInfo - { - ProcName = storedProcEl.Attribute("ProcName")?.Value ?? "", - IsNativelyCompiled = storedProcEl.Attribute("IsNativelyCompiled")?.Value is "true" or "1" - }; - var spStmts = storedProcEl.Element(Ns + "Statements"); - if (spStmts != null) - { - foreach (var childStmt in spStmts.Elements()) - { - var parsed = ParseStatementAndChildren(childStmt, cancellationToken: cancellationToken); - spInfo.Statements.AddRange(parsed); - } - } - stmt.StoredProcPlan = spInfo; - } return stmt; } diff --git a/src/PlanViewer.Web/PlanViewer.Web.csproj b/src/PlanViewer.Web/PlanViewer.Web.csproj index dfc14a6..9e26aea 100644 --- a/src/PlanViewer.Web/PlanViewer.Web.csproj +++ b/src/PlanViewer.Web/PlanViewer.Web.csproj @@ -23,6 +23,7 @@ + diff --git a/tests/PlanViewer.Core.Tests/PlanTestHelper.cs b/tests/PlanViewer.Core.Tests/PlanTestHelper.cs index 04bfab1..f84b86e 100644 --- a/tests/PlanViewer.Core.Tests/PlanTestHelper.cs +++ b/tests/PlanViewer.Core.Tests/PlanTestHelper.cs @@ -44,15 +44,15 @@ public static List AllWarnings(ParsedPlan plan) { var warnings = new List(); - foreach (var batch in plan.Batches) + /* #455: every statement, including the ones inside a stored procedure or UDF body. This + walked batch.Statements alone, exactly like the analyzer did, so the golden master could + not have caught the analyzer skipping procedure bodies - the two shared a blind spot. */ + foreach (var stmt in PlanViewer.Core.Services.PlanStatements.EnumerateAll(plan)) { - foreach (var stmt in batch.Statements) - { - warnings.AddRange(stmt.PlanWarnings); + warnings.AddRange(stmt.PlanWarnings); - if (stmt.RootNode != null) - CollectNodeWarnings(stmt.RootNode, warnings); - } + if (stmt.RootNode != null) + CollectNodeWarnings(stmt.RootNode, warnings); } return warnings; diff --git a/tests/PlanViewer.Core.Tests/Plans/exec_stored_procedure_plan.sqlplan b/tests/PlanViewer.Core.Tests/Plans/exec_stored_procedure_plan.sqlplan new file mode 100644 index 0000000..6880f48 --- /dev/null +++ b/tests/PlanViewer.Core.Tests/Plans/exec_stored_procedure_plan.sqlplan @@ -0,0 +1,2 @@ + + diff --git a/tests/PlanViewer.Core.Tests/StoredProcedurePlanTests.cs b/tests/PlanViewer.Core.Tests/StoredProcedurePlanTests.cs new file mode 100644 index 0000000..d453627 --- /dev/null +++ b/tests/PlanViewer.Core.Tests/StoredProcedurePlanTests.cs @@ -0,0 +1,106 @@ +using System.Linq; +using PlanViewer.Core.Output; +using PlanViewer.Core.Services; + +namespace PlanViewer.Core.Tests; + +/// +/// #455: a plan captured around EXEC <procedure> analyzed as one statement, zero +/// warnings, zero cost, exit 0 — on a file containing dozens of statement plans. +/// +/// The reported diagnosis was that the parse never descended into the procedure. It is subtler +/// than that and the distinction decides the fix: the parser had always read StoredProc +/// sub-plans, but that code sat BELOW an early return taken when a statement carries no +/// QueryPlan of its own — which is exactly what an EXEC statement is. The descent +/// existed and was unreachable in the only case it was written for. +/// +/// What made it dangerous is that the output was well-formed and plausible. Nothing said the +/// analysis had stopped early; it looked like a clean plan with nothing to report, which invites +/// "no warnings found" about a procedure that in fact has plenty. +/// +public class StoredProcedurePlanTests +{ + /// + /// The three numbers from the report, asserted together. Any one alone could be innocent; the + /// combination — one statement, no warnings, no cost — is the signature of a parse that did not + /// reach the real statements. + /// + [Fact] + public void AnExecProcedurePlanAnalyzesTheProcedureBody() + { + var plan = PlanTestHelper.LoadAndAnalyze("exec_stored_procedure_plan.sqlplan"); + var result = ResultMapper.Map(plan, "exec_stored_procedure_plan.sqlplan"); + + Assert.True(result.Summary.TotalStatements > 1, + $"the procedure body's statements are missing (got {result.Summary.TotalStatements})"); + Assert.True(result.Summary.TotalWarnings > 0, + "a body with a non-SARGable predicate and a table variable cannot be warning-free"); + Assert.True(result.Summary.MaxEstimatedCost > 0, + "every statement carrying a plan has a cost; zero means none were seen"); + } + + /// + /// The specific cause, pinned so a future edit cannot reintroduce it by moving sub-plan parsing + /// back below the early return: the EXEC statement itself has no QueryPlan, and must still + /// carry its body. + /// + [Fact] + public void TheExecStatementHasNoPlanOfItsOwnAndStillCarriesItsBody() + { + var plan = PlanTestHelper.LoadAndAnalyze("exec_stored_procedure_plan.sqlplan"); + + var exec = plan.Batches.SelectMany(b => b.Statements).Single(); + + Assert.NotNull(exec.StoredProcPlan); + Assert.NotEmpty(exec.StoredProcPlan!.Statements); + } + + /// + /// The traversal the analyzer, the mapper and the test helper now share. They each walked + /// batch.Statements separately before, which is how the analyzer and the golden master came to + /// have the same blind spot and neither could catch the other. + /// + [Fact] + public void EnumerateAllReachesNestedStatements() + { + var plan = PlanTestHelper.LoadAndAnalyze("exec_stored_procedure_plan.sqlplan"); + + var shallow = plan.Batches.SelectMany(b => b.Statements).Count(); + var all = PlanStatements.EnumerateAll(plan).Count(); + + Assert.Equal(1, shallow); + Assert.True(all > shallow, $"nested statements were not reached (shallow {shallow}, all {all})"); + } + + /// + /// The outer statement comes back before its body. Order matters for output: a reader scanning + /// the statement list should meet the EXEC before the statements it caused. + /// + [Fact] + public void TheCallingStatementComesBeforeItsBody() + { + var plan = PlanTestHelper.LoadAndAnalyze("exec_stored_procedure_plan.sqlplan"); + + var all = PlanStatements.EnumerateAll(plan).ToList(); + var exec = plan.Batches.SelectMany(b => b.Statements).Single(); + + Assert.Same(exec, all[0]); + } + + /// + /// Plans without a procedure are untouched. The fix only ever adds statements that were being + /// dropped, so a plain batch must enumerate exactly as it always did. + /// + [Theory] + [InlineData("row_goal_plan.sqlplan")] + [InlineData("key_lookup_plan.sqlplan")] + [InlineData("spill_plan.sqlplan")] + public void APlanWithNoProcedureEnumeratesUnchanged(string planFile) + { + var plan = PlanTestHelper.LoadAndAnalyze(planFile); + + Assert.Equal( + plan.Batches.SelectMany(b => b.Statements).Count(), + PlanStatements.EnumerateAll(plan).Count()); + } +} diff --git a/tests/PlanViewer.Core.Tests/WarningBaseline.txt b/tests/PlanViewer.Core.Tests/WarningBaseline.txt index 05cef6f..7c7ea13 100644 --- a/tests/PlanViewer.Core.Tests/WarningBaseline.txt +++ b/tests/PlanViewer.Core.Tests/WarningBaseline.txt @@ -75,6 +75,17 @@ Exchange Spill | Critical | Exchange spill — 5,000,000 writes to TempDB. The p Expensive Operator | Critical | Sort took 65,000ms (81.2% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be? Bare Scan | Warning | Clustered index scan reads the full table with no predicate, outputting 1 column(s): Test.Col1. Consider a nonclustered index on the output columns (as key or INCLUDE) so SQL Server can read a narrower structure. For analytical workloads, a columnstore index may be a better fit. +### exec_stored_procedure_plan.sqlplan +Non-SARGable Predicate | Warning | Implicit conversion (CONVERT_IMPLICIT) prevents an index seek. Match the parameter or variable data type to the column data type.\nPredicate: CONVERT_IMPLICIT(nvarchar(20),[ps455].[dbo].[Orders].[Code],0)=[@code] +Filter Operator | Warning | Filter operator discarding rows late in the plan.\nPredicate: [ps455].[dbo].[Orders].[Amount]>(0.5) +Table Variable | Critical | This query modifies a table variable, which forces the entire plan to run single-threaded. SQL Server cannot use parallelism for modifications to table variables. Replace with a #temp table to allow parallel execution. +Table Variable | Critical | Modifying a table variable forces the entire plan to run single-threaded. Replace with a #temp table to allow parallel execution. +Top Above Scan | Warning | Top reads from Clustered Index Scan on ps455.dbo.Orders (Node 2). An index on the ORDER BY columns could eliminate the scan and sort entirely. +Row Goal | Info | Row goal active: estimate reduced from 20,000 to 100 (200x reduction) due to TOP. The optimizer chose this plan shape expecting to stop reading early. If the query reads all rows anyway, the plan choice may be suboptimal. +Table Variable | Warning | Table variable detected. Table variables lack column-level statistics, which causes bad row estimates, join choices, and memory grant decisions. Replace with a #temp table. +Scan With Predicate | Warning | Scan with residual predicate — SQL Server is reading every row and filtering after the fact. Check that you have appropriate indexes.\nPredicate: @t.[Id] as [t].[Id] IS NOT NULL +Table Variable | Warning | Table variable detected. Table variables lack column-level statistics, which causes bad row estimates, join choices, and memory grant decisions. Replace with a #temp table. + ### implicit_convert_seek_plan.sqlplan Implicit Conversion | Critical | Implicit conversion prevented an index seek, forcing a scan instead. Fix the data type mismatch: ensure the parameter or variable type matches the column type exactly. Seek Plan: CONVERT_IMPLICIT(nvarchar(40),[TestDB].[dbo].[Users].[DisplayName],0)=[@d] Bare Scan | Warning | Clustered index scan reads the full table with no predicate, outputting 1 column(s): Users.Id. Consider a nonclustered index on the output columns (as key or INCLUDE) so SQL Server can read a narrower structure. For analytical workloads, a columnstore index may be a better fit.