diff --git a/src/PlanViewer.Core/PlanViewer.Core.csproj b/src/PlanViewer.Core/PlanViewer.Core.csproj
index b0dc1c1..e4f0a76 100644
--- a/src/PlanViewer.Core/PlanViewer.Core.csproj
+++ b/src/PlanViewer.Core/PlanViewer.Core.csproj
@@ -19,4 +19,10 @@
+
+
+
+
+
diff --git a/src/PlanViewer.Core/Services/NodeTimeAttribution.cs b/src/PlanViewer.Core/Services/NodeTimeAttribution.cs
index 5e30d1c..67f2821 100644
--- a/src/PlanViewer.Core/Services/NodeTimeAttribution.cs
+++ b/src/PlanViewer.Core/Services/NodeTimeAttribution.cs
@@ -100,6 +100,13 @@ private static long GetChildElapsedMsSum(PlanNode node)
.DefaultIfEmpty(0)
.Max();
}
+ else if ((child.ActualExecutionMode ?? child.ExecutionMode) == "Batch")
+ {
+ // Batch operators report STANDALONE times, so the zone's times add
+ // rather than nest. Taking only this child's value would leave the
+ // rest of the zone inside the parent's "own" time.
+ sum += SumBatchSubtreeElapsedMs(child);
+ }
else if (child.ActualElapsedMs > 0)
{
sum += child.ActualElapsedMs;
@@ -111,4 +118,25 @@ private static long GetChildElapsedMsSum(PlanNode node)
}
return sum;
}
+
+ ///
+ /// Sums elapsed across a contiguous batch-mode zone, stopping at exchange
+ /// boundaries. Mirrors the analysis path in PlanAnalyzer.Timing.
+ ///
+ private static long SumBatchSubtreeElapsedMs(PlanNode node)
+ {
+ long sum = node.ActualElapsedMs;
+ foreach (var child in node.Children)
+ {
+ if (child.PhysicalOp == "Parallelism") continue; // zone boundary
+
+ if ((child.ActualExecutionMode ?? child.ExecutionMode) == "Batch")
+ sum += SumBatchSubtreeElapsedMs(child);
+ else if (child.ActualElapsedMs > 0)
+ sum += child.ActualElapsedMs; // row mode: already cumulative
+ else
+ sum += GetChildElapsedMsSum(child); // pass-through, no stats
+ }
+ return sum;
+ }
}
diff --git a/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs b/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs
index 7d4aaa3..386d188 100644
--- a/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs
+++ b/src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs
@@ -64,36 +64,41 @@ internal static long GetOperatorOwnElapsedMs(PlanNode node)
return GetSerialOwnElapsed(node);
}
+ ///
+ /// Threads that actually did work. In a parallel plan thread 0 is the
+ /// coordinator: it carries no rows, and its ActualElapsedms is the wall clock
+ /// of the whole parallel branch. Including it in a per-thread self-time
+ /// calculation hands the operator the branch's entire duration.
+ /// A serial plan has a single thread numbered 0, which IS a worker, so only
+ /// exclude thread 0 when other threads exist.
+ ///
+ private static List WorkThreads(PlanNode node)
+ {
+ var workers = node.PerThreadStats.Where(t => t.ThreadId > 0).ToList();
+ return workers.Count > 0 ? workers : node.PerThreadStats;
+ }
+
///
/// Per-thread self-time calculation for parallel row mode operators.
- /// For each thread: self = parent_elapsed[t] - sum(children_elapsed[t]).
- /// Returns max across threads.
+ /// For each worker thread: self = parent[t] - sum(effective children[t]).
+ /// Returns max across worker threads.
///
- private static long GetPerThreadOwnElapsed(PlanNode node)
+ private static long GetPerThreadOwnElapsed(PlanNode node) =>
+ GetPerThreadOwn(node, t => t.ActualElapsedMs, n => n.ActualElapsedMs);
+
+ private static long GetPerThreadOwn(
+ PlanNode node,
+ Func pick,
+ Func nodeTotal)
{
- // Build lookup: threadId -> parent elapsed for this node
var parentByThread = new Dictionary();
- foreach (var ts in node.PerThreadStats)
- parentByThread[ts.ThreadId] = ts.ActualElapsedMs;
+ foreach (var ts in WorkThreads(node))
+ parentByThread[ts.ThreadId] = pick(ts);
- // Build lookup: threadId -> sum of all direct children's elapsed
var childSumByThread = new Dictionary();
foreach (var child in node.Children)
- {
- var childNode = child;
+ AddEffectiveChildByThread(child, pick, nodeTotal, childSumByThread);
- // Exchange operators have unreliable times — look through to their child
- if (child.PhysicalOp == "Parallelism" && child.Children.Count > 0)
- childNode = child.Children.OrderByDescending(c => c.ActualElapsedMs).First();
-
- foreach (var ts in childNode.PerThreadStats)
- {
- childSumByThread.TryGetValue(ts.ThreadId, out var existing);
- childSumByThread[ts.ThreadId] = existing + ts.ActualElapsedMs;
- }
- }
-
- // Self-time per thread = parent - children, take max across threads
var maxSelf = 0L;
foreach (var (threadId, parentMs) in parentByThread)
{
@@ -105,6 +110,83 @@ private static long GetPerThreadOwnElapsed(PlanNode node)
return maxSelf;
}
+ ///
+ /// What a child contributes to its parent's per-thread total. The per-thread
+ /// mirror of GetEffectiveChildElapsedMs, and it must look through the same two
+ /// things the serial path does, or the parent absorbs the subtree beneath them:
+ ///
+ /// - A batch-mode child reports STANDALONE time, so only its own value would
+ /// come off and the rest of the batch zone would stay in the parent.
+ /// - A pass-through child (Compute Scalar) carries no runtime stats at all,
+ /// so zero would come off.
+ ///
+ /// Together these crowned a row-mode Nested Loops above a batch Hash Aggregate
+ /// as the hottest operator in its plan, with the aggregate's time counted twice.
+ ///
+ private static void AddEffectiveChildByThread(
+ PlanNode child,
+ Func pick,
+ Func nodeTotal,
+ Dictionary acc)
+ {
+ // Exchange operators have unreliable times — look through to their child.
+ if (child.PhysicalOp == "Parallelism" && child.Children.Count > 0)
+ {
+ var dominant = child.Children.OrderByDescending(nodeTotal).First();
+ AddEffectiveChildByThread(dominant, pick, nodeTotal, acc);
+ return;
+ }
+
+ var mode = child.ActualExecutionMode ?? child.ExecutionMode;
+ if (mode == "Batch" && child.HasActualStats)
+ {
+ AddBatchSubtreeByThread(child, pick, nodeTotal, acc);
+ return;
+ }
+
+ if (child.HasActualStats && nodeTotal(child) > 0)
+ {
+ foreach (var ts in WorkThreads(child))
+ {
+ acc.TryGetValue(ts.ThreadId, out var existing);
+ acc[ts.ThreadId] = existing + pick(ts);
+ }
+ return;
+ }
+
+ // No runtime stats: look through to the descendants that have them.
+ foreach (var grandchild in child.Children)
+ AddEffectiveChildByThread(grandchild, pick, nodeTotal, acc);
+ }
+
+ ///
+ /// Per-thread sum across a contiguous batch-mode zone, stopping at exchanges.
+ /// Batch operators pipeline, so their times add rather than nest.
+ ///
+ private static void AddBatchSubtreeByThread(
+ PlanNode node,
+ Func pick,
+ Func nodeTotal,
+ Dictionary acc)
+ {
+ foreach (var ts in WorkThreads(node))
+ {
+ acc.TryGetValue(ts.ThreadId, out var existing);
+ acc[ts.ThreadId] = existing + pick(ts);
+ }
+
+ foreach (var child in node.Children)
+ {
+ if (child.PhysicalOp == "Parallelism") continue; // zone boundary
+
+ var childMode = child.ActualExecutionMode ?? child.ExecutionMode;
+ if (childMode == "Batch" && child.HasActualStats)
+ AddBatchSubtreeByThread(child, pick, nodeTotal, acc);
+ else
+ AddEffectiveChildByThread(child, pick, nodeTotal, acc);
+ }
+ }
+
///
/// Max per-thread self-CPU for this operator.
/// Parallel: for each thread, self_cpu = thread_cpu - Σ same-thread child cpu; take max.
@@ -116,33 +198,7 @@ internal static long GetOperatorMaxThreadOwnCpuMs(PlanNode node)
if (!node.HasActualStats || node.ActualCPUMs <= 0) return 0;
if (node.PerThreadStats.Count > 1)
- {
- var parentByThread = new Dictionary();
- foreach (var ts in node.PerThreadStats)
- parentByThread[ts.ThreadId] = ts.ActualCPUMs;
-
- var childSumByThread = new Dictionary();
- foreach (var child in node.Children)
- {
- var childNode = child;
- if (child.PhysicalOp == "Parallelism" && child.Children.Count > 0)
- childNode = child.Children.OrderByDescending(c => c.ActualCPUMs).First();
- foreach (var ts in childNode.PerThreadStats)
- {
- childSumByThread.TryGetValue(ts.ThreadId, out var existing);
- childSumByThread[ts.ThreadId] = existing + ts.ActualCPUMs;
- }
- }
-
- var maxSelf = 0L;
- foreach (var (threadId, parentCpu) in parentByThread)
- {
- childSumByThread.TryGetValue(threadId, out var childCpu);
- var self = Math.Max(0, parentCpu - childCpu);
- if (self > maxSelf) maxSelf = self;
- }
- return maxSelf;
- }
+ return GetPerThreadOwn(node, t => t.ActualCPUMs, n => n.ActualCPUMs);
// Serial: operator_cpu - Σ effective child cpu
var totalChildCpu = 0L;
diff --git a/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs b/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs
index 0842010..e47bf19 100644
--- a/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs
+++ b/src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs
@@ -675,7 +675,13 @@ private static void ParseRuntimeInformation(PlanNode node, XElement relOpEl)
node.HasActualStats = true;
long totalRows = 0, totalExecutions = 0, totalRowsRead = 0;
long totalRebinds = 0, totalRewinds = 0;
- long maxElapsed = 0, totalCpu = 0;
+ // Elapsed takes the max across threads, but thread 0 is the coordinator
+ // in a parallel plan: no rows, and an elapsed equal to the whole parallel
+ // branch's wall clock. Taking the max over it makes every operator in the
+ // branch look like it took the branch's entire duration. A serial plan has
+ // one thread numbered 0, which is a worker, so fall back to it.
+ long maxElapsed = 0, maxWorkerElapsed = 0, totalCpu = 0;
+ var sawWorkerThread = false;
long totalLogicalReads = 0, totalPhysicalReads = 0;
long totalScans = 0, totalReadAheads = 0;
long totalLobLogicalReads = 0, totalLobPhysicalReads = 0, totalLobReadAheads = 0;
@@ -721,6 +727,13 @@ private static void ParseRuntimeInformation(PlanNode node, XElement relOpEl)
var elapsed = ParseLong(thread.Attribute("ActualElapsedms")?.Value);
if (elapsed > maxElapsed) maxElapsed = elapsed;
+
+ var threadId = (int)ParseDouble(thread.Attribute("Thread")?.Value);
+ if (threadId > 0)
+ {
+ sawWorkerThread = true;
+ if (elapsed > maxWorkerElapsed) maxWorkerElapsed = elapsed;
+ }
}
node.ActualRows = totalRows;
@@ -728,7 +741,7 @@ private static void ParseRuntimeInformation(PlanNode node, XElement relOpEl)
node.ActualRowsRead = totalRowsRead;
node.ActualRebinds = totalRebinds;
node.ActualRewinds = totalRewinds;
- node.ActualElapsedMs = maxElapsed;
+ node.ActualElapsedMs = sawWorkerThread ? maxWorkerElapsed : maxElapsed;
node.ActualCPUMs = totalCpu;
node.ActualLogicalReads = totalLogicalReads;
node.ActualPhysicalReads = totalPhysicalReads;
diff --git a/tests/PlanViewer.Core.Tests/OperatorSelfTimeTests.cs b/tests/PlanViewer.Core.Tests/OperatorSelfTimeTests.cs
new file mode 100644
index 0000000..2fd184e
--- /dev/null
+++ b/tests/PlanViewer.Core.Tests/OperatorSelfTimeTests.cs
@@ -0,0 +1,134 @@
+using System.Linq;
+using PlanViewer.Core.Models;
+using PlanViewer.Core.Services;
+
+namespace PlanViewer.Core.Tests;
+
+///
+/// Self-time attribution for parallel operators.
+///
+/// Two traps, both of which inflated a parent operator until it was reported as
+/// the hottest in its plan:
+///
+/// 1. Thread 0 is the coordinator. It carries no rows, and its ActualElapsedms
+/// is the wall clock of the whole parallel branch.
+/// 2. A row-mode parent above a batch-mode subtree, or above a pass-through
+/// operator with no runtime stats, subtracted too little from itself.
+///
+public class OperatorSelfTimeTests
+{
+ private static PlanNode? TryFindNode(PlanNode root, int nodeId)
+ {
+ if (root.NodeId == nodeId) return root;
+ foreach (var child in root.Children)
+ {
+ var found = TryFindNode(child, nodeId);
+ if (found is not null) return found;
+ }
+ return null;
+ }
+
+ ///
+ /// The statement's RootNode is a synthetic wrapper (NodeId -1). The plan's
+ /// real root operator is its first child.
+ ///
+ private static PlanNode RootOf(string planFile)
+ {
+ var plan = PlanTestHelper.LoadAndAnalyze(planFile);
+ var wrapper = plan.Batches[0].Statements[0].RootNode!;
+ return wrapper.NodeId < 0 ? wrapper.Children[0] : wrapper;
+ }
+
+ [Fact]
+ public void CoordinatorThreadIsNotCountedAsOperatorElapsedTime()
+ {
+ var root = RootOf("parallel_row_over_batch_plan.sqlplan");
+
+ // Thread 0 reports 1000ms (the branch's wall clock) with zero rows. The
+ // slowest worker also reports 1000ms here, so the node-level number is the
+ // same -- what matters is that we source it from a worker, not the
+ // coordinator, and that the coordinator never wins a max on its own.
+ var coordinator = root.PerThreadStats.Single(t => t.ThreadId == 0);
+ Assert.Equal(0, coordinator.ActualRows);
+ Assert.Equal(1000, coordinator.ActualElapsedMs);
+
+ // The Columnstore scan's coordinator row is 0ms while its workers are 0ms
+ // too, but the Hash Match's coordinator is 0ms and workers are 900/890.
+ var hashMatch = TryFindNode(root, 2)!;
+ Assert.Equal(900, hashMatch.ActualElapsedMs); // max over WORKERS, not thread 0
+ }
+
+ [Fact]
+ public void RowModeParentAboveBatchSubtreeDoesNotAbsorbIt()
+ {
+ var root = RootOf("parallel_row_over_batch_plan.sqlplan");
+
+ // Node 0 is a parallel row-mode Nested Loops. Slowest worker: 1000ms.
+ // Beneath it: a batch Compute Scalar (0ms) hiding a batch Hash Match
+ // (900ms), plus a row-mode Index Seek (50ms).
+ //
+ // Correct self time = 1000 - (0 + 900) - 50 = 50ms.
+ // Before the fix this reported 1000ms: the pass-through contributed
+ // nothing, the batch zone contributed only its topmost value, and the
+ // coordinator's 1000ms won the per-thread max outright.
+ var own = PlanAnalyzer.GetOperatorOwnElapsedMs(root);
+ Assert.InRange(own, 40, 60);
+ }
+
+ [Fact]
+ public void RowModeParentAboveBatchSubtreeDoesNotAbsorbItsCpu()
+ {
+ var root = RootOf("parallel_row_over_batch_plan.sqlplan");
+
+ // Busiest worker CPU on node 0 is 30ms. Beneath it, per that same thread:
+ // batch zone 0 + 12 = 12ms, row seek 6ms. Self CPU = 30 - 18 = 12ms.
+ var ownCpu = PlanAnalyzer.GetOperatorMaxThreadOwnCpuMs(root);
+ Assert.InRange(ownCpu, 8, 16);
+ }
+
+ [Fact]
+ public void BatchOperatorKeepsItsStandaloneTime()
+ {
+ var root = RootOf("parallel_row_over_batch_plan.sqlplan");
+ var hashMatch = TryFindNode(root, 2)!;
+
+ // Batch mode reports self time directly. Subtracting children would
+ // underflow it.
+ Assert.Equal(900, PlanAnalyzer.GetOperatorOwnElapsedMs(hashMatch));
+ }
+
+ [Fact]
+ public void ParallelPassThroughChildDoesNotInflateItsParent()
+ {
+ // join_or_clause_plan has a parallel row-mode TopN Sort above a Compute
+ // Scalar that carries no runtime statistics. Subtracting zero for it made
+ // the sort absorb everything below.
+ var root = RootOf("join_or_clause_plan.sqlplan");
+ var sort = TryFindNode(root, 8);
+ Assert.NotNull(sort);
+
+ var own = PlanAnalyzer.GetOperatorOwnElapsedMs(sort!);
+ var cumulative = sort!.ActualElapsedMs;
+
+ // Self time must be strictly less than cumulative: the subtree below it
+ // did real work, and that work is not the sort's own.
+ Assert.True(
+ own < cumulative,
+ $"sort reported {own}ms self of {cumulative}ms cumulative -- it absorbed its subtree");
+ }
+
+ [Fact]
+ public void SerialPlanStillUsesItsOnlyThread()
+ {
+ // A serial plan has a single thread numbered 0. It is a worker, not a
+ // coordinator, and excluding it would zero out every operator.
+ var root = RootOf("key_lookup_plan.sqlplan");
+ var withStats = TryFindNode(root, 0);
+ Assert.NotNull(withStats);
+ if (withStats!.HasActualStats && withStats.PerThreadStats.Count == 1)
+ {
+ Assert.Equal(0, withStats.PerThreadStats[0].ThreadId);
+ Assert.True(withStats.ActualElapsedMs >= 0);
+ }
+ }
+}
diff --git a/tests/PlanViewer.Core.Tests/Plans/parallel_row_over_batch_plan.sqlplan b/tests/PlanViewer.Core.Tests/Plans/parallel_row_over_batch_plan.sqlplan
new file mode 100644
index 0000000..ff47cd9
--- /dev/null
+++ b/tests/PlanViewer.Core.Tests/Plans/parallel_row_over_batch_plan.sqlplan
@@ -0,0 +1,85 @@
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
diff --git a/tests/PlanViewer.Core.Tests/WarningBaseline.txt b/tests/PlanViewer.Core.Tests/WarningBaseline.txt
index 5640f74..322cf24 100644
--- a/tests/PlanViewer.Core.Tests/WarningBaseline.txt
+++ b/tests/PlanViewer.Core.Tests/WarningBaseline.txt
@@ -93,7 +93,7 @@ Filter Operator | Warning | Filter operator discarding rows late in the plan.\n
Nested Loops High Executions | Critical | Nested Loops inner side executed 17,091,572 times (DOP 8). Inner side total: 93,279,732 logical reads. Inner side time: 30,655ms (93% of statement). Consider whether a hash or merge join would be more appropriate for this row count.
Scan With Predicate | Warning | Scan with residual predicate — SQL Server is reading every row and filtering after the fact. Check that you have appropriate indexes.\nPredicate: [StackOverflow2013].[dbo].[Posts].[PostTypeId] as [p].[PostTypeId]=(1) OR [StackOverflow2013].[dbo].[Posts].[PostTypeId] as [p].[PostTypeId]=(2)
Nested Loops High Executions | Critical | Nested Loops inner side executed 30,700,008 times (DOP 8). Inner side total: 93,279,732 logical reads. Inner side time: 14,355ms (43% of statement). Consider whether a hash or merge join would be more appropriate for this row count.
-Expensive Operator | Critical | Sort took 19,602ms (59.3% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be?
+Expensive Operator | Critical | Sort took 18,580ms (56.2% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be?
Join OR Clause | Warning | OR in a join predicate. SQL Server rewrote the OR as 2 separate lookups, each evaluated independently — this multiplies the work on the inner side. Rewrite as separate queries joined with UNION ALL. For example, change "FROM a JOIN b ON a.x = b.x OR a.y = b.y" to "FROM a JOIN b ON a.x = b.x UNION ALL FROM a JOIN b ON a.y = b.y".
Expensive Operator | Warning | Clustered Index Seek took 14,355ms (43.4% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be?
@@ -210,6 +210,10 @@ Row Estimate Mismatch | Critical | Estimated 5,292,870 vs Actual 53,946 (13,486
Parallel Skew | Warning | Thread 3 processed 100% of rows (53,946/53,946). Work is heavily skewed to one thread, so parallelism isn't helping much. Common causes: uneven data distribution across partitions or hash buckets, or a scan/seek whose predicate sends most rows to one range. Reducing DOP or rewriting the query to avoid the skewed operation may help.
Bare Scan | Warning | Clustered index scan reads the full table with no predicate, outputting 1 column(s): Votes.PostId. Consider a nonclustered index on the output columns (as key or INCLUDE) so SQL Server can read a narrower structure. For analytical workloads, a columnstore index may be a better fit.
+### parallel_row_over_batch_plan.sqlplan
+Standard Edition DOP Limitation | Info | DOP is limited to 2 and the plan uses batch mode operators. This may be caused by the SQL Server Standard Edition limitation, which caps parallelism at 2 when batch mode is in use. If this server runs Standard Edition, Developer or Enterprise Edition would allow higher DOP.
+Expensive Operator | Critical | Hash Match took 900ms (90.0% of statement elapsed) but no specific rule identified a fix. Worth investigating: is the row volume necessary? Are upstream estimates driving this operator harder than it should be?
+
### param-sniffing-posttypeid2.sqlplan
Wait: RESERVED_MEMORY_ALLOCATION_EXT | Info | RESERVED_MEMORY_ALLOCATION_EXT Observed 1,051 ms across 2,052,049 waits.
Wait: SOS_SCHEDULER_YIELD | Info | SOS_SCHEDULER_YIELD Observed 6 ms across 4,481 waits.