From 5a062d04380981c55aef607fbfa86ebc051b1d00 Mon Sep 17 00:00:00 2001 From: Jeremy Kuhne Date: Tue, 29 Sep 2026 16:08:57 -0700 Subject: [PATCH 1/3] Qualify SampleProfiler CPU evidence and preserve loss warnings Distinguish SampleProfiler thread-stack counts from established ETW CPU time, qualify CPU-facing guidance, and retain capture-loss warnings when manifest case outputs are bounded. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/workflow.md | 13 ++ src/Filtrace.Core/Output/SteeringHints.cs | 54 +++++- .../Tracing/CaptureManifestBatchAnalyzer.cs | 7 +- .../Tracing/CaptureManifestDiffAnalyzer.cs | 9 +- .../Tracing/CaptureManifestOutput.cs | 56 ++++++ .../Tracing/CpuSampleProvenance.cs | 5 +- .../Providers/ProcessInventoryProvider.cs | 63 +------ .../Providers/TimelineProvider.EventLanes.cs | 4 +- .../Providers/TimelineProvider.Snapshot.cs | 5 +- .../Tracing/Providers/TimelineProvider.cs | 8 +- .../Tracing/Providers/TimelineResult.cs | 7 + .../Tracing/Readers/CpuSampleEvidence.cs | 166 ++++++++++++++++++ .../Tracing/Readers/TraceLogReader.cs | 86 +++------ .../Tracing/Readers/TraceReadResult.cs | 5 + src/Filtrace.Core/Tracing/TraceInfo.cs | 6 + src/Filtrace.Core/Tracing/TraceLoader.cs | 9 +- src/Filtrace.Mcp/TraceTools.cs | 7 +- src/Filtrace/Cli/RankingExecutor.cs | 3 +- src/Filtrace/Cli/TimelineExecutor.cs | 4 + tests/Filtrace.Cli.Tests/CliAppTests.cs | 57 +++++- tests/Filtrace.Cli.Tests/DiffExecutorTests.cs | 2 + .../RankingExecutorTests.cs | 9 +- .../Filtrace.Core.Tests/ActivityScopeTests.cs | 3 + .../CaptureManifestReaderTests.cs | 118 ++++++++++++- .../CpuSampleEvidenceTests.cs | 72 ++++++++ .../ProcessInventoryProviderTests.cs | 7 + .../Filtrace.Core.Tests/SteeringHintsTests.cs | 57 ++++++ .../TimelineProviderTests.cs | 4 + tests/Filtrace.Core.Tests/TraceLoaderTests.cs | 6 +- tests/Filtrace.Mcp.Tests/TraceToolsTests.cs | 67 ++++++- 30 files changed, 766 insertions(+), 153 deletions(-) create mode 100644 src/Filtrace.Core/Tracing/Readers/CpuSampleEvidence.cs create mode 100644 tests/Filtrace.Core.Tests/CpuSampleEvidenceTests.cs diff --git a/docs/workflow.md b/docs/workflow.md index 5c472076..7efc7aed 100644 --- a/docs/workflow.md +++ b/docs/workflow.md @@ -715,6 +715,19 @@ cleanly and stays cheap in tokens. scope. CPU units are analyzer-version dependent: call them milliseconds only when recorded interval provenance and interval-aware weighting are established; otherwise use qualified sample counts/weights. Never derive CPU time from wall clock times share. + SampleProfiler thread-stack samples in EventPipe captures may include waiting or + native execution; `cpuSampling.source: sampleprofiler` identifies their raw counts, + not on-core CPU time or a blocked-time percentage. A result mixing those samples + with ETW sampled-profile records uses counts for both (`mixed-etw-sampleprofiler`), + even when the ETW subset has a recorded interval. CPU-derived CLI and MCP results + warn on the selected SampleProfiler evidence and qualify CPU-focused hints. Use + ETW PerfInfo sampling when the question requires on-core CPU time; do not equate + SampleProfiler `External` events with blocked time. + Counts from a mixed-provider result need not be comparable across samplers; do + not treat their combined share as a CPU-time comparison. + Bounded manifest batch/diff cases reserve lost-event and SampleProfiler + advisories before lower-priority warnings for each arm; inspect a direct trace + when the four-warning case budget omits further quality detail. - Keep counts separate from weight. `trace_info.sampleCount` describes the loaded whole trace after process/activity/time filters; it does not establish that a narrower root/method/file query is well sampled. Stack rankings and callers expose diff --git a/src/Filtrace.Core/Output/SteeringHints.cs b/src/Filtrace.Core/Output/SteeringHints.cs index dd804b02..3dc786fc 100644 --- a/src/Filtrace.Core/Output/SteeringHints.cs +++ b/src/Filtrace.Core/Output/SteeringHints.cs @@ -5,6 +5,7 @@ using System.Globalization; using Filtrace.Tracing; using Filtrace.Tracing.Providers; +using Filtrace.Tracing.Readers; namespace Filtrace.Output; @@ -144,7 +145,12 @@ public static IReadOnlyList ForTraceInfo(TraceInfo info) // keeps manually constructed legacy TraceInfo objects useful, but labels those // routes as format-supported because they carry no capture evidence. List routes = []; - if (analyses.Contains("cpu")) { routes.Add("CPU-bound -> cpu"); } + if (analyses.Contains("cpu")) + { + routes.Add(CpuSampleEvidence.ContainsSampleProfiler(info.CpuSampling) + ? "sampled thread stacks (not on-core CPU time) -> cpu" + : "CPU-bound -> cpu"); + } List blocked = []; if (analyses.Contains("contention")) { blocked.Add("contention"); } @@ -285,7 +291,32 @@ public static IReadOnlyList ForRanking( ScopeRequest? scope = null, string? path = null, string? symbols = null, - bool nativeSymbols = false) + bool nativeSymbols = false) => + ForRanking(ranking, metric, scope, path, symbols, nativeSymbols, cpuSampling: null); + + /// + /// The next-step hints for a ranking with its CPU sample provenance, preserving + /// its metric and scope without calling thread-stack samples on-core CPU time. + /// + /// The ranking the hints steer from. + /// The metric the ranking carries. + /// Optional process, activity, and time scope of the ranking. + /// The trace path for a complete quality follow-up. + /// The local symbol directory, if any. + /// Whether native symbol resolution was enabled. + /// The CPU sample provenance, if applicable. + /// The hints and complete follow-ups, never . + /// + /// or is . + /// + public static IReadOnlyList ForRanking( + RankingResult ranking, + MetricInfo metric, + ScopeRequest? scope, + string? path, + string? symbols, + bool nativeSymbols, + CpuSampleProvenance? cpuSampling) { ArgumentNullException.ThrowIfNull(ranking); ArgumentNullException.ThrowIfNull(metric); @@ -305,8 +336,12 @@ public static IReadOnlyList ForRanking( if (scope?.ActivityName is not null || scope?.Window is not null) { + string kind = CpuSampleEvidence.ContainsSampleProfiler(cpuSampling) + ? "sampled-thread stack" + : "CPU"; + string reason = - "this CPU ranking is activity/time-scoped; callers, lines, heatmap, and tree cannot preserve that slice - refine it with self/inclusive measure or root in rank"; + $"this {kind} ranking is activity/time-scoped; callers, lines, heatmap, and tree cannot preserve that slice - refine it with self/inclusive measure or root in rank"; if (IsUnresolvedFrame(ranking.Rows[0].Frame)) { @@ -356,7 +391,10 @@ public static IReadOnlyList ForRanking( ]); } - string hint = $"drill into the hot frame with: callers {ranking.Rows[0].Frame}"; + string hint = CpuSampleEvidence.ContainsSampleProfiler(cpuSampling) + ? $"drill into the most sampled frame with: callers {ranking.Rows[0].Frame}" + : $"drill into the hot frame with: callers {ranking.Rows[0].Frame}"; + string message = PreserveLocalSymbols( PreserveCpuScope(hint, ranking.RootFrame, scope), symbols); @@ -796,7 +834,9 @@ public static IReadOnlyList ForTimeline(TimelineResult timeline) string window = $"{FormatMs(timeline.FromMs)}-{FormatMs(timeline.ToMs)} ms"; if (snapshot.Cpu.SampleCount > 0) { - return SnapshotDrillGuidance("CPU work", "cpu", timeline, window); + return SnapshotDrillGuidance( + timeline.CpuSampleWarning is null ? "CPU work" : "sampled thread stacks", + "cpu", timeline, window); } if (snapshot.Alloc.Types.Count > 0) @@ -817,7 +857,9 @@ public static IReadOnlyList ForTimeline(TimelineResult timeline) // nothing to point at, so it is skipped. if (TryPeakBucket(timeline.Cpu, static bucket => bucket.SampleCount, out int cpuIndex)) { - return DrillWindowGuidance("CPU", "cpu", timeline, cpuIndex); + return DrillWindowGuidance( + timeline.CpuSampleWarning is null ? "CPU" : "thread-stack sample", + "cpu", timeline, cpuIndex); } if (TryPeakBucket(timeline.Alloc, static bucket => bucket.Count, out int allocIndex)) diff --git a/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs b/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs index be418068..3b5607fc 100644 --- a/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs +++ b/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs @@ -191,10 +191,9 @@ private static void AddQualityWarnings( RankingResult ranking, string root) { - foreach (string warning in trace.Info.Warnings.Take(4)) - { - CaptureManifestOutput.AddWarning(warnings, warning); - } + CaptureManifestOutput.AddEventLossWarning(warnings, trace.Info); + CaptureManifestOutput.AddCpuSampleWarning(warnings, trace.Info); + CaptureManifestOutput.AddOtherTraceWarnings(warnings, trace.Info); if (ContributingRecordQuality.TryGetMethodWarning( trace.Source.RecordSemantics, diff --git a/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs b/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs index 8fa7fd5c..e8bd63e6 100644 --- a/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs +++ b/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs @@ -96,6 +96,10 @@ public static CaptureManifestDiffAnalysis Analyze( root, foldPatterns); + CaptureManifestOutput.AddEventLossWarning(caseWarnings, beforeTrace.Info, "baseline"); + CaptureManifestOutput.AddEventLossWarning(caseWarnings, afterTrace.Info, "current"); + CaptureManifestOutput.AddCpuSampleWarning(caseWarnings, beforeTrace.Info, "baseline"); + CaptureManifestOutput.AddCpuSampleWarning(caseWarnings, afterTrace.Info, "current"); AddQualityWarnings(caseWarnings, "baseline", beforeTrace, beforeRanking, root); AddQualityWarnings(caseWarnings, "current", afterTrace, afterRanking, root); RankingDiffResult diff = Diff( @@ -258,10 +262,7 @@ private static void AddQualityWarnings( RankingResult ranking, string root) { - foreach (string warning in trace.Info.Warnings.Take(4)) - { - CaptureManifestOutput.AddWarning(warnings, $"{side}: {warning}"); - } + CaptureManifestOutput.AddOtherTraceWarnings(warnings, trace.Info, side); if (ContributingRecordQuality.TryGetMethodWarning( trace.Source.RecordSemantics, diff --git a/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs b/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs index 02500632..2f13193b 100644 --- a/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs +++ b/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs @@ -2,6 +2,8 @@ // SPDX-License-Identifier: MIT // See LICENSE file in the project root for full license information +using Filtrace.Tracing.Readers; + namespace Filtrace.Tracing; /// @@ -37,6 +39,60 @@ public static void AddWarning(List warnings, string warning) } } + /// + /// Reserves a bounded case warning for contributing SampleProfiler records. + /// + /// The case warnings to append to. + /// The analyzed trace and its CPU sample provenance. + /// The diff arm label, or for batch. + public static void AddCpuSampleWarning(List warnings, TraceInfo info, string? side = null) + { + if (CpuSampleEvidence.WarningFor(info.CpuSampling) is string sampleWarning) + { + AddWarning(warnings, side is null ? sampleWarning : $"{side}: {sampleWarning}"); + } + } + + /// + /// Reserves a bounded case warning for incomplete capture evidence. + /// + /// The case warnings to append to. + /// The trace and its lost-event count. + /// The diff arm label, or for batch. + public static void AddEventLossWarning(List warnings, TraceInfo info, string? side = null) + { + if (TraceLogReader.EventLossWarning(info.EventsLost) is string lossWarning) + { + AddWarning(warnings, side is null ? lossWarning : $"{side}: {lossWarning}"); + } + } + + /// + /// Adds other trace-quality warnings after the reserved SampleProfiler warning. + /// + /// The case warnings to append to. + /// The analyzed trace and its quality warnings. + /// The diff arm label, or for batch. + public static void AddOtherTraceWarnings(List warnings, TraceInfo info, string? side = null) + { + string? sampleWarning = CpuSampleEvidence.WarningFor(info.CpuSampling); + string? lossWarning = TraceLogReader.EventLossWarning(info.EventsLost); + foreach (string warning in info.Warnings.Take(MaxWarningsPerCase)) + { + if (string.Equals(warning, sampleWarning, StringComparison.Ordinal) + || string.Equals(warning, lossWarning, StringComparison.Ordinal)) + { + continue; + } + + AddWarning(warnings, side is null ? warning : $"{side}: {warning}"); + if (warnings.Count == MaxWarningsPerCase) + { + break; + } + } + } + /// /// Replaces control characters and shortens a frame name without splitting a surrogate pair. /// diff --git a/src/Filtrace.Core/Tracing/CpuSampleProvenance.cs b/src/Filtrace.Core/Tracing/CpuSampleProvenance.cs index c82de03e..3a3414ef 100644 --- a/src/Filtrace.Core/Tracing/CpuSampleProvenance.cs +++ b/src/Filtrace.Core/Tracing/CpuSampleProvenance.cs @@ -11,12 +11,13 @@ namespace Filtrace.Tracing; /// those weights can be interpreted as time. /// /// The unit used by CPU sample weights. -/// The trace evidence from which the weights were derived. +/// The sample provider or recorded interval evidence from which the weights were derived. /// /// Whether the trace establishes a time weight for every included CPU sample. /// /// -/// Number of included periodic CPU samples for which no interval was recorded. +/// Number of included samples without an applicable ETW PerfInfo interval, including +/// any SampleProfiler thread-stack samples. /// /// Trace-recorded ETW timer intervals associated with included samples. public sealed record CpuSampleProvenance( diff --git a/src/Filtrace.Core/Tracing/Providers/ProcessInventoryProvider.cs b/src/Filtrace.Core/Tracing/Providers/ProcessInventoryProvider.cs index e1bac7bd..ffc6a645 100644 --- a/src/Filtrace.Core/Tracing/Providers/ProcessInventoryProvider.cs +++ b/src/Filtrace.Core/Tracing/Providers/ProcessInventoryProvider.cs @@ -2,7 +2,6 @@ // SPDX-License-Identifier: MIT // See LICENSE file in the project root for full license information -using System.Globalization; using Filtrace.Tracing.Readers; namespace Filtrace.Tracing.Providers; @@ -71,6 +70,7 @@ private static ProcessInventorySnapshot ReadTraceLog( Dictionary processLabels = []; Dictionary byProcess = new(StringComparer.Ordinal); CpuSampleWeighting? cpuWeighting = format == TraceFormat.Etl ? new() : null; + CpuSampleEvidence cpuSamples = default; int totalSamples = 0; foreach (TraceEvent data in traceLog.Events) @@ -115,7 +115,7 @@ private static ProcessInventorySnapshot ReadTraceLog( ?? ProcessLabelCacheEntry.CreateLabel(processId, processName); (int Count, double Weight) accumulated = byProcess.GetValueOrDefault(process); - double weight = cpuWeighting?.GetSampleWeight() ?? 1.0; + double weight = cpuSamples.GetSampleWeight(cpuWeighting, data is ClrThreadSampleTraceData); byProcess[process] = ( AnalysisEventCounter.SaturatingIncrement(accumulated.Count), accumulated.Weight + weight); @@ -123,9 +123,9 @@ private static ProcessInventorySnapshot ReadTraceLog( totalSamples = AnalysisEventCounter.SaturatingIncrement(totalSamples); } - bool timeWeightsEstablished = cpuWeighting?.HasCompleteIntervalEvidence == true; + CpuSampleProvenance cpuSampling = cpuSamples.CreateProvenance(cpuWeighting, totalSamples); + bool timeWeightsEstablished = cpuSampling.TimeWeightsEstablished; MetricInfo metric = timeWeightsEstablished ? MetricInfo.Cpu : MetricInfo.CpuSamples; - CpuSampleProvenance cpuSampling = CreateCpuSampling(cpuWeighting, totalSamples); List processes = new(byProcess.Count); double totalWeight = 0.0; foreach (KeyValuePair entry in byProcess) @@ -152,7 +152,7 @@ private static ProcessInventorySnapshot ReadTraceLog( List warnings = []; TraceLogReader.AddEventLossWarning(warnings, traceLog.EventsLost); - AddCpuWarnings(warnings, cpuWeighting, cpuSampling, totalSamples); + cpuSamples.AddWarnings(warnings, cpuWeighting, cpuSampling, totalSamples); _ = CaptureMetadataReader.Read(path, warnings); if (totalSamples == 0) { @@ -170,57 +170,4 @@ private static ProcessInventorySnapshot ReadTraceLog( cacheState); } - private static CpuSampleProvenance CreateCpuSampling( - CpuSampleWeighting? weighting, - int sampleCount) - { - if (weighting is null) - { - return new CpuSampleProvenance( - "samples", - "unavailable", - TimeWeightsEstablished: false, - UnknownIntervalSampleCount: sampleCount, - Intervals: []); - } - - bool established = weighting.HasCompleteIntervalEvidence; - return new CpuSampleProvenance( - established ? "ms" : "samples", - weighting.Intervals.Count > 0 ? "etw-perfinfo" : "unavailable", - established, - weighting.UnknownIntervalSampleCount, - weighting.Intervals) - { - OmittedIntervalSegmentCount = weighting.OmittedIntervalSegmentCount, - OmittedIntervalSampleCount = weighting.OmittedIntervalSampleCount, - IntervalsTruncated = weighting.OmittedIntervalSegmentCount > 0 - }; - } - - private static void AddCpuWarnings( - List warnings, - CpuSampleWeighting? weighting, - CpuSampleProvenance provenance, - int sampleCount) - { - if (provenance.TimeWeightsEstablished) - { - warnings.Add( - provenance.Intervals.Count == 1 - ? $"CPU sample weights use the trace-recorded ETW PerfInfo interval ({provenance.Intervals[0].IntervalMSec.ToString("0.####", CultureInfo.InvariantCulture)} ms)." - : "CPU sample weights use the trace-recorded ETW PerfInfo interval active at each sample; the interval changed during the trace."); - } - else if (sampleCount > 0) - { - warnings.Add( - "CPU sampling interval is not recorded for every included sample; CPU weights are raw sample counts, not milliseconds."); - } - - if (weighting?.OmittedIntervalSegmentCount > 0) - { - warnings.Add( - $"CPU sampling provenance retained the first {weighting.Intervals.Count} interval segments and omitted {weighting.OmittedIntervalSegmentCount} later segments covering {weighting.OmittedIntervalSampleCount} samples."); - } - } } diff --git a/src/Filtrace.Core/Tracing/Providers/TimelineProvider.EventLanes.cs b/src/Filtrace.Core/Tracing/Providers/TimelineProvider.EventLanes.cs index 3e28ecfc..2b2c9290 100644 --- a/src/Filtrace.Core/Tracing/Providers/TimelineProvider.EventLanes.cs +++ b/src/Filtrace.Core/Tracing/Providers/TimelineProvider.EventLanes.cs @@ -13,9 +13,11 @@ public sealed partial class TimelineProvider /// Exception-count buckets, or when not requested. /// Allocation buckets, or when not requested. /// JIT compilation buckets, or when not requested. + /// A warning when the CPU lane contains SampleProfiler records. private readonly record struct EventLanes( IReadOnlyList? Cpu, IReadOnlyList? Exceptions, IReadOnlyList? Alloc, - IReadOnlyList? Jit); + IReadOnlyList? Jit, + string? CpuSampleWarning); } diff --git a/src/Filtrace.Core/Tracing/Providers/TimelineProvider.Snapshot.cs b/src/Filtrace.Core/Tracing/Providers/TimelineProvider.Snapshot.cs index 20ac3186..00540d27 100644 --- a/src/Filtrace.Core/Tracing/Providers/TimelineProvider.Snapshot.cs +++ b/src/Filtrace.Core/Tracing/Providers/TimelineProvider.Snapshot.cs @@ -130,6 +130,7 @@ public TimelineResult ReadSnapshot( Dictionary pauseStarts = []; List pauseIntervals = []; SnapshotGcCollector gcCollector = new(startMs, endMs); + CpuSampleEvidence cpuSamples = default; bool detailTruncated = false; bool gcPauseDataIncomplete = false; bool unknownPauseDataIncomplete = false; @@ -215,7 +216,8 @@ public TimelineResult ReadSnapshot( Mode = "snapshot", Snapshot = snapshot, AppliedProcessScope = FollowUpProcessScope(resolved), - ScopeWarnings = resolved.Warnings + ScopeWarnings = resolved.Warnings, + CpuSampleWarning = cpuSamples.Warning }; void Accumulate(TraceEvent data) @@ -339,6 +341,7 @@ void Accumulate(TraceEvent data) break; } + cpuSamples.ObserveSample(data is ClrThreadSampleTraceData); cpuSampleCount++; TraceCodeAddress? leafAddress = LeafCodeAddress(stack); if (leafAddress is not null diff --git a/src/Filtrace.Core/Tracing/Providers/TimelineProvider.cs b/src/Filtrace.Core/Tracing/Providers/TimelineProvider.cs index d1c13a56..8ddc5750 100644 --- a/src/Filtrace.Core/Tracing/Providers/TimelineProvider.cs +++ b/src/Filtrace.Core/Tracing/Providers/TimelineProvider.cs @@ -240,7 +240,8 @@ public TimelineResult Read( eventLanes.Jit) { AppliedProcessScope = FollowUpProcessScope(resolved), - ScopeWarnings = resolved.Warnings + ScopeWarnings = resolved.Warnings, + CpuSampleWarning = eventLanes.CpuSampleWarning }; } @@ -292,6 +293,7 @@ private static (IReadOnlyList? Gc, EventLanes Events) BuildLanes( long[]? allocCount = wantAlloc ? new long[buckets] : null; long[]? allocBytes = wantAlloc ? new long[buckets] : null; int[]? jitCount = wantJit ? new int[buckets] : null; + CpuSampleEvidence cpuSamples = default; HashSet? scopedAnalysisProcessIndexes = wantGc && resolvedScope.ProcessInstanceIndexes is not null ? [] : null; @@ -323,7 +325,8 @@ private static (IReadOnlyList? Gc, EventLanes Events) BuildLanes( wantCpu ? BuildCpuLane(cpuCount!, cpuTop!, buckets) : null, wantExceptions ? BuildExceptionLane(exCount!, exTop!, buckets) : null, wantAlloc ? BuildAllocLane(allocCount!, allocBytes!, buckets) : null, - wantJit ? BuildJitLane(jitCount!, buckets) : null) + wantJit ? BuildJitLane(jitCount!, buckets) : null, + cpuSamples.Warning) : default; return (gc, events); @@ -367,6 +370,7 @@ void Accumulate(TraceEvent data) break; } + cpuSamples.ObserveSample(data is ClrThreadSampleTraceData); int idx = BucketIndex(time, startMs, bucketSizeMs, buckets); cpuCount![idx]++; string? leaf = LeafMethod(stack); diff --git a/src/Filtrace.Core/Tracing/Providers/TimelineResult.cs b/src/Filtrace.Core/Tracing/Providers/TimelineResult.cs index 51799a84..96e9f133 100644 --- a/src/Filtrace.Core/Tracing/Providers/TimelineResult.cs +++ b/src/Filtrace.Core/Tracing/Providers/TimelineResult.cs @@ -64,4 +64,11 @@ public sealed record TimelineResult( /// [JsonIgnore] public IReadOnlyList ScopeWarnings { get; init; } = []; + + /// + /// The warning for contributing SampleProfiler CPU-labeled samples, omitted + /// from result JSON because the heads put it in the envelope warnings. + /// + [JsonIgnore] + public string? CpuSampleWarning { get; init; } } diff --git a/src/Filtrace.Core/Tracing/Readers/CpuSampleEvidence.cs b/src/Filtrace.Core/Tracing/Readers/CpuSampleEvidence.cs new file mode 100644 index 00000000..a0094c0c --- /dev/null +++ b/src/Filtrace.Core/Tracing/Readers/CpuSampleEvidence.cs @@ -0,0 +1,166 @@ +// Copyright (c) Jeremy W Kuhne and contributors +// SPDX-License-Identifier: MIT +// See LICENSE file in the project root for full license information + +using System.Globalization; + +namespace Filtrace.Tracing.Readers; + +/// +/// Tracks contributing ETW and SampleProfiler records without treating thread-stack +/// samples as time-weighted CPU work. +/// +internal struct CpuSampleEvidence +{ + /// + /// Provenance of SampleProfiler-only CPU-labeled counts. + /// + internal const string SampleProfilerSource = "sampleprofiler"; + + /// + /// Provenance of CPU-labeled counts from both sample providers. + /// + internal const string MixedSource = "mixed-etw-sampleprofiler"; + + private const string SampleProfilerWarning = + "SampleProfiler thread-stack samples can include waits or native work; weights are raw counts, not on-core CPU milliseconds or blocked-time percentages. Use ETW PerfInfo for CPU time."; + + private const string MixedWarning = + "Mixed ETW sampled-profile and SampleProfiler thread stacks: weights are raw counts from different samplers, not on-core CPU milliseconds or blocked-time percentages. Use ETW PerfInfo alone for CPU time."; + + private int _sampleProfilerCount; + private int _etwSampleCount; + + /// + /// Gets whether at least one SampleProfiler record contributed to this result. + /// + internal bool HasSampleProfiler => _sampleProfilerCount > 0; + + /// + /// Gets the provider-specific advisory, or when no + /// SampleProfiler sample contributed. + /// + internal string? Warning => !HasSampleProfiler + ? null + : _etwSampleCount > 0 ? MixedWarning : SampleProfilerWarning; + + /// + /// Observes a selected sample with a usable call stack. + /// + /// Whether the sample is a SampleProfiler thread-stack record. + internal void ObserveSample(bool sampleProfiler) + { + if (sampleProfiler) + { + if (_sampleProfilerCount < int.MaxValue) + { + _sampleProfilerCount++; + } + } + else if (_etwSampleCount < int.MaxValue) + { + _etwSampleCount++; + } + } + + /// + /// Weights an ETW periodic sample by its own recorded interval, but never applies + /// that interval to a SampleProfiler thread-stack record. + /// + /// The ETW interval state, if available. + /// Whether this is a SampleProfiler record. + /// The weight of this sample before possible mixed-source normalization. + internal double GetSampleWeight(CpuSampleWeighting? weighting, bool sampleProfiler) + { + ObserveSample(sampleProfiler); + return sampleProfiler ? 1.0 : weighting?.GetSampleWeight() ?? 1.0; + } + + /// + /// Describes the unit and provider evidence of the selected CPU-labeled samples. + /// + /// ETW interval evidence, or for EventPipe. + /// The total number of selected samples. + /// Conservative CPU weight provenance for this result. + internal CpuSampleProvenance CreateProvenance(CpuSampleWeighting? weighting, int sampleCount) + { + bool established = !HasSampleProfiler && weighting?.HasCompleteIntervalEvidence == true; + int unknown = weighting is null + ? sampleCount + : (int)Math.Min((long)sampleCount, (long)weighting.UnknownIntervalSampleCount + _sampleProfilerCount); + + string source = HasSampleProfiler + ? _etwSampleCount > 0 ? MixedSource : SampleProfilerSource + : weighting?.Intervals.Count > 0 ? "etw-perfinfo" : "unavailable"; + + return new CpuSampleProvenance( + established ? "ms" : "samples", + source, + established, + unknown, + weighting?.Intervals ?? []) + { + OmittedIntervalSegmentCount = weighting?.OmittedIntervalSegmentCount ?? 0, + OmittedIntervalSampleCount = weighting?.OmittedIntervalSampleCount ?? 0, + IntervalsTruncated = weighting?.OmittedIntervalSegmentCount > 0 + }; + } + + /// + /// Appends the applicable interval or SampleProfiler advisory to the result. + /// + /// The result warnings to append to. + /// ETW interval evidence, if any. + /// The selected CPU weight provenance. + /// The number of selected samples. + internal void AddWarnings( + List warnings, + CpuSampleWeighting? weighting, + CpuSampleProvenance provenance, + int sampleCount) + { + if (Warning is string sampleWarning) + { + warnings.Add(sampleWarning); + } + else if (provenance.TimeWeightsEstablished) + { + warnings.Add( + provenance.Intervals.Count == 1 + ? $"CPU sample weights use the trace-recorded ETW PerfInfo interval ({provenance.Intervals[0].IntervalMSec.ToString("0.####", CultureInfo.InvariantCulture)} ms)." + : "CPU sample weights use the trace-recorded ETW PerfInfo interval active at each sample; the interval changed during the trace."); + } + else if (sampleCount > 0) + { + warnings.Add( + "CPU sampling interval is not recorded for every included sample; CPU weights are raw sample counts, not milliseconds."); + } + + if (weighting?.OmittedIntervalSegmentCount > 0) + { + warnings.Add( + $"CPU sampling provenance retained the first {weighting.Intervals.Count} interval segments and omitted {weighting.OmittedIntervalSegmentCount} later segments covering {weighting.OmittedIntervalSampleCount} samples."); + } + } + + /// + /// Tests whether the CPU weight provenance includes SampleProfiler records. + /// + /// The source's CPU sample provenance, if known. + /// when SampleProfiler samples contributed. + internal static bool ContainsSampleProfiler(CpuSampleProvenance? provenance) => + provenance?.Source is SampleProfilerSource or MixedSource; + + /// + /// Gets the provider-specific warning from established CPU sample provenance. + /// + /// The CPU sample provenance, if known. + /// The warning when SampleProfiler samples contributed, or . + internal static string? WarningFor(CpuSampleProvenance? provenance) => + provenance?.Source switch + { + SampleProfilerSource => SampleProfilerWarning, + MixedSource => MixedWarning, + _ => null + }; +} diff --git a/src/Filtrace.Core/Tracing/Readers/TraceLogReader.cs b/src/Filtrace.Core/Tracing/Readers/TraceLogReader.cs index 840868d6..3ab005b0 100644 --- a/src/Filtrace.Core/Tracing/Readers/TraceLogReader.cs +++ b/src/Filtrace.Core/Tracing/Readers/TraceLogReader.cs @@ -14,11 +14,11 @@ namespace Filtrace.Tracing.Readers; /// /// /// -/// Both formats normalize, through , onto the same -/// CPU-sample event with a resolvable -/// . Managed method names resolve from the CLR -/// rundown embedded in the trace, so no external symbol server is needed for -/// managed frames; native frames may remain unresolved. +/// ETW sampled-profile and SampleProfiler thread-stack records both normalize, +/// through , onto weighted samples with a resolvable +/// . Managed method names resolve from the CLR rundown +/// embedded in the trace, so no external symbol server is needed for managed +/// frames; native frames may remain unresolved. /// /// /// ETW samples are weighted by the timer interval recorded in @@ -306,6 +306,7 @@ private static TraceReadResult ReadCore( List leafToRoot = []; List? leafToRootLocations = resolveSourceLocations ? [] : null; CpuSampleWeighting? cpuWeighting = format == TraceFormat.Etl ? new() : null; + CpuSampleEvidence cpuSamples = default; foreach (TraceEvent data in traceLog.Events) { @@ -570,7 +571,8 @@ private static TraceReadResult ReadCore( string process = processEntry?.GetLabel(processName) ?? ProcessLabelCacheEntry.CreateLabel(processId, processName); - double weight = cpuWeighting?.GetSampleWeight() ?? 1.0; + bool sampleProfiler = data is ClrThreadSampleTraceData; + double weight = cpuSamples.GetSampleWeight(cpuWeighting, sampleProfiler); SampleStack sample = cachedStack is null ? new SampleStack(frames, weight, thread, locations, process) : cachedStack.GetOrCreateSample(weight, threadId, thread, process); @@ -606,40 +608,15 @@ private static TraceReadResult ReadCore( } } - bool timeWeightsEstablished = cpuWeighting?.HasCompleteIntervalEvidence == true; + CpuSampleProvenance cpuSampling = cpuSamples.CreateProvenance(cpuWeighting, samples.Count); + bool timeWeightsEstablished = cpuSampling.TimeWeightsEstablished; MetricInfo metric = timeWeightsEstablished ? MetricInfo.Cpu : MetricInfo.CpuSamples; - CpuSampleProvenance cpuSampling; - - if (cpuWeighting is null) + if (!timeWeightsEstablished && cpuWeighting?.Intervals.Count > 0) { - cpuSampling = new CpuSampleProvenance( - "samples", - "unavailable", - TimeWeightsEstablished: false, - UnknownIntervalSampleCount: samples.Count, - Intervals: []); - } - else - { - if (!timeWeightsEstablished && cpuWeighting.Intervals.Count > 0) + for (int i = 0; i < samples.Count; i++) { - for (int i = 0; i < samples.Count; i++) - { - samples[i].NormalizeCpuWeightToSampleCount(); - } + samples[i].NormalizeCpuWeightToSampleCount(); } - - cpuSampling = new CpuSampleProvenance( - timeWeightsEstablished ? "ms" : "samples", - cpuWeighting.Intervals.Count > 0 ? "etw-perfinfo" : "unavailable", - timeWeightsEstablished, - cpuWeighting.UnknownIntervalSampleCount, - cpuWeighting.Intervals) - { - OmittedIntervalSegmentCount = cpuWeighting.OmittedIntervalSegmentCount, - OmittedIntervalSampleCount = cpuWeighting.OmittedIntervalSampleCount, - IntervalsTruncated = cpuWeighting.OmittedIntervalSegmentCount > 0 - }; } double resolutionRate = totalFrames > 0 ? (double)resolvedFrames / totalFrames : 0.0; @@ -650,25 +627,7 @@ private static TraceReadResult ReadCore( List warnings = [.. scopeWarnings]; AddEventLossWarning(warnings, traceLog.EventsLost); - if (timeWeightsEstablished) - { - warnings.Add( - cpuWeighting!.Intervals.Count == 1 - ? $"CPU sample weights use the trace-recorded ETW PerfInfo interval ({cpuWeighting.Intervals[0].IntervalMSec.ToString("0.####", CultureInfo.InvariantCulture)} ms)." - : "CPU sample weights use the trace-recorded ETW PerfInfo interval active at each sample; the interval changed during the trace."); - - } - else if (samples.Count > 0) - { - warnings.Add( - "CPU sampling interval is not recorded for every included sample; CPU weights are raw sample counts, not milliseconds."); - } - - if (cpuWeighting?.OmittedIntervalSegmentCount > 0) - { - warnings.Add( - $"CPU sampling provenance retained the first {cpuWeighting.Intervals.Count} interval segments and omitted {cpuWeighting.OmittedIntervalSegmentCount} later segments covering {cpuWeighting.OmittedIntervalSampleCount} samples."); - } + cpuSamples.AddWarnings(warnings, cpuWeighting, cpuSampling, samples.Count); if (samples.Count == 0) { @@ -755,6 +714,7 @@ private static TraceReadResult ReadCore( analysisEvents.Counts, sourceResolution.CreateInfo()) { + EventsLost = traceLog.EventsLost, NativeSymbols = nativeSymbols, AppliedProcessScope = resolvedScope.AppliedScope, AppliedActivityName = activityName, @@ -769,14 +729,22 @@ private static TraceReadResult ReadCore( /// The lost-event count retained by the trace log. internal static void AddEventLossWarning(List warnings, int eventsLost) { - if (eventsLost > 0) + if (EventLossWarning(eventsLost) is string warning) { - warnings.Add( - $"Trace records report {eventsLost.ToString(CultureInfo.InvariantCulture)} lost events; " - + "analysis is incomplete and must not be treated as a complete profile."); + warnings.Add(warning); } } + /// + /// Formats incomplete-capture evidence when ETLX reports lost events. + /// + /// The trace's lost-event count. + /// The warning, or when no events were lost. + internal static string? EventLossWarning(int eventsLost) => eventsLost > 0 + ? $"Trace records report {eventsLost.ToString(CultureInfo.InvariantCulture)} lost events; " + + "analysis is incomplete and must not be treated as a complete profile." + : null; + /// /// Determines whether another thread label can be retained for reference sharing. /// diff --git a/src/Filtrace.Core/Tracing/Readers/TraceReadResult.cs b/src/Filtrace.Core/Tracing/Readers/TraceReadResult.cs index 2995be82..5403836c 100644 --- a/src/Filtrace.Core/Tracing/Readers/TraceReadResult.cs +++ b/src/Filtrace.Core/Tracing/Readers/TraceReadResult.cs @@ -32,6 +32,11 @@ internal sealed record TraceReadResult( IReadOnlyDictionary? AnalysisEventCounts = null, SourceResolutionInfo? SourceResolution = null) { + /// + /// The number of events ETLX reports lost during capture. + /// + internal int EventsLost { get; init; } + /// /// Local native symbol lookup results, or when no local /// symbol directory was supplied or the trace had no unresolved native frames. diff --git a/src/Filtrace.Core/Tracing/TraceInfo.cs b/src/Filtrace.Core/Tracing/TraceInfo.cs index 9f58fd36..b5599205 100644 --- a/src/Filtrace.Core/Tracing/TraceInfo.cs +++ b/src/Filtrace.Core/Tracing/TraceInfo.cs @@ -132,6 +132,12 @@ public TraceInfo( /// public IReadOnlyList Warnings { get; } + /// + /// The ETLX-reported lost-event count, kept separate from rendered warnings so + /// bounded manifest results can always retain incomplete-capture evidence. + /// + internal int EventsLost { get; init; } + /// /// The analyses filtrace can run against this trace format. This is a format /// constraint only; use for capture enablement and event diff --git a/src/Filtrace.Core/Tracing/TraceLoader.cs b/src/Filtrace.Core/Tracing/TraceLoader.cs index 52a22835..6146f954 100644 --- a/src/Filtrace.Core/Tracing/TraceLoader.cs +++ b/src/Filtrace.Core/Tracing/TraceLoader.cs @@ -145,7 +145,8 @@ private static LoadedTrace LoadCpu( result.AppliedProcessScope, result.AppliedActivityName, result.AppliedTimeWindow, - result.CpuSampling); + result.CpuSampling, + result.EventsLost); StackSampleSource source = new(result.Metric, result.Samples, result.RecordSemantics); return new LoadedTrace(info, source); @@ -441,7 +442,8 @@ private static TraceInfo BuildInfo( AppliedProcessScope? appliedProcessScope = null, string? appliedActivityName = null, TimeWindow? appliedTimeWindow = null, - CpuSampleProvenance? cpuSampling = null) + CpuSampleProvenance? cpuSampling = null, + int eventsLost = 0) { double totalWeight = 0.0; Dictionary threadCounts = new(StringComparer.Ordinal); @@ -487,7 +489,8 @@ private static TraceInfo BuildInfo( AppliedProcessScope = appliedProcessScope, AppliedActivityName = appliedActivityName, AppliedTimeWindow = appliedTimeWindow, - CpuSampling = cpuSampling + CpuSampling = cpuSampling, + EventsLost = eventsLost }; } diff --git a/src/Filtrace.Mcp/TraceTools.cs b/src/Filtrace.Mcp/TraceTools.cs index e807fee8..ee8623f7 100644 --- a/src/Filtrace.Mcp/TraceTools.cs +++ b/src/Filtrace.Mcp/TraceTools.cs @@ -400,7 +400,8 @@ or InvalidDataException scope, info.Path, resolvedSymbols, - nativeSymbols), + nativeSymbols, + info.CpuSampling), AnalysisContext.ForTrace( "rank", trace, @@ -1031,6 +1032,10 @@ _ when normalizedMode.Equals("snapshot", StringComparison.OrdinalIgnoreCase) => } warnings.AddRange(result.ScopeWarnings); + if (result.CpuSampleWarning is string cpuSampleWarning) + { + warnings.Add(cpuSampleWarning); + } // Surface the process the scope resolved to (an explicit name or the automatic // busiest) so a narrowed machine-wide capture is not silently one process's view. diff --git a/src/Filtrace/Cli/RankingExecutor.cs b/src/Filtrace/Cli/RankingExecutor.cs index dcbc4d76..1a41552b 100644 --- a/src/Filtrace/Cli/RankingExecutor.cs +++ b/src/Filtrace/Cli/RankingExecutor.cs @@ -96,7 +96,8 @@ or InvalidDataException scope, info.Path, symbols, - request.SymbolOptions?.ResolveNativeRuntime == true), + request.SymbolOptions?.ResolveNativeRuntime == true, + info.CpuSampling), AnalysisContext.ForTrace( "rank", trace, diff --git a/src/Filtrace/Cli/TimelineExecutor.cs b/src/Filtrace/Cli/TimelineExecutor.cs index d3d100a5..61f98791 100644 --- a/src/Filtrace/Cli/TimelineExecutor.cs +++ b/src/Filtrace/Cli/TimelineExecutor.cs @@ -111,6 +111,10 @@ public static int Run(TimelineRequest request, TextWriter output, TextWriter err } warnings.AddRange(result.ScopeWarnings); + if (result.CpuSampleWarning is string cpuSampleWarning) + { + warnings.Add(cpuSampleWarning); + } // Surface the process the scope resolved to (an explicit name or the automatic // busiest) so a narrowed machine-wide capture is not silently one process's view. diff --git a/tests/Filtrace.Cli.Tests/CliAppTests.cs b/tests/Filtrace.Cli.Tests/CliAppTests.cs index add16102..ef680c1c 100644 --- a/tests/Filtrace.Cli.Tests/CliAppTests.cs +++ b/tests/Filtrace.Cli.Tests/CliAppTests.cs @@ -124,6 +124,27 @@ public void Run_InfoJson_EmitsTheSameEnvelopeAsTheTool() output.Should().Contain("\"symbolResolutionRate\""); } + [TestMethod] + public void Run_InfoEventPipeJson_WarnsAndQualifiesCpuRoute() + { + (int exit, string output, _) = Run( + "info", FixturePath("activity.nettrace"), "--format", "json"); + + exit.Should().Be(ExitCodes.Success); + using JsonDocument document = JsonDocument.Parse(output); + JsonElement envelope = document.RootElement; + envelope.GetProperty("result").GetProperty("cpuSampling") + .GetProperty("source").GetString().Should().Be("sampleprofiler"); + + envelope.GetProperty("warnings").EnumerateArray().Should().Contain(warning => + warning.GetProperty("message").GetString()!.Contains( + "SampleProfiler thread-stack samples", StringComparison.Ordinal)); + + envelope.GetProperty("hints").EnumerateArray().Should().Contain(hint => + hint.GetProperty("reason").GetString()!.Contains( + "sampled thread stacks (not on-core CPU time) -> cpu", StringComparison.Ordinal)); + } + [TestMethod] public void Run_InfoQualityPolicy_AcceptsObservedCpu() { @@ -771,7 +792,7 @@ public void Run_Processes_OnSpeedscope_ListsTheSingleProcess() [TestMethod] [DataRow("folding.speedscope.json", "ms", "speedscope-profile-declared-time-weights", true)] - [DataRow("activity.nettrace", "samples", "unavailable", false)] + [DataRow("activity.nettrace", "samples", "sampleprofiler", false)] public void Run_ProcessesJson_ReportsCpuWeightContract( string fixture, string expectedUnit, @@ -794,6 +815,12 @@ public void Run_ProcessesJson_ReportsCpuWeightContract( JsonElement cpuSampling = context.GetProperty("cpuSampling"); cpuSampling.GetProperty("source").GetString().Should().Be(expectedSource); cpuSampling.GetProperty("timeWeightsEstablished").GetBoolean().Should().Be(timeWeightsEstablished); + if (expectedSource == "sampleprofiler") + { + root.GetProperty("warnings").EnumerateArray().Should().Contain(warning => + warning.GetProperty("message").GetString()!.Contains( + "SampleProfiler thread-stack samples", StringComparison.Ordinal)); + } } [TestMethod] @@ -1259,6 +1286,34 @@ public void Run_TimelineSnapshot_ParsesModeAtAndWindow() .And.Contain("\"snapshot\""); } + [TestMethod] + public void Run_TimelineEventPipeCpu_WarnsInBucketsAndSnapshot() + { + foreach (string[] arguments in new[] + { + new[] { "--lanes", "cpu" }, + new[] { "--mode", "snapshot", "--at", "0", "--window", "60000" } + }) + { + (int exit, string output, _) = Run( + ["timeline", ExceptionsTrace, .. arguments, "--format", "json"]); + + exit.Should().Be(ExitCodes.Success); + using JsonDocument document = JsonDocument.Parse(output); + JsonElement envelope = document.RootElement; + envelope.GetProperty("warnings").EnumerateArray().Should().Contain(warning => + warning.GetProperty("message").GetString()!.Contains( + "SampleProfiler thread-stack samples", StringComparison.Ordinal)); + + envelope.GetProperty("hints").EnumerateArray().Should().Contain(hint => + hint.GetProperty("reason").GetString()!.Contains( + arguments[0] == "--lanes" ? "thread-stack sample window" : "sampled thread stacks", + StringComparison.Ordinal)); + + envelope.GetProperty("result").TryGetProperty("cpuSampleWarning", out _).Should().BeFalse(); + } + } + [TestMethod] public void Run_TimelineSnapshot_OmittedWindowUsesDefault() { diff --git a/tests/Filtrace.Cli.Tests/DiffExecutorTests.cs b/tests/Filtrace.Cli.Tests/DiffExecutorTests.cs index 68d95f06..a3c544a1 100644 --- a/tests/Filtrace.Cli.Tests/DiffExecutorTests.cs +++ b/tests/Filtrace.Cli.Tests/DiffExecutorTests.cs @@ -310,6 +310,8 @@ public void Run_PeriodicThinRoot_PrefixesWarningsForBothSides() output.Should().NotContain("CPU self-time"); output.Should().Contain("baseline: Only 180 periodic CPU records"); output.Should().Contain("current: Only 180 periodic CPU records"); + output.Should().Contain("baseline: SampleProfiler thread-stack samples"); + output.Should().Contain("current: SampleProfiler thread-stack samples"); } [TestMethod] diff --git a/tests/Filtrace.Cli.Tests/RankingExecutorTests.cs b/tests/Filtrace.Cli.Tests/RankingExecutorTests.cs index 2ab17054..3cab41b7 100644 --- a/tests/Filtrace.Cli.Tests/RankingExecutorTests.cs +++ b/tests/Filtrace.Cli.Tests/RankingExecutorTests.cs @@ -154,7 +154,9 @@ public void Run_ThinPeriodicCpuRoot_ReportsCountAndWarning() output.Should().Contain("CPU self-weight"); output.Should().NotContain("CPU self-time"); output.Should().Contain("samples symbols"); - output.Should().Contain("CPU weights are raw sample counts, not milliseconds"); + output.Should().Contain("SampleProfiler thread-stack samples can include waits or native work"); + output.Should().Contain("not on-core CPU milliseconds or blocked-time percentages"); + output.Should().Contain("drill into the most sampled frame"); output.Should().Contain("records 179"); output.Should().Contain("Only 179 periodic CPU records"); output.Should().Contain("at least 200"); @@ -251,8 +253,11 @@ public void Run_EventPipeJson_ReportsSampleUnitAndUnknownIntervalProvenance() JsonElement context = document.RootElement.GetProperty("context"); context.GetProperty("unit").GetString().Should().Be("samples"); JsonElement cpuSampling = context.GetProperty("cpuSampling"); - cpuSampling.GetProperty("source").GetString().Should().Be("unavailable"); + cpuSampling.GetProperty("source").GetString().Should().Be("sampleprofiler"); cpuSampling.GetProperty("timeWeightsEstablished").GetBoolean().Should().BeFalse(); + document.RootElement.GetProperty("warnings").EnumerateArray().Should().Contain( + warning => warning.GetProperty("message").GetString()!.Contains( + "SampleProfiler thread-stack samples", StringComparison.Ordinal)); } [TestMethod] diff --git a/tests/Filtrace.Core.Tests/ActivityScopeTests.cs b/tests/Filtrace.Core.Tests/ActivityScopeTests.cs index 51e9a6b2..2c2deb90 100644 --- a/tests/Filtrace.Core.Tests/ActivityScopeTests.cs +++ b/tests/Filtrace.Core.Tests/ActivityScopeTests.cs @@ -66,5 +66,8 @@ public void Load_CpuScopedToUnknownActivity_DropsEverySampleAndBlamesTheScope() scoped.Info.SampleCount.Should().Be(0); scoped.Info.Warnings.Should().Contain(w => w.Contains("No samples remained inside the 'NoSuchActivity' activity", StringComparison.Ordinal)); + + scoped.Info.Warnings.Should().NotContain(w => + w.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); } } diff --git a/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs b/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs index dcda3ee6..491d4084 100644 --- a/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs +++ b/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs @@ -4,6 +4,8 @@ using Touki; +using Filtrace.Tracing.Readers; + namespace Filtrace.Tracing; [TestClass] @@ -622,6 +624,102 @@ public void AnalyzeBatch_MixedCaseOutcomes_ReturnsCaseSpecificRowsAndWarnings() result.Cases[2].TopFrame.Should().BeNull(); } + [TestMethod] + public void AnalyzeBatch_LostEventsAndSampleProfiler_SurviveCaseBudget() + { + CpuSampleProvenance sampling = new( + "samples", CpuSampleEvidence.SampleProfilerSource, + TimeWeightsEstablished: false, UnknownIntervalSampleCount: 2, Intervals: []); + + string sampleWarning = CpuSampleEvidence.WarningFor(sampling)!; + string lossWarning = TraceLogReader.EventLossWarning(eventsLost: 4)!; + LoadedTrace trace = Loaded( + "sampleprofiler", 1.0, 1.0, + warnings: ["first", "second", "third", "fourth", sampleWarning, lossWarning], + cpuSampling: sampling, + eventsLost: 4); + + BatchRankingResult result = CaptureManifestBatchAnalyzer.Analyze( + Manifest(Case("sample", "Bench.Work", "Mode: Sample", "Sample")), + "cpu", inclusive: false, root: "", FrameNames.DefaultFoldPatterns, + (_, _) => trace); + + IReadOnlyList warnings = result.Cases.Single().Warnings; + warnings.Should().HaveCount(CaptureManifestOutput.MaxWarningsPerCase); + warnings[0].Should().StartWith("Trace records report 4 lost events"); + warnings[1].Should().StartWith("SampleProfiler thread-stack samples"); + warnings.Should().ContainSingle(warning => + warning.StartsWith("Trace records report 4 lost events", StringComparison.Ordinal)); + + warnings.Should().ContainSingle(warning => + warning.StartsWith("SampleProfiler thread-stack samples", StringComparison.Ordinal)); + } + + [TestMethod] + public void AnalyzeBatch_PrioritizedWarnings_AreNotDuplicated() + { + CpuSampleProvenance sampling = new( + "samples", CpuSampleEvidence.SampleProfilerSource, + TimeWeightsEstablished: false, UnknownIntervalSampleCount: 2, Intervals: []); + + string sampleWarning = CpuSampleEvidence.WarningFor(sampling)!; + string lossWarning = TraceLogReader.EventLossWarning(eventsLost: 2)!; + LoadedTrace trace = Loaded( + "sampleprofiler", 1.0, 1.0, + warnings: [lossWarning, sampleWarning, "Scoped to one process."], + cpuSampling: sampling, + eventsLost: 2); + + BatchRankingResult result = CaptureManifestBatchAnalyzer.Analyze( + Manifest(Case("sample", "Bench.Work", "Mode: Sample", "Sample")), + "cpu", inclusive: false, root: "", FrameNames.DefaultFoldPatterns, + (_, _) => trace); + + IReadOnlyList warnings = result.Cases.Single().Warnings; + warnings.Should().HaveCount(3); + warnings[0].Should().StartWith("Trace records report 2 lost events"); + warnings[1].Should().StartWith("SampleProfiler thread-stack samples"); + warnings[2].Should().Be("Scoped to one process."); + } + + [TestMethod] + public void AnalyzeManifestDiff_LostEventsAndSampleProfiler_SurviveBothArmBudgets() + { + CpuSampleProvenance sampling = new( + "samples", CpuSampleEvidence.SampleProfilerSource, + TimeWeightsEstablished: false, UnknownIntervalSampleCount: 2, Intervals: []); + + string sampleWarning = CpuSampleEvidence.WarningFor(sampling)!; + string baselineLoss = TraceLogReader.EventLossWarning(eventsLost: 4)!; + string currentLoss = TraceLogReader.EventLossWarning(eventsLost: 7)!; + LoadedTrace baseline = Loaded( + "baseline", 1.0, 1.0, + warnings: ["first", "second", "third", "fourth", sampleWarning, baselineLoss], + cpuSampling: sampling, + eventsLost: 4); + + LoadedTrace current = Loaded( + "current", 1.0, 1.0, + warnings: ["first", "second", "third", "fourth", sampleWarning, currentLoss], + cpuSampling: sampling, + eventsLost: 7); + + CaptureManifest before = Manifest(Case("sample", "Bench.Work", "Mode: Sample", "Sample")); + CaptureManifest after = Manifest(Case("sample", "Bench.Work", "Mode: Sample", "Sample")); + + CaptureManifestDiffAnalysis analysis = CaptureManifestDiffAnalyzer.Analyze( + before, after, inclusive: false, root: "", + FrameNames.DefaultFoldPatterns, top: 5, + (manifest, _) => ReferenceEquals(manifest, before) ? baseline : current); + + IReadOnlyList warnings = analysis.Result.Cases.Single().Warnings; + warnings.Should().HaveCount(CaptureManifestOutput.MaxWarningsPerCase); + warnings[0].Should().StartWith("baseline: Trace records report 4 lost events"); + warnings[1].Should().StartWith("current: Trace records report 7 lost events"); + warnings[2].Should().StartWith("baseline: SampleProfiler thread-stack samples"); + warnings[3].Should().StartWith("current: SampleProfiler thread-stack samples"); + } + [TestMethod] public void AnalyzeBatch_RootScope_CarriesPerCaseCoverage() { @@ -806,7 +904,10 @@ private static LoadedTrace Loaded( string path, double hotWeight, double otherWeight, - StackRecordSemantics recordSemantics = StackRecordSemantics.EventedIntervals) + StackRecordSemantics recordSemantics = StackRecordSemantics.EventedIntervals, + IReadOnlyList? warnings = null, + CpuSampleProvenance? cpuSampling = null, + int eventsLost = 0) { SampleStack[] samples = [ @@ -816,16 +917,23 @@ private static LoadedTrace Loaded( TraceInfo info = new( path, - TraceFormat.Speedscope, + cpuSampling is null ? TraceFormat.Speedscope : TraceFormat.NetTrace, hotWeight + otherWeight, samples.Length, 1.0, [], - [], - ["cpu"]); + warnings ?? [], + ["cpu"]) + { + CpuSampling = cpuSampling, + EventsLost = eventsLost + }; return new LoadedTrace( info, - new StackSampleSource(MetricInfo.Cpu, samples, recordSemantics)); + new StackSampleSource( + cpuSampling?.WeightUnit == "samples" ? MetricInfo.CpuSamples : MetricInfo.Cpu, + samples, + recordSemantics)); } } diff --git a/tests/Filtrace.Core.Tests/CpuSampleEvidenceTests.cs b/tests/Filtrace.Core.Tests/CpuSampleEvidenceTests.cs new file mode 100644 index 00000000..25cd8f66 --- /dev/null +++ b/tests/Filtrace.Core.Tests/CpuSampleEvidenceTests.cs @@ -0,0 +1,72 @@ +// Copyright (c) Jeremy W Kuhne and contributors +// SPDX-License-Identifier: MIT +// See LICENSE file in the project root for full license information + +using Filtrace.Tracing.Readers; + +namespace Filtrace.Tracing; + +[TestClass] +public sealed class CpuSampleEvidenceTests +{ + [TestMethod] + public void GetSampleWeight_SampleProfilerAfterEtwInterval_UsesCountsAndNoEtwInterval() + { + CpuSampleWeighting weighting = new(); + weighting.ObserveInterval(opcode: 73, sampleSource: 0, newInterval100Nanoseconds: 1_250); + CpuSampleEvidence evidence = default; + + evidence.GetSampleWeight(weighting, sampleProfiler: true).Should().Be(1.0); + + CpuSampleProvenance provenance = evidence.CreateProvenance(weighting, sampleCount: 1); + provenance.WeightUnit.Should().Be("samples"); + provenance.Source.Should().Be(CpuSampleEvidence.SampleProfilerSource); + provenance.TimeWeightsEstablished.Should().BeFalse(); + provenance.UnknownIntervalSampleCount.Should().Be(1); + provenance.Intervals.Should().BeEmpty(); + evidence.Warning.Should().Contain("not on-core CPU milliseconds") + .And.Contain("blocked-time percentages"); + } + + [TestMethod] + public void CreateProvenance_MixedEtwAndSampleProfiler_UsesRawCountsAndKeepsOnlyEtwIntervalEvidence() + { + CpuSampleWeighting weighting = new(); + weighting.ObserveInterval(opcode: 73, sampleSource: 0, newInterval100Nanoseconds: 1_250); + CpuSampleEvidence evidence = default; + + evidence.GetSampleWeight(weighting, sampleProfiler: false).Should().Be(0.125); + evidence.GetSampleWeight(weighting, sampleProfiler: true).Should().Be(1.0); + + CpuSampleProvenance provenance = evidence.CreateProvenance(weighting, sampleCount: 2); + provenance.WeightUnit.Should().Be("samples"); + provenance.Source.Should().Be(CpuSampleEvidence.MixedSource); + provenance.TimeWeightsEstablished.Should().BeFalse(); + provenance.UnknownIntervalSampleCount.Should().Be(1); + provenance.Intervals.Should().Equal(new CpuSampleIntervalSegment(0.125, 1)); + evidence.Warning.Should().Contain("Mixed ETW sampled-profile and SampleProfiler") + .And.Contain("weights are raw counts from different samplers"); + } + + [TestMethod] + public void GetSampleWeight_EtwOnly_UsesTraceRecordedIntervalAndRetainsExistingWarning() + { + CpuSampleWeighting weighting = new(); + weighting.ObserveInterval(opcode: 73, sampleSource: 0, newInterval100Nanoseconds: 1_250); + CpuSampleEvidence evidence = default; + + evidence.GetSampleWeight(weighting, sampleProfiler: false).Should().Be(0.125); + + CpuSampleProvenance provenance = evidence.CreateProvenance(weighting, sampleCount: 1); + provenance.WeightUnit.Should().Be("ms"); + provenance.Source.Should().Be("etw-perfinfo"); + provenance.TimeWeightsEstablished.Should().BeTrue(); + provenance.UnknownIntervalSampleCount.Should().Be(0); + evidence.Warning.Should().BeNull(); + + List warnings = []; + evidence.AddWarnings(warnings, weighting, provenance, sampleCount: 1); + warnings.Should().ContainSingle() + .Which.Should().Be("CPU sample weights use the trace-recorded ETW PerfInfo interval (0.125 ms)."); + } +} diff --git a/tests/Filtrace.Core.Tests/ProcessInventoryProviderTests.cs b/tests/Filtrace.Core.Tests/ProcessInventoryProviderTests.cs index 5dcc1a4b..a6cec835 100644 --- a/tests/Filtrace.Core.Tests/ProcessInventoryProviderTests.cs +++ b/tests/Filtrace.Core.Tests/ProcessInventoryProviderTests.cs @@ -3,6 +3,7 @@ // See LICENSE file in the project root for full license information using Filtrace.Tracing.Providers; +using Filtrace.Tracing.Readers; namespace Filtrace.Tracing; @@ -29,6 +30,9 @@ public void Read_EtlFixture_MatchesFullStackInventory() inventory.Metric.Should().Be(loaded.Aggregator.Metric); inventory.CpuSampling.Should().BeEquivalentTo(loaded.Info.CpuSampling); + inventory.Warnings.Should().NotContain(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); + inventory.Warnings.Should().NotContain( warning => warning.Contains("frames resolved", StringComparison.Ordinal)); } @@ -49,6 +53,9 @@ public void Read_NetTraceFixture_MatchesFullStackInventory() inventory.Metric.Should().Be(loaded.Aggregator.Metric); inventory.CpuSampling.Should().BeEquivalentTo(loaded.Info.CpuSampling); + inventory.CpuSampling.Source.Should().Be(CpuSampleEvidence.SampleProfilerSource); + inventory.Warnings.Should().ContainSingle(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); } [TestMethod] diff --git a/tests/Filtrace.Core.Tests/SteeringHintsTests.cs b/tests/Filtrace.Core.Tests/SteeringHintsTests.cs index d1f167be..3003aac6 100644 --- a/tests/Filtrace.Core.Tests/SteeringHintsTests.cs +++ b/tests/Filtrace.Core.Tests/SteeringHintsTests.cs @@ -172,6 +172,25 @@ public void ForRanking_UnresolvedExactPid_OffersCompleteScopePreservingInfoStep( step.Arguments.Frame.Should().BeNull(); } + [TestMethod] + public void ForRanking_SampleProfiler_OffersMostSampledFrameRatherThanHotCpu() + { + RankingResult ranking = new(25.0, "", [new RankRow("App.Work", 25.0, 100.0)]); + CpuSampleProvenance provenance = new( + "samples", "sampleprofiler", TimeWeightsEstablished: false, + UnknownIntervalSampleCount: 25, Intervals: []); + + IReadOnlyList hints = SteeringHints.ForRanking( + ranking, MetricInfo.CpuSamples, scope: null, path: null, symbols: null, + nativeSymbols: false, provenance); + + hints.Should().ContainSingle().Which.Should().Be( + "drill into the most sampled frame with: callers App.Work"); + + new AnalysisResult(ranking, hints: hints).NextSteps + .Should().ContainSingle().Which.Operation.Should().Be("callers"); + } + [TestMethod] public void ForRanking_UnresolvedNamedProcess_OffersScopePreservingInfoStep() { @@ -584,6 +603,26 @@ public void ForTraceInfo_CaptureStates_RoutesOnlyKnownEnabledAnalyses() && h.Contains("wait", StringComparison.Ordinal)); } + [TestMethod] + public void ForTraceInfo_SampleProfiler_QualifiesCpuBoundRoute() + { + TraceInfo info = new( + "/t.nettrace", TraceFormat.NetTrace, 100.0, 100, 1.0, [], [], + TraceCapabilities.AnalysesFor(TraceFormat.NetTrace)) + { + CpuSampling = new CpuSampleProvenance( + "samples", "sampleprofiler", TimeWeightsEstablished: false, + UnknownIntervalSampleCount: 100, Intervals: []) + }; + + IReadOnlyList hints = SteeringHints.ForTraceInfo(info); + + hints.Should().Contain(h => h.Contains( + "sampled thread stacks (not on-core CPU time) -> cpu", StringComparison.Ordinal)); + + hints.Should().NotContain(h => h.Contains("CPU-bound -> cpu", StringComparison.Ordinal)); + } + [TestMethod] public void ForTraceInfo_Etl_OmitsRoutesTheFormatCannotAnswer() { @@ -1158,6 +1197,24 @@ public void ForTimeline_CpuLane_DrillsBusiestWindowWithScopedRanking() .Be("busiest CPU window is bucket 2 (40-60 ms); scope a ranking with: rank --metric cpu --time 40,60"); } + [TestMethod] + public void ForTimeline_SampleProfiler_DrillsBusiestSampleWindow() + { + TimelineResult timeline = new( + 0.0, 100.0, 20.0, 5, Process: null, + Gc: null, Cpu: [new CpuBucket(0, TopMethod: null), new CpuBucket(10, "App.Work"), + new CpuBucket(0, TopMethod: null), new CpuBucket(0, TopMethod: null), new CpuBucket(0, TopMethod: null)], + Exceptions: null, Alloc: null, Jit: null) + { + CpuSampleWarning = "SampleProfiler thread-stack samples" + }; + + IReadOnlyList hints = SteeringHints.ForTimeline(timeline); + + hints.Should().ContainSingle().Which.Should().Contain( + "busiest thread-stack sample window is bucket 1"); + } + [TestMethod] public void ForTimeline_ProcessScoped_CarriesProcessIntoDrillHint() { diff --git a/tests/Filtrace.Core.Tests/TimelineProviderTests.cs b/tests/Filtrace.Core.Tests/TimelineProviderTests.cs index f4f4ef36..fbe76549 100644 --- a/tests/Filtrace.Core.Tests/TimelineProviderTests.cs +++ b/tests/Filtrace.Core.Tests/TimelineProviderTests.cs @@ -62,6 +62,7 @@ public void Read_LanesSelector_BuildsOnlyRequestedLanes() result.Cpu.Should().BeNull(); result.Exceptions.Should().BeNull(); result.Jit.Should().BeNull(); + result.CpuSampleWarning.Should().BeNull(); } [TestMethod] @@ -117,6 +118,7 @@ public void Read_NettraceFixture_CountsEventPipeCpuSamplesAlongsideGc() result.Cpu!.Sum(static b => (long)b.SampleCount).Should().BeGreaterThan(0, "the capture carries CPU samples"); result.Gc.Should().NotBeNull("the gc lane was requested in the same pass"); + result.CpuSampleWarning.Should().Contain("SampleProfiler thread-stack samples"); } [TestMethod] @@ -136,6 +138,7 @@ public void ReadSnapshot_ExceptionsFixture_ReturnsBoundedCrossLaneEvidence() result.Snapshot.Events.TypeCount.Should().BeGreaterThan(TimelineProvider.SnapshotDetailLimit); result.Snapshot.Events.Types.Should().HaveCount(TimelineProvider.SnapshotDetailLimit); result.Snapshot.Cpu.SampleCount.Should().BeGreaterThan(0); + result.CpuSampleWarning.Should().Contain("SampleProfiler thread-stack samples"); result.Snapshot.Cpu.Methods.Should().NotBeEmpty() .And.HaveCountLessThanOrEqualTo(TimelineProvider.SnapshotDetailLimit); @@ -253,6 +256,7 @@ public void Read_EtlFixture_CountsCpuSamples() FixturePath("etw.etl"), lanes: [TimelineProvider.CpuLane]); result.Cpu!.Sum(static b => (long)b.SampleCount).Should().BeGreaterThan(0); + result.CpuSampleWarning.Should().BeNull(); } [TestMethod] diff --git a/tests/Filtrace.Core.Tests/TraceLoaderTests.cs b/tests/Filtrace.Core.Tests/TraceLoaderTests.cs index a6c7fe2d..fc8db63f 100644 --- a/tests/Filtrace.Core.Tests/TraceLoaderTests.cs +++ b/tests/Filtrace.Core.Tests/TraceLoaderTests.cs @@ -3,6 +3,7 @@ // See LICENSE file in the project root for full license information using System.Globalization; +using Filtrace.Tracing.Readers; namespace Filtrace.Tracing; @@ -165,11 +166,12 @@ public void Load_EventPipeCpuMetric_UsesRawSamplesWhenIntervalIsUnavailable() trace.Source.Samples.Should().OnlyContain(static sample => sample.Weight == 1.0); trace.Info.CpuSampling.Should().NotBeNull(); trace.Info.CpuSampling!.WeightUnit.Should().Be("samples"); - trace.Info.CpuSampling.Source.Should().Be("unavailable"); + trace.Info.CpuSampling.Source.Should().Be(CpuSampleEvidence.SampleProfilerSource); trace.Info.CpuSampling.TimeWeightsEstablished.Should().BeFalse(); trace.Info.CpuSampling.UnknownIntervalSampleCount.Should().Be(trace.Info.SampleCount); trace.Info.Warnings.Should().Contain( - "CPU sampling interval is not recorded for every included sample; CPU weights are raw sample counts, not milliseconds."); + warning => warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal) + && warning.Contains("not on-core CPU milliseconds", StringComparison.Ordinal)); } [TestMethod] diff --git a/tests/Filtrace.Mcp.Tests/TraceToolsTests.cs b/tests/Filtrace.Mcp.Tests/TraceToolsTests.cs index 08ef5548..c4132459 100644 --- a/tests/Filtrace.Mcp.Tests/TraceToolsTests.cs +++ b/tests/Filtrace.Mcp.Tests/TraceToolsTests.cs @@ -86,6 +86,19 @@ public void Info_NetTrace_ReportsObservedAndUnknownAnalysisStates() envelope.Result.CpuSampling.TimeWeightsEstablished.Should().BeFalse(); } + [TestMethod] + public void Info_EventPipeSamples_WarnsAndQualifiesCpuRoute() + { + AnalysisResult envelope = TraceTools.Info(new TraceStore(), FixturePath(Activity)); + + envelope.Result.CpuSampling!.Source.Should().Be("sampleprofiler"); + envelope.Warnings.Should().ContainSingle(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); + + envelope.Hints.Should().Contain(hint => + hint.Contains("sampled thread stacks (not on-core CPU time) -> cpu", StringComparison.Ordinal)); + } + [TestMethod] public async Task Info_NetTrace_UnmarkedCache_ReportsExplicitMigration() { @@ -463,6 +476,9 @@ public void Rank_ThinPeriodicCpuRoot_WarnsUsingContributingRecords() scoped.Warnings.Should().Contain( warning => warning.Contains("179 periodic CPU records", StringComparison.Ordinal) && warning.Contains("200", StringComparison.Ordinal)); + + scoped.Warnings.Should().ContainSingle(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); } [TestMethod] @@ -1033,6 +1049,21 @@ public void Diff_DifferentCpuWeightUnits_ThrowsMcpException() .WithMessage("Cannot compare CPU weights in ms with weights in samples*"); } + [TestMethod] + public void Diff_EventPipeSamples_PrefixesProviderWarningsForBothArms() + { + TraceStore store = new(); + string trace = FixturePath(Activity); + + AnalysisResult envelope = TraceTools.Diff(store, trace, trace); + + envelope.Warnings.Should().Contain(warning => + warning.StartsWith("baseline: SampleProfiler thread-stack samples", StringComparison.Ordinal)); + + envelope.Warnings.Should().Contain(warning => + warning.StartsWith("current: SampleProfiler thread-stack samples", StringComparison.Ordinal)); + } + [TestMethod] public void Diff_UnknownMeasure_Throws() { @@ -1403,6 +1434,38 @@ public void Timeline_LanesSelector_LimitsLanes() envelope.Result.Gc.Should().NotBeNull(); envelope.Result.Cpu.Should().BeNull(); envelope.Result.Alloc.Should().BeNull(); + envelope.Warnings.Should().NotContain(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); + } + + [TestMethod] + public void Timeline_EventPipeCpuLane_WarnsAndQualifiesHint() + { + AnalysisResult envelope = TraceTools.Timeline( + FixturePath(Exceptions), lanes: TimelineProvider.CpuLane); + + envelope.Warnings.Should().ContainSingle(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); + + envelope.Hints.Should().Contain(hint => + hint.Contains("thread-stack sample window", StringComparison.Ordinal)); + } + + [TestMethod] + public void Timeline_EventPipeSnapshot_WarnsAndQualifiesHint() + { + AnalysisResult envelope = TraceTools.Timeline( + FixturePath(Exceptions), + mode: "snapshot", + at: 0.0, + window: TimelineProvider.MaxSnapshotHalfWindowMs); + + envelope.Result.Snapshot!.Cpu.SampleCount.Should().BeGreaterThan(0); + envelope.Warnings.Should().ContainSingle(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); + + envelope.Hints.Should().Contain(hint => + hint.Contains("sampled thread stacks", StringComparison.Ordinal)); } [TestMethod] @@ -1840,8 +1903,10 @@ public void Processes_EventPipe_ReportsRawCpuWeightContract() context.Unit.Should().Be("samples"); context.Scope.Should().BeNull(); context.CpuSampling.Should().NotBeNull(); - context.CpuSampling!.Source.Should().Be("unavailable"); + context.CpuSampling!.Source.Should().Be("sampleprofiler"); context.CpuSampling.TimeWeightsEstablished.Should().BeFalse(); + envelope.Warnings.Should().ContainSingle(warning => + warning.Contains("SampleProfiler thread-stack samples", StringComparison.Ordinal)); } [TestMethod] From 1fe236e513e129dd1f988923a45d6e1e279af1d2 Mon Sep 17 00:00:00 2001 From: Jeremy Kuhne Date: Tue, 29 Sep 2026 16:45:08 -0700 Subject: [PATCH 2/3] Preserve manifest diagnostics and accept SampleProfiler provenance Accept schema 18 SampleProfiler and mixed sample-count evidence in the Track D validator without admitting false time or malformed interval claims. Keep capture loss and sample provenance while reserving bounded manifest case warnings for root and per-operation diagnostics. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- benchmarks/Invoke-TrackDInvestigation.ps1 | 19 ++- docs/workflow.md | 7 +- .../Tracing/CaptureManifestBatchAnalyzer.cs | 65 ++++++----- .../Tracing/CaptureManifestDiffAnalyzer.cs | 100 +++++++++------- .../Tracing/CaptureManifestOutput.cs | 60 ++++++++++ .../CaptureManifestReaderTests.cs | 100 +++++++++++++++- tools/Test-TrackDInvestigation.ps1 | 110 +++++++++++++++++- 7 files changed, 381 insertions(+), 80 deletions(-) diff --git a/benchmarks/Invoke-TrackDInvestigation.ps1 b/benchmarks/Invoke-TrackDInvestigation.ps1 index 19324271..1d7f530b 100644 --- a/benchmarks/Invoke-TrackDInvestigation.ps1 +++ b/benchmarks/Invoke-TrackDInvestigation.ps1 @@ -1132,14 +1132,25 @@ function Get-ValidatedCpuSampling( $source -cnotin @( 'unavailable', 'etw-perfinfo', + 'sampleprofiler', + 'mixed-etw-sampleprofiler', 'speedscope-profile-declared-sample-weights') -or - ($source -cin @('unavailable', 'speedscope-profile-declared-sample-weights') -and + ($source -cin @( + 'unavailable', 'sampleprofiler', + 'speedscope-profile-declared-sample-weights') -and ($intervalCount -ne 0 -or $intervalsTruncated -or - $unknownIntervalSampleCount -ne $ExpectedRecordCount)) -or + $unknownIntervalSampleCount -ne $ExpectedRecordCount -or + ($source -ceq 'sampleprofiler' -and $ExpectedRecordCount -eq 0))) -or ($source -ceq 'etw-perfinfo' -and ($intervalCount -eq 0 -or $unknownIntervalSampleCount -le 0 -or - $unknownIntervalSampleCount -gt $ExpectedRecordCount)) + $unknownIntervalSampleCount -gt $ExpectedRecordCount)) -or + ($source -ceq 'mixed-etw-sampleprofiler' -and + ($ExpectedRecordCount -lt 2 -or + $unknownIntervalSampleCount -le 0 -or + ($intervalCount -eq 0 -and + ($omittedIntervalSegmentCount -ne 0 -or + $unknownIntervalSampleCount -ne $ExpectedRecordCount)))) ) { throw "$Owner returned incompatible schema 17 CPU sampling provenance." } @@ -1155,7 +1166,7 @@ function Get-ValidatedCpuSampling( throw "$Owner returned incompatible schema 17 CPU sampling provenance." } - if ($source -ceq 'etw-perfinfo') { + if ($source -cin @('etw-perfinfo', 'mixed-etw-sampleprofiler')) { if ( $unknownIntervalSampleCount -gt $ExpectedRecordCount -or $retainedIntervalSampleCount -gt $ExpectedRecordCount - $unknownIntervalSampleCount -or diff --git a/docs/workflow.md b/docs/workflow.md index 7efc7aed..f9d2976f 100644 --- a/docs/workflow.md +++ b/docs/workflow.md @@ -725,9 +725,10 @@ cleanly and stays cheap in tokens. SampleProfiler `External` events with blocked time. Counts from a mixed-provider result need not be comparable across samplers; do not treat their combined share as a CPU-time comparison. - Bounded manifest batch/diff cases reserve lost-event and SampleProfiler - advisories before lower-priority warnings for each arm; inspect a direct trace - when the four-warning case budget omits further quality detail. + Bounded manifest batch/diff cases retain lost-event and SampleProfiler evidence + (combined with arm labels in diff) plus root-mismatch and per-operation + diagnostics before lower-priority warnings. Inspect a direct trace when the + four-warning case budget omits further quality detail. - Keep counts separate from weight. `trace_info.sampleCount` describes the loaded whole trace after process/activity/time filters; it does not establish that a narrower root/method/file query is well sampled. Stack rankings and callers expose diff --git a/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs b/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs index 3b5607fc..d04e0c6e 100644 --- a/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs +++ b/src/Filtrace.Core/Tracing/CaptureManifestBatchAnalyzer.cs @@ -83,7 +83,6 @@ public static BatchRankingResult Analyze( ? trace.Aggregator.InclusiveTime(root, foldPatterns, 1) : trace.Aggregator.SelfTime(root, foldPatterns, 1); - AddQualityWarnings(warnings, trace, ranking, root); RankRow? top = ranking.Rows.FirstOrDefault(); string? operationUnit = null; double? scopePerOperation = null; @@ -94,12 +93,11 @@ public static BatchRankingResult Analyze( scopePerOperation = ranking.ScopeWeight / captureCase.OperationCount!.Value; topPerOperation = top?.Weight / captureCase.OperationCount.Value; } - else if (captureCase.OperationCount is not null || captureCase.OperationUnit is not null) - { - CaptureManifestOutput.AddWarning( - warnings, - "per-operation values omitted: operationCount and operationUnit must both be present"); - } + + bool incompleteOperationMetadata = !captureCase.HasCompleteOperationMetadata + && (captureCase.OperationCount is not null || captureCase.OperationUnit is not null); + + AddQualityWarnings(warnings, trace, ranking, root, incompleteOperationMetadata); cases.Add(new BatchRankingCaseResult( benchmark, @@ -189,25 +187,14 @@ private static void AddQualityWarnings( List warnings, LoadedTrace trace, RankingResult ranking, - string root) + string root, + bool incompleteOperationMetadata) { CaptureManifestOutput.AddEventLossWarning(warnings, trace.Info); CaptureManifestOutput.AddCpuSampleWarning(warnings, trace.Info); - CaptureManifestOutput.AddOtherTraceWarnings(warnings, trace.Info); - - if (ContributingRecordQuality.TryGetMethodWarning( - trace.Source.RecordSemantics, - ranking.ContributingRecordCount, - out string? recordWarning)) - { - CaptureManifestOutput.AddWarning(warnings, recordWarning!); - } - - if (ranking.Rows.Count == 0) - { - CaptureManifestOutput.AddWarning(warnings, "query matched no ranked frames"); - } + bool rootMissing = false; + string? ambiguousRootWarning = null; if (!string.IsNullOrEmpty(root)) { FrameMatchReport report = FrameMatchAnalyzer.Analyze( @@ -215,17 +202,43 @@ private static void AddQualityWarnings( root, FrameMatchSelection.Outermost); - if (report.Matches.Count == 0) + rootMissing = report.Matches.Count == 0; + if (rootMissing) { CaptureManifestOutput.AddWarning(warnings, $"root '{root}' matched no frames"); } else if (report.IsAmbiguous) { - CaptureManifestOutput.AddWarning( - warnings, - $"root '{root}' matched {report.Matches.Count} frame definitions; outermost selected"); + ambiguousRootWarning = $"root '{root}' matched {report.Matches.Count} frame definitions; outermost selected"; } } + + if (incompleteOperationMetadata) + { + CaptureManifestOutput.AddWarning( + warnings, + "per-operation values omitted: operationCount and operationUnit must both be present"); + } + + if (ranking.Rows.Count == 0 && !rootMissing) + { + CaptureManifestOutput.AddWarning(warnings, "query matched no ranked frames"); + } + + if (ambiguousRootWarning is not null) + { + CaptureManifestOutput.AddWarning(warnings, ambiguousRootWarning); + } + + if (ContributingRecordQuality.TryGetMethodWarning( + trace.Source.RecordSemantics, + ranking.ContributingRecordCount, + out string? recordWarning)) + { + CaptureManifestOutput.AddWarning(warnings, recordWarning!); + } + + CaptureManifestOutput.AddOtherTraceWarnings(warnings, trace.Info); } private static bool IsCaseFailure(Exception exception) => diff --git a/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs b/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs index e8bd63e6..fcbcc1ec 100644 --- a/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs +++ b/src/Filtrace.Core/Tracing/CaptureManifestDiffAnalyzer.cs @@ -96,30 +96,69 @@ public static CaptureManifestDiffAnalysis Analyze( root, foldPatterns); - CaptureManifestOutput.AddEventLossWarning(caseWarnings, beforeTrace.Info, "baseline"); - CaptureManifestOutput.AddEventLossWarning(caseWarnings, afterTrace.Info, "current"); - CaptureManifestOutput.AddCpuSampleWarning(caseWarnings, beforeTrace.Info, "baseline"); - CaptureManifestOutput.AddCpuSampleWarning(caseWarnings, afterTrace.Info, "current"); - AddQualityWarnings(caseWarnings, "baseline", beforeTrace, beforeRanking, root); - AddQualityWarnings(caseWarnings, "current", afterTrace, afterRanking, root); RankingDiffResult diff = Diff( beforeRanking, afterRanking, rowsPerCase, pair.Before, pair.After, - caseWarnings); + out string? operationWarning); + + RootScopeCoverage? beforeRootCoverage = string.IsNullOrEmpty(root) + ? null + : beforeTrace.Aggregator.GetRootScopeCoverage(root); + + RootScopeCoverage? afterRootCoverage = string.IsNullOrEmpty(root) + ? null + : afterTrace.Aggregator.GetRootScopeCoverage(root); + + FrameMatchReport? beforeMatches = string.IsNullOrEmpty(root) + ? null + : FrameMatchAnalyzer.Analyze(beforeTrace.Source, root, FrameMatchSelection.Outermost); + + FrameMatchReport? afterMatches = string.IsNullOrEmpty(root) + ? null + : FrameMatchAnalyzer.Analyze(afterTrace.Source, root, FrameMatchSelection.Outermost); + + CaptureManifestOutput.AddPairCaptureWarning(caseWarnings, beforeTrace.Info, afterTrace.Info); + if (beforeMatches?.Matches.Count == 0) + { + CaptureManifestOutput.AddWarning(caseWarnings, $"baseline: root '{root}' matched no frames"); + } + + if (afterMatches?.Matches.Count == 0) + { + CaptureManifestOutput.AddWarning(caseWarnings, $"current: root '{root}' matched no frames"); + } + + if (operationWarning is not null) + { + CaptureManifestOutput.AddWarning(caseWarnings, operationWarning); + } + + if (beforeMatches?.IsAmbiguous == true) + { + CaptureManifestOutput.AddWarning( + caseWarnings, + $"baseline: root '{root}' matched {beforeMatches.Matches.Count} frame definitions; outermost selected"); + } + + if (afterMatches?.IsAmbiguous == true) + { + CaptureManifestOutput.AddWarning( + caseWarnings, + $"current: root '{root}' matched {afterMatches.Matches.Count} frame definitions; outermost selected"); + } + + AddOtherQualityWarnings(caseWarnings, "baseline", beforeTrace, beforeRanking); + AddOtherQualityWarnings(caseWarnings, "current", afterTrace, afterRanking); cases.Add(ToCaseResult( pair, diff, caseWarnings, - string.IsNullOrEmpty(root) - ? null - : beforeTrace.Aggregator.GetRootScopeCoverage(root), - string.IsNullOrEmpty(root) - ? null - : afterTrace.Aggregator.GetRootScopeCoverage(root))); + beforeRootCoverage, + afterRootCoverage)); } catch (Exception exception) when (!incompatibleUnits && IsCaseFailure(exception)) { @@ -194,8 +233,9 @@ private static RankingDiffResult Diff( int top, CaptureManifestCase beforeCase, CaptureManifestCase afterCase, - List warnings) + out string? operationWarning) { + operationWarning = null; if (beforeCase.HasCompleteOperationMetadata && afterCase.HasCompleteOperationMetadata && string.Equals( @@ -219,9 +259,7 @@ private static RankingDiffResult Diff( if (hasAnyOperationMetadata) { - CaptureManifestOutput.AddWarning( - warnings, - "per-operation values omitted: both cases require positive operationCount and the same operationUnit"); + operationWarning = "per-operation values omitted: both cases require positive operationCount and the same operationUnit"; } return RankingDiff.Diff(before, after, top); @@ -255,15 +293,12 @@ private static RankingDiffCaseResult ToCaseResult( ScopeWeightPerOperationDelta = diff.ScopeWeightPerOperationDelta }; - private static void AddQualityWarnings( + private static void AddOtherQualityWarnings( List warnings, string side, LoadedTrace trace, - RankingResult ranking, - string root) + RankingResult ranking) { - CaptureManifestOutput.AddOtherTraceWarnings(warnings, trace.Info, side); - if (ContributingRecordQuality.TryGetMethodWarning( trace.Source.RecordSemantics, ranking.ContributingRecordCount, @@ -272,26 +307,7 @@ private static void AddQualityWarnings( CaptureManifestOutput.AddWarning(warnings, $"{side}: {recordWarning}"); } - if (!string.IsNullOrEmpty(root)) - { - FrameMatchReport report = FrameMatchAnalyzer.Analyze( - trace.Source, - root, - FrameMatchSelection.Outermost); - - if (report.Matches.Count == 0) - { - CaptureManifestOutput.AddWarning( - warnings, - $"{side}: root '{root}' matched no frames"); - } - else if (report.IsAmbiguous) - { - CaptureManifestOutput.AddWarning( - warnings, - $"{side}: root '{root}' matched {report.Matches.Count} frame definitions; outermost selected"); - } - } + CaptureManifestOutput.AddOtherTraceWarnings(warnings, trace.Info, side); } private static bool IsCaseFailure(Exception exception) => diff --git a/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs b/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs index 2f13193b..8f94dba1 100644 --- a/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs +++ b/src/Filtrace.Core/Tracing/CaptureManifestOutput.cs @@ -2,6 +2,7 @@ // SPDX-License-Identifier: MIT // See LICENSE file in the project root for full license information +using System.Globalization; using Filtrace.Tracing.Readers; namespace Filtrace.Tracing; @@ -67,6 +68,65 @@ public static void AddEventLossWarning(List warnings, TraceInfo info, st } } + /// + /// Summarizes both diff arms' capture quality in one bounded warning so + /// root and per-operation diagnostics still have room in the case budget. + /// + /// The case warnings to append to. + /// The baseline trace's capture evidence. + /// The current trace's capture evidence. + public static void AddPairCaptureWarning(List warnings, TraceInfo baseline, TraceInfo current) + { + string? before = DescribeCapture(baseline); + string? after = DescribeCapture(current); + if (before is null && after is null) + { + return; + } + + List parts = []; + if (before is not null) + { + parts.Add($"baseline: {before}"); + } + + if (after is not null) + { + parts.Add($"current: {after}"); + } + + if (baseline.EventsLost > 0 || current.EventsLost > 0) + { + parts.Add("capture incomplete"); + } + + if (CpuSampleEvidence.ContainsSampleProfiler(baseline.CpuSampling) + || CpuSampleEvidence.ContainsSampleProfiler(current.CpuSampling)) + { + parts.Add("thread stacks are raw counts, not on-core CPU time or blocked-time percentages"); + } + + AddWarning(warnings, string.Join("; ", parts)); + } + + private static string? DescribeCapture(TraceInfo info) + { + string? source = info.CpuSampling?.Source switch + { + CpuSampleEvidence.SampleProfilerSource => "SampleProfiler", + CpuSampleEvidence.MixedSource => "mixed ETW/SampleProfiler", + _ => null + }; + + if (info.EventsLost <= 0) + { + return source; + } + + string loss = $"{info.EventsLost.ToString(CultureInfo.InvariantCulture)} lost events"; + return source is null ? loss : $"{loss}, {source}"; + } + /// /// Adds other trace-quality warnings after the reserved SampleProfiler warning. /// diff --git a/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs b/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs index 491d4084..13b476b4 100644 --- a/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs +++ b/tests/Filtrace.Core.Tests/CaptureManifestReaderTests.cs @@ -682,6 +682,35 @@ public void AnalyzeBatch_PrioritizedWarnings_AreNotDuplicated() warnings[2].Should().Be("Scoped to one process."); } + [TestMethod] + public void AnalyzeBatch_RootMismatchAndIncompleteMetadata_SurviveCaptureWarnings() + { + CpuSampleProvenance sampling = new( + "samples", CpuSampleEvidence.SampleProfilerSource, + TimeWeightsEstablished: false, UnknownIntervalSampleCount: 2, Intervals: []); + + LoadedTrace trace = Loaded( + "sampleprofiler", 1.0, 1.0, + warnings: ["scope one", "scope two", "scope three", "scope four"], + cpuSampling: sampling, + eventsLost: 4); + + CaptureManifest manifest = Manifest( + Case("sample", "Bench.Work", "Mode: Sample", "Sample") with { OperationCount = 10 }); + + BatchRankingResult result = CaptureManifestBatchAnalyzer.Analyze( + manifest, "cpu", inclusive: false, root: "Absent", FrameNames.DefaultFoldPatterns, + (_, _) => trace); + + BatchRankingCaseResult captureCase = result.Cases.Single(); + captureCase.TopFrame.Should().BeNull(); + captureCase.Warnings.Should().HaveCount(CaptureManifestOutput.MaxWarningsPerCase); + captureCase.Warnings[0].Should().StartWith("Trace records report 4 lost events"); + captureCase.Warnings[1].Should().StartWith("SampleProfiler thread-stack samples"); + captureCase.Warnings[2].Should().Contain("root 'Absent' matched no frames"); + captureCase.Warnings[3].Should().Contain("per-operation values omitted"); + } + [TestMethod] public void AnalyzeManifestDiff_LostEventsAndSampleProfiler_SurviveBothArmBudgets() { @@ -714,10 +743,73 @@ public void AnalyzeManifestDiff_LostEventsAndSampleProfiler_SurviveBothArmBudget IReadOnlyList warnings = analysis.Result.Cases.Single().Warnings; warnings.Should().HaveCount(CaptureManifestOutput.MaxWarningsPerCase); - warnings[0].Should().StartWith("baseline: Trace records report 4 lost events"); - warnings[1].Should().StartWith("current: Trace records report 7 lost events"); - warnings[2].Should().StartWith("baseline: SampleProfiler thread-stack samples"); - warnings[3].Should().StartWith("current: SampleProfiler thread-stack samples"); + warnings[0].Should().Contain("baseline: 4 lost events, SampleProfiler") + .And.Contain("current: 7 lost events, SampleProfiler") + .And.Contain("raw counts, not on-core CPU time"); + + warnings[1].Should().Be("baseline: first"); + } + + [TestMethod] + public void AnalyzeManifestDiff_RootMismatchAndMetadataFailure_SurviveBothCaptureArms() + { + CpuSampleProvenance sampling = new( + "samples", CpuSampleEvidence.SampleProfilerSource, + TimeWeightsEstablished: false, UnknownIntervalSampleCount: 2, Intervals: []); + + LoadedTrace baseline = Loaded("baseline", 1.0, 1.0, cpuSampling: sampling, eventsLost: 4); + LoadedTrace current = Loaded("current", 1.0, 1.0, cpuSampling: sampling, eventsLost: 7); + CaptureManifest before = Manifest( + Case("sample", "Bench.Work", "Mode: Sample", "Sample") with + { + OperationCount = 10, + OperationUnit = "items" + }); + + CaptureManifest after = Manifest( + Case("sample", "Bench.Work", "Mode: Sample", "Sample") with + { + OperationCount = 20, + OperationUnit = "operations" + }); + + CaptureManifestDiffAnalysis analysis = CaptureManifestDiffAnalyzer.Analyze( + before, after, inclusive: false, root: "Absent", + FrameNames.DefaultFoldPatterns, top: 5, + (manifest, _) => ReferenceEquals(manifest, before) ? baseline : current); + + RankingDiffCaseResult result = analysis.Result.Cases.Single(); + result.Rows.Should().BeEmpty(); + result.BeforeRootCoverage!.RetainedWeight.Should().Be(0.0); + result.AfterRootCoverage!.RetainedWeight.Should().Be(0.0); + result.Warnings.Should().HaveCount(CaptureManifestOutput.MaxWarningsPerCase); + result.Warnings[0].Should().Contain("baseline: 4 lost events, SampleProfiler") + .And.Contain("current: 7 lost events, SampleProfiler"); + + result.Warnings[1].Should().Contain("baseline: root 'Absent' matched no frames"); + result.Warnings[2].Should().Contain("current: root 'Absent' matched no frames"); + result.Warnings[3].Should().Contain("per-operation values omitted"); + } + + [TestMethod] + public void AddPairCaptureWarning_MaximumLossAndMixedSamples_StaysWithinCaseBudget() + { + CpuSampleProvenance sampling = new( + "samples", CpuSampleEvidence.MixedSource, + TimeWeightsEstablished: false, UnknownIntervalSampleCount: 2, Intervals: []); + + LoadedTrace baseline = Loaded("baseline", 1.0, 1.0, cpuSampling: sampling, eventsLost: int.MaxValue); + LoadedTrace current = Loaded("current", 1.0, 1.0, cpuSampling: sampling, eventsLost: int.MaxValue); + List warnings = []; + + CaptureManifestOutput.AddPairCaptureWarning(warnings, baseline.Info, current.Info); + + warnings.Should().ContainSingle(); + warnings[0].Length.Should().BeLessThanOrEqualTo(CaptureManifestOutput.MaxWarningLength); + warnings[0].Should().Contain("baseline: 2147483647 lost events") + .And.Contain("current: 2147483647 lost events") + .And.Contain("mixed ETW/SampleProfiler") + .And.Contain("raw counts, not on-core CPU time"); } [TestMethod] diff --git a/tools/Test-TrackDInvestigation.ps1 b/tools/Test-TrackDInvestigation.ps1 index d5f8e1df..f5878c6c 100644 --- a/tools/Test-TrackDInvestigation.ps1 +++ b/tools/Test-TrackDInvestigation.ps1 @@ -544,6 +544,114 @@ try { "Invalid profile number '$($invalidProfileNumber.Member)' value '$($invalidProfileNumber.Value)' type '$(if ($null -eq $invalidProfileNumber.Value) { '' } else { $invalidProfileNumber.Value.GetType().FullName })' was accepted or rejected incorrectly. Actual: $invalidNumberMessage" } + [object] $schema18SampleInfo = $schema17SampleInfoJson | ConvertFrom-Json -Depth 32 + $schema18SampleInfo.schemaVersion = 18 + $schema18SampleInfo.result.cpuSampling.source = 'sampleprofiler' + [object] $schema18SampleRank = $schema17SampleRank | + ConvertTo-Json -Depth 20 | ConvertFrom-Json -Depth 20 + $schema18SampleRank.schemaVersion = 18 + $schema18SampleRank.context.cpuSampling.source = 'sampleprofiler' + Write-Json (Join-Path $analysisEvidenceDirectory 'info.json') $schema18SampleInfo + Write-Json (Join-Path $analysisEvidenceDirectory 'rank.json') $schema18SampleRank + [System.Collections.IDictionary] $sampleProfilerEvidence = Get-AnalysisEvidence ` + $analysisEvidenceDirectory 'cpu' $true + Assert-True ` + ($sampleProfilerEvidence.schemaVersion -eq 18 -and + $sampleProfilerEvidence.weightUnit -ceq 'samples' -and + $sampleProfilerEvidence.cpuSampling.source -ceq 'sampleprofiler' -and + -not $sampleProfilerEvidence.cpuSampling.timeWeightsEstablished -and + $sampleProfilerEvidence.cpuSampling.unknownIntervalSampleCount -eq 128) ` + 'Schema 18 SampleProfiler counts were rejected or assigned CPU milliseconds.' + + [object] $mixedWithoutInterval = $schema18SampleInfo.result | + ConvertTo-Json -Depth 10 | ConvertFrom-Json -Depth 10 + $mixedWithoutInterval.cpuSampling.source = 'mixed-etw-sampleprofiler' + [object] $validatedMixedWithoutInterval = Get-ValidatedCpuSampling ` + $mixedWithoutInterval 18 'samples' 128 'mixed without ETW interval' + Assert-True ` + ($validatedMixedWithoutInterval.source -ceq 'mixed-etw-sampleprofiler' -and + $validatedMixedWithoutInterval.unknownIntervalSampleCount -eq 128) ` + 'Mixed sampling without ETW intervals did not retain raw-count provenance.' + + [object] $mixedWithInterval = $validEtwSampling | + ConvertTo-Json -Depth 10 | ConvertFrom-Json -Depth 10 + $mixedWithInterval.cpuSampling.source = 'mixed-etw-sampleprofiler' + [object] $validatedMixedWithInterval = Get-ValidatedCpuSampling ` + $mixedWithInterval 18 'samples' 128 'mixed with ETW interval' + Assert-True ` + ($validatedMixedWithInterval.source -ceq 'mixed-etw-sampleprofiler' -and + $validatedMixedWithInterval.unknownIntervalSampleCount -eq 27) ` + 'Mixed sampling with ETW intervals did not reconcile raw-count provenance.' + + [object[]] $invalidProviderCases = @( + @{ Name = 'sampleprofiler-time-claim'; Count = 128; Mutate = { + param($sampling) $sampling.cpuSampling.timeWeightsEstablished = $true + } }, + @{ Name = 'sampleprofiler-interval'; Count = 128; Mutate = { + param($sampling) + $sampling.cpuSampling.intervals = @([pscustomobject]@{ + intervalMSec = 1 + sampleCount = 128 + }) + } }, + @{ Name = 'sampleprofiler-count-mismatch'; Count = 128; Mutate = { + param($sampling) $sampling.cpuSampling.unknownIntervalSampleCount = 127 + } }, + @{ Name = 'sampleprofiler-no-records'; Count = 0; Mutate = { + param($sampling) $sampling.cpuSampling.unknownIntervalSampleCount = 0 + } }, + @{ Name = 'sampleprofiler-case-variant'; Count = 128; Mutate = { + param($sampling) $sampling.cpuSampling.source = 'SAMPLEPROFILER' + } }, + @{ Name = 'mixed-without-interval-count-mismatch'; Count = 128; Mutate = { + param($sampling) + $sampling.cpuSampling.source = 'mixed-etw-sampleprofiler' + $sampling.cpuSampling.unknownIntervalSampleCount = 127 + } }, + @{ Name = 'mixed-without-interval-one-record'; Count = 1; Mutate = { + param($sampling) + $sampling.cpuSampling.source = 'mixed-etw-sampleprofiler' + $sampling.cpuSampling.unknownIntervalSampleCount = 1 + } }, + @{ Name = 'mixed-with-interval-count-mismatch'; Count = 128; Mutate = { + param($sampling) + $sampling.cpuSampling.source = 'mixed-etw-sampleprofiler' + $sampling.cpuSampling.unknownIntervalSampleCount = 27 + $sampling.cpuSampling.intervals = @([pscustomobject]@{ + intervalMSec = 0.5 + sampleCount = 100 + }) + } }) + foreach ($case in $invalidProviderCases) { + [object] $invalidProvider = $schema18SampleInfo.result | + ConvertTo-Json -Depth 10 | ConvertFrom-Json -Depth 10 + & $case.Mutate $invalidProvider + [bool] $rejected = $false + try { + $null = Get-ValidatedCpuSampling ` + $invalidProvider 18 'samples' $case['Count'] "invalid '$($case.Name)'" + } + catch { + $rejected = $_.Exception.Message.Contains( + 'incompatible schema 17 CPU sampling provenance', + [StringComparison]::Ordinal) + } + Assert-True $rejected "Invalid provider case '$($case.Name)' was accepted." + } + + $schema18SampleRank.context.cpuSampling.source = 'unavailable' + Write-Json (Join-Path $analysisEvidenceDirectory 'rank.json') $schema18SampleRank + [bool] $mismatchedSourceRejected = $false + try { + $null = Get-AnalysisEvidence $analysisEvidenceDirectory 'cpu' $true + } + catch { + $mismatchedSourceRejected = $_.Exception.Message.Contains( + 'inconsistent info and rank CPU sampling provenance', + [StringComparison]::Ordinal) + } + Assert-True $mismatchedSourceRejected 'Schema 18 info/rank source mismatch was accepted.' + [string] $realAnalyzerName = if ($IsWindows) { 'filtrace.exe' } else { 'filtrace' } [string] $realAnalyzer = Join-Path ` $root ` @@ -606,7 +714,7 @@ try { Assert-True ` ($realCliEvidence.schemaVersion -eq 18 -and $realCliEvidence.weightUnit -ceq 'samples' -and - $realCliEvidence.cpuSampling.source -ceq 'unavailable' -and + $realCliEvidence.cpuSampling.source -ceq 'sampleprofiler' -and -not $realCliEvidence.cpuSampling.timeWeightsEstablished -and $realCliEvidence.eventCount -eq 11587 -and $realCliEvidence.summaries[0].scopeWeight -eq From 5d8213e93ee2412af173aa23998a8fc65417f480 Mon Sep 17 00:00:00 2001 From: Jeremy Kuhne Date: Tue, 29 Sep 2026 18:28:27 -0700 Subject: [PATCH 3/3] Report actual CPU sampling schema in Track D errors Pass the schema version through count conversion and provenance validation so malformed schema 18 results no longer report schema 17. Preserve accepted inputs and pin missing, malformed, and legacy errors in the Track D contract. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- benchmarks/Invoke-TrackDInvestigation.ps1 | 42 +++++++++-------- tools/Test-TrackDInvestigation.ps1 | 56 ++++++++++++++++++++++- 2 files changed, 79 insertions(+), 19 deletions(-) diff --git a/benchmarks/Invoke-TrackDInvestigation.ps1 b/benchmarks/Invoke-TrackDInvestigation.ps1 index 1d7f530b..e8c4f5b5 100644 --- a/benchmarks/Invoke-TrackDInvestigation.ps1 +++ b/benchmarks/Invoke-TrackDInvestigation.ps1 @@ -950,20 +950,22 @@ function Test-FiniteJsonNumber([object] $Value) { function ConvertTo-ValidatedSamplingCount( [object] $Value, - [string] $Owner) { + [string] $Owner, + [int] $SchemaVersion) { + [string] $provenanceError = "$Owner returned incompatible schema $SchemaVersion CPU sampling provenance." if ( -not (Test-FiniteJsonNumber $Value) -or [double]$Value -lt 0 -or [double]$Value -ne [Math]::Truncate([double]$Value) ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } try { return [Convert]::ToInt64($Value, [Globalization.CultureInfo]::InvariantCulture) } catch { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } } @@ -1027,12 +1029,13 @@ function Get-ValidatedCpuSampling( } } + [string] $provenanceError = "$Owner returned incompatible schema $SchemaVersion CPU sampling provenance." [object] $cpuSamplingProperty = $Container.PSObject.Properties['cpuSampling'] if ( $null -eq $cpuSamplingProperty -or $cpuSamplingProperty.Value -isnot [pscustomobject] ) { - throw "$Owner omitted schema 17 CPU sampling provenance." + throw "$Owner omitted schema $SchemaVersion CPU sampling provenance." } [object] $cpuSampling = $cpuSamplingProperty.Value [object] $weightUnitProperty = $cpuSampling.PSObject.Properties['weightUnit'] @@ -1055,16 +1058,17 @@ function Get-ValidatedCpuSampling( $intervalsProperty.Value.Count -gt 32 -or $ExpectedRecordCount -lt 0 ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } [long] $unknownIntervalSampleCount = ConvertTo-ValidatedSamplingCount ` $unknownCountProperty.Value ` - $Owner + $Owner ` + $SchemaVersion [long] $retainedIntervalSampleCount = 0 foreach ($interval in $intervalsProperty.Value) { if ($null -eq $interval) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } [object] $intervalProperty = $interval.PSObject.Properties['intervalMSec'] @@ -1075,18 +1079,19 @@ function Get-ValidatedCpuSampling( [double]$intervalProperty.Value -le 0 -or $null -eq $sampleCountProperty ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } [long] $sampleCount = ConvertTo-ValidatedSamplingCount ` $sampleCountProperty.Value ` - $Owner + $Owner ` + $SchemaVersion if ( $sampleCount -le 0 -or $sampleCount -gt $ExpectedRecordCount -or $retainedIntervalSampleCount -gt $ExpectedRecordCount - $sampleCount ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } $retainedIntervalSampleCount += $sampleCount } @@ -1098,13 +1103,13 @@ function Get-ValidatedCpuSampling( 0 } else { - ConvertTo-ValidatedSamplingCount $omittedSegmentsProperty.Value $Owner + ConvertTo-ValidatedSamplingCount $omittedSegmentsProperty.Value $Owner $SchemaVersion } [long] $omittedIntervalSampleCount = if ($null -eq $omittedSamplesProperty) { 0 } else { - ConvertTo-ValidatedSamplingCount $omittedSamplesProperty.Value $Owner + ConvertTo-ValidatedSamplingCount $omittedSamplesProperty.Value $Owner $SchemaVersion } [bool] $intervalsTruncated = if ($null -eq $truncatedProperty) { $false @@ -1113,14 +1118,14 @@ function Get-ValidatedCpuSampling( $truncatedProperty.Value } else { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } if ( $intervalsTruncated -ne ($omittedIntervalSegmentCount -gt 0) -or $omittedIntervalSampleCount -lt $omittedIntervalSegmentCount -or ($omittedIntervalSegmentCount -eq 0 -and $omittedIntervalSampleCount -ne 0) ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } [string] $source = [string]$sourceProperty.Value @@ -1152,7 +1157,7 @@ function Get-ValidatedCpuSampling( ($omittedIntervalSegmentCount -ne 0 -or $unknownIntervalSampleCount -ne $ExpectedRecordCount)))) ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } } elseif ( @@ -1163,7 +1168,7 @@ function Get-ValidatedCpuSampling( ($source -ceq 'speedscope-profile-declared-time-weights' -and ($intervalCount -ne 0 -or $intervalsTruncated)) ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } if ($source -cin @('etw-perfinfo', 'mixed-etw-sampleprofiler')) { @@ -1175,7 +1180,7 @@ function Get-ValidatedCpuSampling( $retainedIntervalSampleCount + $omittedIntervalSampleCount + $unknownIntervalSampleCount -ne $ExpectedRecordCount ) { - throw "$Owner returned incompatible schema 17 CPU sampling provenance." + throw $provenanceError } } @@ -1544,7 +1549,8 @@ function Get-AnalysisEvidence( } $retainedSampleCount = ConvertTo-ValidatedSamplingCount ` $sampleCountProperty.Value ` - "Profile analysis '$AnalysisName' info" + "Profile analysis '$AnalysisName' info" ` + $schemaVersion [object] $infoCpuSamplingProperty = $resultProperty.Value.PSObject.Properties['cpuSampling'] [object] $infoWeightUnitProperty = if ( diff --git a/tools/Test-TrackDInvestigation.ps1 b/tools/Test-TrackDInvestigation.ps1 index f5878c6c..6ffeb075 100644 --- a/tools/Test-TrackDInvestigation.ps1 +++ b/tools/Test-TrackDInvestigation.ps1 @@ -597,6 +597,13 @@ try { @{ Name = 'sampleprofiler-count-mismatch'; Count = 128; Mutate = { param($sampling) $sampling.cpuSampling.unknownIntervalSampleCount = 127 } }, + @{ Name = 'sampleprofiler-malformed-count'; Count = 128; Mutate = { + param($sampling) $sampling.cpuSampling.unknownIntervalSampleCount = '128' + } }, + @{ Name = 'sampleprofiler-overflow-count'; Count = 128; Mutate = { + param($sampling) + $sampling.cpuSampling.unknownIntervalSampleCount = [double]9223372036854775808 + } }, @{ Name = 'sampleprofiler-no-records'; Count = 0; Mutate = { param($sampling) $sampling.cpuSampling.unknownIntervalSampleCount = 0 } }, @@ -621,6 +628,20 @@ try { intervalMSec = 0.5 sampleCount = 100 }) + } }, + @{ Name = 'mixed-malformed-interval-count'; Count = 128; Mutate = { + param($sampling) + $sampling.cpuSampling.source = 'mixed-etw-sampleprofiler' + $sampling.cpuSampling.unknownIntervalSampleCount = 27 + $sampling.cpuSampling.intervals = @([pscustomobject]@{ + intervalMSec = 0.5 + sampleCount = '101' + }) + } }, + @{ Name = 'mixed-malformed-omitted-count'; Count = 128; Mutate = { + param($sampling) + $sampling.cpuSampling.source = 'mixed-etw-sampleprofiler' + $sampling.cpuSampling | Add-Member omittedIntervalSampleCount '1' } }) foreach ($case in $invalidProviderCases) { [object] $invalidProvider = $schema18SampleInfo.result | @@ -633,12 +654,45 @@ try { } catch { $rejected = $_.Exception.Message.Contains( - 'incompatible schema 17 CPU sampling provenance', + 'incompatible schema 18 CPU sampling provenance', [StringComparison]::Ordinal) } Assert-True $rejected "Invalid provider case '$($case.Name)' was accepted." } + foreach ($version in @(17, 18)) { + [object] $missingProvenance = $schema18SampleInfo.result | + ConvertTo-Json -Depth 10 | ConvertFrom-Json -Depth 10 + $missingProvenance.PSObject.Properties.Remove('cpuSampling') + [bool] $missingRejected = $false + try { + $null = Get-ValidatedCpuSampling ` + $missingProvenance $version 'samples' 128 "missing schema $version" + } + catch { + $missingRejected = $_.Exception.Message.Contains( + "omitted schema $version CPU sampling provenance", + [StringComparison]::Ordinal) + } + Assert-True $missingRejected "Missing schema $version CPU sampling provenance was accepted." + } + + [object] $invalidRetainedCount = $schema18SampleInfo | + ConvertTo-Json -Depth 20 | ConvertFrom-Json -Depth 20 + $invalidRetainedCount.result.sampleCount = '128' + Write-Json (Join-Path $analysisEvidenceDirectory 'info.json') $invalidRetainedCount + [bool] $invalidRetainedRejected = $false + try { + $null = Get-AnalysisEvidence $analysisEvidenceDirectory 'cpu' $true + } + catch { + $invalidRetainedRejected = $_.Exception.Message.Contains( + 'incompatible schema 18 CPU sampling provenance', + [StringComparison]::Ordinal) + } + Assert-True $invalidRetainedRejected 'Malformed schema 18 retained sample count was accepted.' + Write-Json (Join-Path $analysisEvidenceDirectory 'info.json') $schema18SampleInfo + $schema18SampleRank.context.cpuSampling.source = 'unavailable' Write-Json (Join-Path $analysisEvidenceDirectory 'rank.json') $schema18SampleRank [bool] $mismatchedSourceRejected = $false