Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions src/PlanViewer.Core/PlanViewer.Core.csproj
Original file line number Diff line number Diff line change
Expand Up @@ -19,4 +19,10 @@
<EmbeddedResource Include="Resources\WaitStats.json" />
</ItemGroup>

<ItemGroup>
<!-- Self-time attribution (PlanAnalyzer.Timing) is internal but is the
source of every operator timing the UI and BenefitScorer report. -->
<InternalsVisibleTo Include="PlanViewer.Core.Tests" />
</ItemGroup>

</Project>
28 changes: 28 additions & 0 deletions src/PlanViewer.Core/Services/NodeTimeAttribution.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -111,4 +118,25 @@ private static long GetChildElapsedMsSum(PlanNode node)
}
return sum;
}

/// <summary>
/// Sums elapsed across a contiguous batch-mode zone, stopping at exchange
/// boundaries. Mirrors the analysis path in PlanAnalyzer.Timing.
/// </summary>
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;
}
}
152 changes: 104 additions & 48 deletions src/PlanViewer.Core/Services/PlanAnalyzer.Timing.cs
Original file line number Diff line number Diff line change
Expand Up @@ -64,36 +64,41 @@ internal static long GetOperatorOwnElapsedMs(PlanNode node)
return GetSerialOwnElapsed(node);
}

/// <summary>
/// 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.
/// </summary>
private static List<PerThreadRuntimeInfo> WorkThreads(PlanNode node)
{
var workers = node.PerThreadStats.Where(t => t.ThreadId > 0).ToList();
return workers.Count > 0 ? workers : node.PerThreadStats;
}

/// <summary>
/// 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.
/// </summary>
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<PerThreadRuntimeInfo, long> pick,
Func<PlanNode, long> nodeTotal)
{
// Build lookup: threadId -> parent elapsed for this node
var parentByThread = new Dictionary<int, long>();
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<int, long>();
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)
{
Expand All @@ -105,6 +110,83 @@ private static long GetPerThreadOwnElapsed(PlanNode node)
return maxSelf;
}

/// <summary>
/// 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.
/// </summary>
private static void AddEffectiveChildByThread(
PlanNode child,
Func<PerThreadRuntimeInfo, long> pick,
Func<PlanNode, long> nodeTotal,
Dictionary<int, long> 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);
}

/// <summary>
/// Per-thread sum across a contiguous batch-mode zone, stopping at exchanges.
/// Batch operators pipeline, so their times add rather than nest.
/// </summary>
private static void AddBatchSubtreeByThread(
PlanNode node,
Func<PerThreadRuntimeInfo, long> pick,
Func<PlanNode, long> nodeTotal,
Dictionary<int, long> 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);
}
}

/// <summary>
/// Max per-thread self-CPU for this operator.
/// Parallel: for each thread, self_cpu = thread_cpu - Σ same-thread child cpu; take max.
Expand All @@ -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<int, long>();
foreach (var ts in node.PerThreadStats)
parentByThread[ts.ThreadId] = ts.ActualCPUMs;

var childSumByThread = new Dictionary<int, long>();
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;
Expand Down
17 changes: 15 additions & 2 deletions src/PlanViewer.Core/Services/ShowPlanParser.RelOp.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -721,14 +727,21 @@ 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;
node.ActualExecutions = totalExecutions;
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;
Expand Down
Loading
Loading