From 2d2011fb01b7b4c57f2675fb1292b2e56fd1f666 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Fri, 10 Apr 2026 14:54:59 -0400 Subject: [PATCH 1/2] Add wait stats as cross-cutting analysis signal in PlanAnalyzer Surface statement-level wait stats across Rules 1, 5, 11, and 16 so the analyzer uses actual execution wait evidence to enrich warnings. The dominant wait type (SOS_SCHEDULER_YIELD, CXPACKET, HTBUILD, PAGEIOLATCH, LCK_M_S, etc.) is appended to each warning message. Rule 11 (Scan with Predicate) additionally elevates to Critical when I/O waits confirm the scan is hitting disk at >= 50% of plan cost. Expand GetWaitStatsAdvice (Rules 25/31) with specific explanations for all 21 wait types found in real plan files: SOS_SCHEDULER_YIELD, CXSYNC_PORT, MEMORY_ALLOCATION_EXT, HTBUILD/HTDELETE/HTREPARTITION, BPSORT, BMPBUILD, PAGELATCH, LOGBUFFER, ASYNC_NETWORK_IO, SOS_PHYS_PAGE_CACHE, and others. Remove dead RESOURCE_SEMAPHORE branch (pre-execution wait, never appears in statement-level plan wait stats). Co-Authored-By: Claude Opus 4.6 (1M context) --- src/PlanViewer.Core/Services/PlanAnalyzer.cs | 137 ++++++- .../PlanAnalyzerTests.cs | 380 ++++++++++++++++++ 2 files changed, 509 insertions(+), 8 deletions(-) diff --git a/src/PlanViewer.Core/Services/PlanAnalyzer.cs b/src/PlanViewer.Core/Services/PlanAnalyzer.cs index f2e052d..3a66d47 100644 --- a/src/PlanViewer.Core/Services/PlanAnalyzer.cs +++ b/src/PlanViewer.Core/Services/PlanAnalyzer.cs @@ -548,9 +548,9 @@ private static void AnalyzeNode(PlanNode node, PlanStatement stmt, AnalyzerConfi { // Gate: skip trivial filters based on actual stats or estimated cost bool isTrivial; + long childReads = 0; if (node.HasActualStats) { - long childReads = 0; foreach (var child in node.Children) childReads += SumSubtreeReads(child); var childElapsed = node.Children.Max(c => c.ActualElapsedMs); @@ -571,6 +571,14 @@ private static void AnalyzeNode(PlanNode node, PlanStatement stmt, AnalyzerConfi message += $"\n{impact}"; message += $"\nPredicate: {predicate}"; + // Wait stats add context — rows burned CPU/I/O/waits just to be discarded + if (childReads >= 1000) + { + var waitContext = GetTopWaitContext(stmt.WaitStats); + if (waitContext != null) + message += $"\n{waitContext}"; + } + node.Warnings.Add(new PlanWarning { WarningType = "Filter Operator", @@ -647,10 +655,16 @@ private static void AnalyzeNode(PlanNode node, PlanStatement stmt, AnalyzerConfi var actualDisplay = executions > 1 ? $"Actual {node.ActualRows:N0} ({actualPerExec:N0} rows x {executions:N0} executions)" : $"Actual {node.ActualRows:N0}"; + var message = $"Estimated {node.EstimateRows:N0} vs {actualDisplay} — {factor:F0}x {direction}. {harm}"; + + var waitContext = GetTopWaitContext(stmt.WaitStats); + if (waitContext != null) + message += $" {waitContext}"; + node.Warnings.Add(new PlanWarning { WarningType = "Row Estimate Mismatch", - Message = $"Estimated {node.EstimateRows:N0} vs {actualDisplay} — {factor:F0}x {direction}. {harm}", + Message = message, Severity = factor >= 100 ? PlanWarningSeverity.Critical : PlanWarningSeverity.Warning }); } @@ -833,6 +847,16 @@ _ when nonSargableReason.StartsWith("Function call") => if (!string.IsNullOrEmpty(details.Summary)) message += $" {details.Summary}"; message += " Check that you have appropriate indexes."; + + var waitContext = GetTopWaitContext(stmt.WaitStats); + if (waitContext != null) + message += $" {waitContext}"; + + // I/O waits specifically confirm the scan is hitting disk — elevate + if (HasSignificantIoWaits(stmt.WaitStats) && details.CostPct >= 50 + && severity != PlanWarningSeverity.Critical) + severity = PlanWarningSeverity.Critical; + message += $"\nPredicate: {Truncate(displayPredicate, 200)}"; node.Warnings.Add(new PlanWarning @@ -1023,6 +1047,10 @@ _ when nonSargableReason.StartsWith("Function call") => else details.Add("Consider whether a hash or merge join would be more appropriate for this row count."); + var waitContext = GetTopWaitContext(stmt.WaitStats); + if (waitContext != null) + details.Add(waitContext); + node.Warnings.Add(new PlanWarning { WarningType = "Nested Loops High Executions", @@ -1693,24 +1721,117 @@ private static ScanImpact BuildScanImpactDetails(PlanNode node, PlanStatement st var waitType = top.WaitType.ToUpperInvariant(); var advice = waitType switch { + // I/O: reading/writing data pages from disk _ when waitType.StartsWith("PAGEIOLATCH") => $"I/O bound — {topPct:N0}% of wait time is {top.WaitType}. Data is being read from disk rather than memory. Consider adding indexes to reduce I/O, or investigate memory pressure.", + _ when waitType.Contains("IO_COMPLETION") => + $"I/O bound — {topPct:N0}% of wait time is {top.WaitType}. Non-buffer I/O such as sort/hash spills to TempDB or eager writes.", + + // CPU: thread yielding its scheduler quantum + _ when waitType == "SOS_SCHEDULER_YIELD" => + $"CPU bound — {topPct:N0}% of wait time is {top.WaitType}. The query is consuming significant CPU. Look for expensive operators (scans, sorts, hash builds) that could be eliminated or reduced.", + + // Parallelism: exchange and synchronization waits + _ when waitType.StartsWith("CXPACKET") || waitType.StartsWith("CXCONSUMER") => + $"Parallel thread skew — {topPct:N0}% of wait time is {top.WaitType}. Work is unevenly distributed across parallel threads.", + _ when waitType.StartsWith("CXSYNC") => + $"Parallel synchronization — {topPct:N0}% of wait time is {top.WaitType}. Threads are waiting at exchange operators to synchronize parallel execution.", + + // Hash operations + _ when waitType.StartsWith("HT") => + $"Hash operation — {topPct:N0}% of wait time is {top.WaitType}. Time spent building, repartitioning, or cleaning up hash tables. Large hash builds may indicate missing indexes or bad row estimates.", + + // Sort/bitmap batch operations + _ when waitType == "BPSORT" => + $"Batch sort — {topPct:N0}% of wait time is {top.WaitType}. Time spent in batch-mode sort operations.", + _ when waitType == "BMPBUILD" => + $"Bitmap build — {topPct:N0}% of wait time is {top.WaitType}. Time spent building bitmap filters for hash joins.", + + // Memory allocation + _ when waitType.Contains("MEMORY_ALLOCATION_EXT") => + $"Memory allocation — {topPct:N0}% of wait time is {top.WaitType}. Frequent memory allocations during query execution.", + + // Latch contention (non-I/O) + _ when waitType.StartsWith("PAGELATCH") => + $"Page latch contention — {topPct:N0}% of wait time is {top.WaitType}. In-memory page contention, often on TempDB or hot pages.", _ when waitType.StartsWith("LATCH_") => $"Latch contention — {topPct:N0}% of wait time is {top.WaitType}.", + + // Lock contention _ when waitType.StartsWith("LCK_") => $"Lock contention — {topPct:N0}% of wait time is {top.WaitType}. Other sessions are holding locks that this query needs.", - _ when waitType.StartsWith("CXPACKET") || waitType.StartsWith("CXCONSUMER") => - $"Parallel thread skew — {topPct:N0}% of wait time is {top.WaitType}. Work is unevenly distributed across parallel threads.", - _ when waitType.Contains("IO_COMPLETION") => - $"I/O bound — {topPct:N0}% of wait time is {top.WaitType}.", - _ when waitType.StartsWith("RESOURCE_SEMAPHORE") => - $"Memory grant wait — {topPct:N0}% of wait time is {top.WaitType}. The query had to wait for a memory grant.", + + // Log writes + _ when waitType == "LOGBUFFER" => + $"Log write — {topPct:N0}% of wait time is {top.WaitType}. Waiting for transaction log buffer flushes, typically from data modifications.", + + // Network + _ when waitType == "ASYNC_NETWORK_IO" => + $"Network bound — {topPct:N0}% of wait time is {top.WaitType}. The client application is not consuming results fast enough.", + + // Physical page cache + _ when waitType == "SOS_PHYS_PAGE_CACHE" => + $"Physical page cache — {topPct:N0}% of wait time is {top.WaitType}. Contention on the physical memory page allocator.", + _ => $"Dominant wait is {top.WaitType} ({topPct:N0}% of wait time)." }; return advice; } + /// + /// Returns true if the statement has significant I/O waits (PAGEIOLATCH_*, IO_COMPLETION). + /// Used for severity elevation decisions where I/O specifically indicates disk access. + /// Thresholds: I/O waits >= 20% of total wait time AND >= 100ms absolute. + /// + private static bool HasSignificantIoWaits(List waits) + { + if (waits.Count == 0) + return false; + + var totalMs = waits.Sum(w => w.WaitTimeMs); + if (totalMs == 0) + return false; + + long ioMs = 0; + foreach (var w in waits) + { + var wt = w.WaitType.ToUpperInvariant(); + if (wt.StartsWith("PAGEIOLATCH") || wt.Contains("IO_COMPLETION")) + ioMs += w.WaitTimeMs; + } + + var pct = (double)ioMs / totalMs * 100; + return ioMs >= 100 && pct >= 20; + } + + /// + /// Returns a terse sentence describing the dominant wait type for appending + /// to an existing warning message, or null if waits are negligible. + /// Surfaces whatever wait type is dominant — PAGEIOLATCH, SOS_SCHEDULER_YIELD, + /// CXPACKET, LCK_*, HTBUILD, EXECSYNC, IO_COMPLETION, etc. + /// Threshold: top wait >= 100ms and >= 20% of total wait time. + /// + private static string? GetTopWaitContext(List waits) + { + if (waits.Count == 0) + return null; + + var totalMs = waits.Sum(w => w.WaitTimeMs); + if (totalMs == 0) + return null; + + var top = waits.OrderByDescending(w => w.WaitTimeMs).First(); + if (top.WaitTimeMs < 100) + return null; + + var pct = (double)top.WaitTimeMs / totalMs * 100; + if (pct < 20) + return null; + + return $"Dominant wait: {top.WaitType} ({top.WaitTimeMs:N0}ms, {pct:N0}% of total wait time)."; + } + private static bool AllocatesResources(PlanNode node) { // Operators that get memory grants or allocate structures based on row estimates. diff --git a/tests/PlanViewer.Core.Tests/PlanAnalyzerTests.cs b/tests/PlanViewer.Core.Tests/PlanAnalyzerTests.cs index d0656aa..e6f450f 100644 --- a/tests/PlanViewer.Core.Tests/PlanAnalyzerTests.cs +++ b/tests/PlanViewer.Core.Tests/PlanAnalyzerTests.cs @@ -1,4 +1,5 @@ using PlanViewer.Core.Models; +using PlanViewer.Core.Services; namespace PlanViewer.Core.Tests; @@ -844,4 +845,383 @@ public void Issue178_7_FilterSuppressedOnTrivialChildIO() Assert.Empty(filterWarnings); } + + // --------------------------------------------------------------- + // Wait stats cross-cutting integration + // --------------------------------------------------------------- + + private static List IoWaits(long ms = 2000) => new() + { + new WaitStatInfo { WaitType = "PAGEIOLATCH_SH", WaitTimeMs = ms, WaitCount = 50 }, + new WaitStatInfo { WaitType = "ASYNC_NETWORK_IO", WaitTimeMs = 100, WaitCount = 10 } + }; + + private static List LockWaits(long ms = 3000) => new() + { + new WaitStatInfo { WaitType = "LCK_M_S", WaitTimeMs = ms, WaitCount = 200 }, + new WaitStatInfo { WaitType = "ASYNC_NETWORK_IO", WaitTimeMs = 100, WaitCount = 10 } + }; + + private static List CpuWaits(long ms = 4000) => new() + { + new WaitStatInfo { WaitType = "SOS_SCHEDULER_YIELD", WaitTimeMs = ms, WaitCount = 5000 }, + new WaitStatInfo { WaitType = "ASYNC_NETWORK_IO", WaitTimeMs = 100, WaitCount = 10 } + }; + + private static List CxWaits(long ms = 3000) => new() + { + new WaitStatInfo { WaitType = "CXPACKET", WaitTimeMs = ms, WaitCount = 400 }, + new WaitStatInfo { WaitType = "SOS_SCHEDULER_YIELD", WaitTimeMs = 200, WaitCount = 100 } + }; + + private static List HashWaits(long ms = 2500) => new() + { + new WaitStatInfo { WaitType = "HTBUILD", WaitTimeMs = ms, WaitCount = 80 }, + new WaitStatInfo { WaitType = "SOS_SCHEDULER_YIELD", WaitTimeMs = 200, WaitCount = 100 } + }; + + private static ParsedPlan BuildSyntheticPlan(PlanStatement stmt) + { + var plan = new ParsedPlan(); + plan.Batches.Add(new PlanBatch { Statements = { stmt } }); + return plan; + } + + [Fact] + public void WaitStats_Rule01_FilterAppendsIoContext() + { + // Filter with >1000 child reads + I/O waits → message includes wait context + var child = new PlanNode + { + NodeId = 1, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + HasActualStats = true, ActualRows = 100000, ActualLogicalReads = 5000, ActualElapsedMs = 500 + }; + var filter = new PlanNode + { + NodeId = 0, PhysicalOp = "Filter", LogicalOp = "Filter", + Predicate = "[col1] > 100", + HasActualStats = true, ActualRows = 10, ActualElapsedMs = 500, + Children = { child } + }; + child.Parent = filter; + + var stmt = new PlanStatement + { + RootNode = filter, + WaitStats = IoWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Filter Operator").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Message.Contains("PAGEIOLATCH_SH")); + } + + [Fact] + public void WaitStats_Rule01_FilterNoContextWithoutWaits() + { + // Same filter but no wait stats → no wait context in message + var child = new PlanNode + { + NodeId = 1, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + HasActualStats = true, ActualRows = 100000, ActualLogicalReads = 5000, ActualElapsedMs = 500 + }; + var filter = new PlanNode + { + NodeId = 0, PhysicalOp = "Filter", LogicalOp = "Filter", + Predicate = "[col1] > 100", + HasActualStats = true, ActualRows = 10, ActualElapsedMs = 500, + Children = { child } + }; + child.Parent = filter; + + var stmt = new PlanStatement { RootNode = filter }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Filter Operator").ToList(); + Assert.NotEmpty(warnings); + Assert.DoesNotContain(warnings, w => w.Message.Contains("Wait stats")); + } + + [Fact] + public void WaitStats_Rule05_SpillWithIoWaitsAppendsContext() + { + // Row mismatch causing a spill + I/O waits → I/O context appended + // Sort needs a spill warning so AssessEstimateHarm returns non-null, + // and must have a non-root parent (NodeId != -1). + var sortNode = new PlanNode + { + NodeId = 2, PhysicalOp = "Sort", LogicalOp = "Sort", + HasActualStats = true, + EstimateRows = 100, ActualRows = 100000, ActualExecutions = 1, + Warnings = { new PlanWarning + { + WarningType = "Sort Spill", + Message = "Sort spilled", + Severity = PlanWarningSeverity.Warning, + SpillDetails = new SpillDetail { SpillType = "Sort", WritesToTempDb = 1000 } + }} + }; + var selectNode = new PlanNode + { + NodeId = 1, PhysicalOp = "Compute Scalar", LogicalOp = "Compute Scalar", + Children = { sortNode } + }; + sortNode.Parent = selectNode; + var root = new PlanNode + { + NodeId = -1, PhysicalOp = "SELECT", LogicalOp = "SELECT", + Children = { selectNode } + }; + selectNode.Parent = root; + + var stmt = new PlanStatement + { + RootNode = root, + WaitStats = IoWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Row Estimate Mismatch").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Message.Contains("PAGEIOLATCH_SH")); + } + + [Fact] + public void WaitStats_Rule11_ScanWithIoWaitsElevatedToCritical() + { + // Scan at 60% cost + I/O waits → elevated to Critical (normally needs 90%) + var scan = new PlanNode + { + NodeId = 0, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + Predicate = "[col1] = @p1", + EstimatedTotalSubtreeCost = 6.0 + }; + var stmt = new PlanStatement + { + RootNode = scan, + StatementSubTreeCost = 10.0, + WaitStats = IoWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Scan With Predicate").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Severity == PlanWarningSeverity.Critical); + Assert.Contains(warnings, w => w.Message.Contains("PAGEIOLATCH_SH")); + } + + [Fact] + public void WaitStats_Rule11_ScanWithoutIoWaitsStaysWarning() + { + // Same scan at 60% cost but no I/O waits → stays Warning + var scan = new PlanNode + { + NodeId = 0, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + Predicate = "[col1] = @p1", + EstimatedTotalSubtreeCost = 6.0 + }; + var stmt = new PlanStatement + { + RootNode = scan, + StatementSubTreeCost = 10.0 + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Scan With Predicate").ToList(); + Assert.NotEmpty(warnings); + Assert.All(warnings, w => Assert.Equal(PlanWarningSeverity.Warning, w.Severity)); + } + + [Fact] + public void WaitStats_Rule16_NestedLoopsAppendsLockContext() + { + // Nested Loops with >100K inner executions + lock waits → lock context appended + var outer = new PlanNode + { + NodeId = 1, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + HasActualStats = true, ActualRows = 500000, ActualExecutions = 1, EstimateRows = 500000 + }; + var inner = new PlanNode + { + NodeId = 2, PhysicalOp = "Index Seek", LogicalOp = "Index Seek", + HasActualStats = true, ActualRows = 500000, ActualExecutions = 500000 + }; + var nl = new PlanNode + { + NodeId = 0, PhysicalOp = "Nested Loops", LogicalOp = "Inner Join", + HasActualStats = true, ActualRows = 500000, + Children = { outer, inner } + }; + outer.Parent = nl; + inner.Parent = nl; + + var stmt = new PlanStatement + { + RootNode = nl, + WaitStats = LockWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Nested Loops High Executions").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Message.Contains("LCK_M_S")); + } + + [Fact] + public void WaitStats_Rule16_NestedLoopsSurfacesIoWaits() + { + // Nested Loops with >100K inner executions + I/O waits → I/O context + var outer = new PlanNode + { + NodeId = 1, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + HasActualStats = true, ActualRows = 500000, ActualExecutions = 1, EstimateRows = 500000 + }; + var inner = new PlanNode + { + NodeId = 2, PhysicalOp = "Index Seek", LogicalOp = "Index Seek", + HasActualStats = true, ActualRows = 500000, ActualExecutions = 500000 + }; + var nl = new PlanNode + { + NodeId = 0, PhysicalOp = "Nested Loops", LogicalOp = "Inner Join", + HasActualStats = true, ActualRows = 500000, + Children = { outer, inner } + }; + outer.Parent = nl; + inner.Parent = nl; + + var stmt = new PlanStatement + { + RootNode = nl, + WaitStats = IoWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Nested Loops High Executions").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Message.Contains("PAGEIOLATCH_SH")); + } + + [Fact] + public void WaitStats_SosSchedulerYield_SurfacedOnScan() + { + // SOS_SCHEDULER_YIELD as dominant wait on a scan → surfaces in message + var scan = new PlanNode + { + NodeId = 0, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + Predicate = "[col1] = @p1", + EstimatedTotalSubtreeCost = 6.0 + }; + var stmt = new PlanStatement + { + RootNode = scan, + StatementSubTreeCost = 10.0, + WaitStats = CpuWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Scan With Predicate").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Message.Contains("SOS_SCHEDULER_YIELD")); + // CPU waits are not I/O — should NOT elevate severity (stays Warning at 60% cost) + Assert.All(warnings, w => Assert.Equal(PlanWarningSeverity.Warning, w.Severity)); + } + + [Fact] + public void WaitStats_CxPacket_SurfacedOnNestedLoops() + { + // CXPACKET as dominant wait on Nested Loops → surfaces in message + var outer = new PlanNode + { + NodeId = 1, PhysicalOp = "Clustered Index Scan", LogicalOp = "Clustered Index Scan", + HasActualStats = true, ActualRows = 500000, ActualExecutions = 1, EstimateRows = 500000 + }; + var inner = new PlanNode + { + NodeId = 2, PhysicalOp = "Index Seek", LogicalOp = "Index Seek", + HasActualStats = true, ActualRows = 500000, ActualExecutions = 500000 + }; + var nl = new PlanNode + { + NodeId = 0, PhysicalOp = "Nested Loops", LogicalOp = "Inner Join", + HasActualStats = true, ActualRows = 500000, + Children = { outer, inner } + }; + outer.Parent = nl; + inner.Parent = nl; + + var stmt = new PlanStatement + { + RootNode = nl, + WaitStats = CxWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Nested Loops High Executions").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Message.Contains("CXPACKET")); + } + + [Fact] + public void WaitStats_HtBuild_SurfacedOnEstimateMismatch() + { + // HTBUILD as dominant wait on a hash join with bad estimates → surfaces in message + var hashNode = new PlanNode + { + NodeId = 2, PhysicalOp = "Hash Match", LogicalOp = "Inner Join", + HasActualStats = true, + EstimateRows = 100, ActualRows = 100000, ActualExecutions = 1, + Warnings = { new PlanWarning + { + WarningType = "Hash Spill", + Message = "Hash spilled", + Severity = PlanWarningSeverity.Warning, + SpillDetails = new SpillDetail { SpillType = "Hash", WritesToTempDb = 500 } + }} + }; + var parent = new PlanNode + { + NodeId = 1, PhysicalOp = "Compute Scalar", LogicalOp = "Compute Scalar", + Children = { hashNode } + }; + hashNode.Parent = parent; + var root = new PlanNode + { + NodeId = -1, PhysicalOp = "SELECT", LogicalOp = "SELECT", + Children = { parent } + }; + parent.Parent = root; + + var stmt = new PlanStatement + { + RootNode = root, + WaitStats = HashWaits() + }; + var plan = BuildSyntheticPlan(stmt); + PlanAnalyzer.Analyze(plan); + + var warnings = PlanTestHelper.AllNodeWarnings(stmt) + .Where(w => w.WarningType == "Row Estimate Mismatch").ToList(); + Assert.NotEmpty(warnings); + Assert.Contains(warnings, w => w.Message.Contains("HTBUILD")); + } } From e9655311760a1c253659238ccf7580870cdad5b8 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Fri, 10 Apr 2026 15:31:33 -0400 Subject: [PATCH 2/2] Add inline wait type labels and expand wait stats coverage MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Annotate each wait stat line in the advice panel with a short description (e.g., "I/O — reading data from disk", "CPU — scheduler yielding") so users can immediately understand what each wait type means without leaving the panel. Labels render inline in muted text via GetWaitLabel(). Extract DescribeWaitType() from GetWaitStatsAdvice() so the wait type knowledge is reusable. Remove dead RESOURCE_SEMAPHORE branch (pre-execution wait, never appears in plan wait stats). Drop the separate summary line that had formatting issues in favor of per-line inline labels. Co-Authored-By: Claude Opus 4.6 (1M context) --- .../Services/AdviceContentBuilder.cs | 7 ++ src/PlanViewer.Core/Services/PlanAnalyzer.cs | 78 +++++++++++++------ 2 files changed, 63 insertions(+), 22 deletions(-) diff --git a/src/PlanViewer.App/Services/AdviceContentBuilder.cs b/src/PlanViewer.App/Services/AdviceContentBuilder.cs index 2c96e54..525fb9d 100644 --- a/src/PlanViewer.App/Services/AdviceContentBuilder.cs +++ b/src/PlanViewer.App/Services/AdviceContentBuilder.cs @@ -7,6 +7,7 @@ using Avalonia.Layout; using Avalonia.Media; using PlanViewer.Core.Output; +using PlanViewer.Core.Services; namespace PlanViewer.App.Services; @@ -994,6 +995,12 @@ private static StackPanel CreateWaitStatLine(string waitName, string waitValue, var waitBrush = GetWaitCategoryBrush(waitName); tb.Inlines!.Add(new Run(waitName) { Foreground = waitBrush }); tb.Inlines.Add(new Run(": " + waitValue) { Foreground = ValueBrush }); + + // Inline description label for the wait type + var label = PlanAnalyzer.GetWaitLabel(waitName); + if (!string.IsNullOrEmpty(label)) + tb.Inlines.Add(new Run(" " + label) { Foreground = MutedBrush, FontSize = 11 }); + wrapper.Children.Add(tb); // Proportional bar scaled to max wait in group diff --git a/src/PlanViewer.Core/Services/PlanAnalyzer.cs b/src/PlanViewer.Core/Services/PlanAnalyzer.cs index 3a66d47..d656279 100644 --- a/src/PlanViewer.Core/Services/PlanAnalyzer.cs +++ b/src/PlanViewer.Core/Services/PlanAnalyzer.cs @@ -1699,9 +1699,36 @@ private static ScanImpact BuildScanImpactDetails(PlanNode node, PlanStatement st /// - A parent Sort/Hash spilled (downstream estimate caused bad grant) /// /// - /// Returns targeted advice based on statement-level wait stats, or null if no waits. - /// When the dominant wait type is clear, gives specific guidance instead of generic advice. + /// Returns a short label describing what a wait type means (e.g., "I/O — reading from disk"). + /// Public for use by UI components that annotate wait stats inline. /// + public static string GetWaitLabel(string waitType) + { + var wt = waitType.ToUpperInvariant(); + return wt switch + { + _ when wt.StartsWith("PAGEIOLATCH") => "I/O — reading data from disk", + _ when wt.Contains("IO_COMPLETION") => "I/O — spills to TempDB or eager writes", + _ when wt == "SOS_SCHEDULER_YIELD" => "CPU — scheduler yielding", + _ when wt.StartsWith("CXPACKET") || wt.StartsWith("CXCONSUMER") => "parallelism — thread skew", + _ when wt.StartsWith("CXSYNC") => "parallelism — exchange synchronization", + _ when wt == "HTBUILD" => "hash — building hash table", + _ when wt == "HTDELETE" => "hash — cleaning up hash table", + _ when wt == "HTREPARTITION" => "hash — repartitioning", + _ when wt.StartsWith("HT") => "hash operation", + _ when wt == "BPSORT" => "batch sort", + _ when wt == "BMPBUILD" => "bitmap filter build", + _ when wt.Contains("MEMORY_ALLOCATION_EXT") => "memory allocation", + _ when wt.StartsWith("PAGELATCH") => "page latch — in-memory contention", + _ when wt.StartsWith("LATCH_") => "latch contention", + _ when wt.StartsWith("LCK_") => "lock contention", + _ when wt == "LOGBUFFER" => "transaction log writes", + _ when wt == "ASYNC_NETWORK_IO" => "network — client not consuming results", + _ when wt == "SOS_PHYS_PAGE_CACHE" => "physical page cache contention", + _ => "" + }; + } + private static string? GetWaitStatsAdvice(List waits) { if (waits.Count == 0) @@ -1718,65 +1745,72 @@ private static ScanImpact BuildScanImpactDetails(PlanNode node, PlanStatement st if (topPct < 80) return null; - var waitType = top.WaitType.ToUpperInvariant(); - var advice = waitType switch + return DescribeWaitType(top.WaitType, topPct); + } + + /// + /// Maps a wait type to a human-readable description with percentage context. + /// Covers all wait types observed in real execution plan files. + /// + private static string DescribeWaitType(string rawWaitType, double topPct) + { + var waitType = rawWaitType.ToUpperInvariant(); + return waitType switch { // I/O: reading/writing data pages from disk _ when waitType.StartsWith("PAGEIOLATCH") => - $"I/O bound — {topPct:N0}% of wait time is {top.WaitType}. Data is being read from disk rather than memory. Consider adding indexes to reduce I/O, or investigate memory pressure.", + $"I/O bound — {topPct:N0}% of wait time is {rawWaitType}. Data is being read from disk rather than memory. Consider adding indexes to reduce I/O, or investigate memory pressure.", _ when waitType.Contains("IO_COMPLETION") => - $"I/O bound — {topPct:N0}% of wait time is {top.WaitType}. Non-buffer I/O such as sort/hash spills to TempDB or eager writes.", + $"I/O bound — {topPct:N0}% of wait time is {rawWaitType}. Non-buffer I/O such as sort/hash spills to TempDB or eager writes.", // CPU: thread yielding its scheduler quantum _ when waitType == "SOS_SCHEDULER_YIELD" => - $"CPU bound — {topPct:N0}% of wait time is {top.WaitType}. The query is consuming significant CPU. Look for expensive operators (scans, sorts, hash builds) that could be eliminated or reduced.", + $"CPU bound — {topPct:N0}% of wait time is {rawWaitType}. The query is consuming significant CPU. Look for expensive operators (scans, sorts, hash builds) that could be eliminated or reduced.", // Parallelism: exchange and synchronization waits _ when waitType.StartsWith("CXPACKET") || waitType.StartsWith("CXCONSUMER") => - $"Parallel thread skew — {topPct:N0}% of wait time is {top.WaitType}. Work is unevenly distributed across parallel threads.", + $"Parallel thread skew — {topPct:N0}% of wait time is {rawWaitType}. Work is unevenly distributed across parallel threads.", _ when waitType.StartsWith("CXSYNC") => - $"Parallel synchronization — {topPct:N0}% of wait time is {top.WaitType}. Threads are waiting at exchange operators to synchronize parallel execution.", + $"Parallel synchronization — {topPct:N0}% of wait time is {rawWaitType}. Threads are waiting at exchange operators to synchronize parallel execution.", // Hash operations _ when waitType.StartsWith("HT") => - $"Hash operation — {topPct:N0}% of wait time is {top.WaitType}. Time spent building, repartitioning, or cleaning up hash tables. Large hash builds may indicate missing indexes or bad row estimates.", + $"Hash operation — {topPct:N0}% of wait time is {rawWaitType}. Time spent building, repartitioning, or cleaning up hash tables. Large hash builds may indicate missing indexes or bad row estimates.", // Sort/bitmap batch operations _ when waitType == "BPSORT" => - $"Batch sort — {topPct:N0}% of wait time is {top.WaitType}. Time spent in batch-mode sort operations.", + $"Batch sort — {topPct:N0}% of wait time is {rawWaitType}. Time spent in batch-mode sort operations.", _ when waitType == "BMPBUILD" => - $"Bitmap build — {topPct:N0}% of wait time is {top.WaitType}. Time spent building bitmap filters for hash joins.", + $"Bitmap build — {topPct:N0}% of wait time is {rawWaitType}. Time spent building bitmap filters for hash joins.", // Memory allocation _ when waitType.Contains("MEMORY_ALLOCATION_EXT") => - $"Memory allocation — {topPct:N0}% of wait time is {top.WaitType}. Frequent memory allocations during query execution.", + $"Memory allocation — {topPct:N0}% of wait time is {rawWaitType}. Frequent memory allocations during query execution.", // Latch contention (non-I/O) _ when waitType.StartsWith("PAGELATCH") => - $"Page latch contention — {topPct:N0}% of wait time is {top.WaitType}. In-memory page contention, often on TempDB or hot pages.", + $"Page latch contention — {topPct:N0}% of wait time is {rawWaitType}. In-memory page contention, often on TempDB or hot pages.", _ when waitType.StartsWith("LATCH_") => - $"Latch contention — {topPct:N0}% of wait time is {top.WaitType}.", + $"Latch contention — {topPct:N0}% of wait time is {rawWaitType}.", // Lock contention _ when waitType.StartsWith("LCK_") => - $"Lock contention — {topPct:N0}% of wait time is {top.WaitType}. Other sessions are holding locks that this query needs.", + $"Lock contention — {topPct:N0}% of wait time is {rawWaitType}. Other sessions are holding locks that this query needs.", // Log writes _ when waitType == "LOGBUFFER" => - $"Log write — {topPct:N0}% of wait time is {top.WaitType}. Waiting for transaction log buffer flushes, typically from data modifications.", + $"Log write — {topPct:N0}% of wait time is {rawWaitType}. Waiting for transaction log buffer flushes, typically from data modifications.", // Network _ when waitType == "ASYNC_NETWORK_IO" => - $"Network bound — {topPct:N0}% of wait time is {top.WaitType}. The client application is not consuming results fast enough.", + $"Network bound — {topPct:N0}% of wait time is {rawWaitType}. The client application is not consuming results fast enough.", // Physical page cache _ when waitType == "SOS_PHYS_PAGE_CACHE" => - $"Physical page cache — {topPct:N0}% of wait time is {top.WaitType}. Contention on the physical memory page allocator.", + $"Physical page cache — {topPct:N0}% of wait time is {rawWaitType}. Contention on the physical memory page allocator.", - _ => $"Dominant wait is {top.WaitType} ({topPct:N0}% of wait time)." + _ => $"Dominant wait is {rawWaitType} ({topPct:N0}% of wait time)." }; - - return advice; } ///