From 5a02d4ccb7f1fd56d2b9fe7e61527679ddcc73ee Mon Sep 17 00:00:00 2001 From: bgn64 Date: Tue, 5 May 2026 14:56:21 -0700 Subject: [PATCH 1/2] Fix thread-to-process misattribution in merged WPR traces For merged WPR traces (LogFileName == '[multiple files]'), the first pass built a ThreadToProcess mapping reflecting final thread ownership. The second pass reused this mapping, causing samples from reused thread IDs to be silently attributed to the wrong process. Always reopen the trace between passes so the second pass builds its ThreadToProcess mapping incrementally as events arrive, reflecting temporal thread ownership rather than final state. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs b/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs index dd1e7700..26f21db2 100644 --- a/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs +++ b/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs @@ -236,7 +236,7 @@ public RawProfileData ProcessEvents(ProfileLoadProgressHandler progressCallback, var userStackKeyToPendingSamples = new Dictionary>(); var profile = new RawProfileData(tracePath_, handleDotNetEvents_); - // Enable building of a thead ID -> process ID table + // Enable building of a thread ID -> process ID table // that is used for circular traces to get the event process ID // when it is not set in the trace (-1). var kernel = new KernelTraceEventParser(source_, KernelTraceEventParser.ParserTrackingOptions.ThreadToProcess); @@ -259,6 +259,13 @@ public RawProfileData ProcessEvents(ProfileLoadProgressHandler progressCallback, // Process the trace in case it's using circular buffers // to build the thread -> process ID table. source_.Process(); + + // Always reopen the trace for the main processing pass. This ensures + // the ThreadToProcess mapping is built from scratch during the pass, + // reflecting temporal thread ownership rather than final state. + // Without this, merged WPR traces ("[multiple files]") would resolve + // reused thread IDs to the wrong process for earlier samples. + kernel = ReopenTrace(); } // For ETL file, the image timestamp (needed to find a binary on a symbol server) From 030e74f2c9623afc61b208feb4f97c6e406eeefe Mon Sep 17 00:00:00 2001 From: bgn64 Date: Tue, 5 May 2026 14:59:05 -0700 Subject: [PATCH 2/2] Resolve unknown ProcessID in ETW samples using StackWalk events TraceEvent reports ProcessID = -1 for ~40% of PerfInfoSample events in WPR traces lacking ThreadDCStart rundown events. Previously these samples were silently dropped, causing significant undercounting vs WPA. StackWalk events immediately follow their PerfInfoSample in the event stream and reliably carry valid ProcessIDs. Use deferred same-pass resolution: when PerfInfoSample has PID=-1, defer sample creation until the following StackWalk event provides the correct ProcessID. A per-thread cache handles subsequent samples without deferral. Applied to all event handlers: PerfInfoSample, PerfInfoPMCSample, StackWalkStack, StackWalkStackKeyKernel, StackWalkStackKeyUser, and BuildProcessSummary. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../Profile/ETW/ETWEventProcessor.cs | 179 +++++++++++++++--- 1 file changed, 157 insertions(+), 22 deletions(-) diff --git a/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs b/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs index 26f21db2..5430d444 100644 --- a/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs +++ b/src/ProfileExplorerCore/Profile/ETW/ETWEventProcessor.cs @@ -163,20 +163,33 @@ ProfileProcess HandleProcessEvent(ProcessTraceData data) { HandleProcessEvent(data); }; + // Track per-thread ProcessID from StackWalk events for deferred resolution + // of PerfInfoSample events where TraceEvent reports ProcessID = -1. + var lastKnownThreadPid = new Dictionary(); + var pendingSamples = new Dictionary(); + kernel.PerfInfoSample += data => { if (cancelableTask.IsCanceled) { source_.StopProcessing(); } - // The thread ID -> process ID mapping is used internally. - if (data.ProcessID < 0) { - return; + int processId = data.ProcessID; + + // Resolve unknown ProcessID using last known PID for this thread. + if (processId < 0) { + if (!lastKnownThreadPid.TryGetValue(data.ThreadID, out processId)) { + // No known PID yet; store as pending for deferred StackWalk resolution. + var pendingWeight = TimeSpan.FromMilliseconds(samplingIntervalMS_); + var pendingTime = TimeSpan.FromMilliseconds(data.TimeStampRelativeMSec); + pendingSamples[data.ThreadID] = (pendingWeight, pendingTime); + return; + } } sampleId++; var sampleWeight = TimeSpan.FromMilliseconds(samplingIntervalMS_); var sampleTime = TimeSpan.FromMilliseconds(data.TimeStampRelativeMSec); - summaryBuilder.AddSample(sampleWeight, sampleTime, data.ProcessID); + summaryBuilder.AddSample(sampleWeight, sampleTime, processId); // Rebuild process list and update UI from time to time. if (sampleId - lastReportedSample >= SampleReportingInterval) { @@ -206,6 +219,22 @@ ProfileProcess HandleProcessEvent(ProcessTraceData data) { } }; + // Use StackWalk events to resolve ProcessID for threads where + // PerfInfoSample reports ProcessID = -1. + kernel.StackWalkStack += data => { + if (data.ProcessID >= 0) { + int tid = data.ThreadID; + lastKnownThreadPid[tid] = data.ProcessID; + + // Resolve any pending sample for this thread. + if (pendingSamples.TryGetValue(tid, out var pending)) { + pendingSamples.Remove(tid); + sampleId++; + summaryBuilder.AddSample(pending.Weight, pending.Time, data.ProcessID); + } + } + }; + // Go again over events and accumulate samples to build the process summary. source_.Process(); profile.Dispose(); @@ -236,6 +265,14 @@ public RawProfileData ProcessEvents(ProfileLoadProgressHandler progressCallback, var userStackKeyToPendingSamples = new Dictionary>(); var profile = new RawProfileData(tracePath_, handleDotNetEvents_); + // Track per-thread ProcessID from StackWalk events for deferred resolution + // of PerfInfoSample events where TraceEvent reports ProcessID = -1. + // StackWalk events immediately follow their PerfInfoSample in the event stream + // and reliably carry valid ProcessIDs even when PerfInfoSample doesn't. + var lastKnownThreadPid = new Dictionary(); + var pendingPidSamples = new Dictionary(); + // Enable building of a thread ID -> process ID table // that is used for circular traces to get the event process ID // when it is not set in the trace (-1). @@ -442,7 +479,36 @@ public RawProfileData ProcessEvents(ProfileLoadProgressHandler progressCallback, }; kernel.StackWalkStack += data => { - if (!IsAcceptedProcess(data.ProcessID)) { + int stackProcessId = data.ProcessID; + + // Track per-thread ProcessID from StackWalk events for resolving + // PerfInfoSample events where TraceEvent reports ProcessID = -1. + if (stackProcessId >= 0) { + lastKnownThreadPid[data.ThreadID] = stackProcessId; + } + else if (lastKnownThreadPid.TryGetValue(data.ThreadID, out int knownPid)) { + stackProcessId = knownPid; + } + + // Create any deferred sample whose PID was unknown at PerfInfoSample time. + if (pendingPidSamples.TryGetValue(data.ThreadID, out var pending)) { + pendingPidSamples.Remove(data.ThreadID); + + if (stackProcessId >= 0 && IsAcceptedProcess(stackProcessId)) { + var pendingCtx = profile.RentTempContext(stackProcessId, pending.ThreadId, pending.Cpu); + int pendingCtxId = profile.AddContext(pendingCtx); + var pendingSample = new ProfileSample(pending.IP, + TimeSpan.FromMilliseconds(pending.TimestampMs), + TimeSpan.FromMilliseconds(pending.WeightMs), + pending.IsKernelCode, pendingCtxId); + int pendingSampleId = profile.AddSample(pendingSample); + profile.ReturnContext(pendingCtxId); + perThreadLastSampleMap[data.ThreadID] = pendingSampleId; + perContextLastSampleMap[pendingCtxId] = pendingSampleId; + } + } + + if (!IsAcceptedProcess(stackProcessId)) { return; // Ignore events from other processes. } @@ -457,9 +523,9 @@ public RawProfileData ProcessEvents(ProfileLoadProgressHandler progressCallback, // Trace.WriteLine($" kernel {isKernelStack}, kernelStart {isKernelStackStart}"); // } - //Trace.WriteLine($"User stack {data.InstructionPointer(0):X}, proc {data.ProcessID}, name {data.ProcessName}, TS {data.EventTimeStampQPC}"); + //Trace.WriteLine($"User stack {data.InstructionPointer(0):X}, proc {stackProcessId}, name {data.ProcessName}, TS {data.EventTimeStampQPC}"); #endif - var context = profile.RentTempContext(data.ProcessID, data.ThreadID, data.ProcessorNumber); + var context = profile.RentTempContext(stackProcessId, data.ThreadID, data.ProcessorNumber); int contextId = profile.AddContext(context); int frameCount = data.FrameCount; ProfileStack kstack = null; @@ -537,11 +603,38 @@ public RawProfileData ProcessEvents(ProfileLoadProgressHandler progressCallback, }; kernel.StackWalkStackKeyKernel += data => { - if (!IsAcceptedProcess(data.ProcessID)) { + int keyKernelProcessId = data.ProcessID; + + if (keyKernelProcessId >= 0) { + lastKnownThreadPid[data.ThreadID] = keyKernelProcessId; + } + else if (lastKnownThreadPid.TryGetValue(data.ThreadID, out int knownPid)) { + keyKernelProcessId = knownPid; + } + + // Create any deferred sample whose PID was unknown at PerfInfoSample time. + if (pendingPidSamples.TryGetValue(data.ThreadID, out var pending)) { + pendingPidSamples.Remove(data.ThreadID); + + if (keyKernelProcessId >= 0 && IsAcceptedProcess(keyKernelProcessId)) { + var pendingCtx = profile.RentTempContext(keyKernelProcessId, pending.ThreadId, pending.Cpu); + int pendingCtxId = profile.AddContext(pendingCtx); + var pendingSample = new ProfileSample(pending.IP, + TimeSpan.FromMilliseconds(pending.TimestampMs), + TimeSpan.FromMilliseconds(pending.WeightMs), + pending.IsKernelCode, pendingCtxId); + int pendingSampleId = profile.AddSample(pendingSample); + profile.ReturnContext(pendingCtxId); + perThreadLastSampleMap[data.ThreadID] = pendingSampleId; + perContextLastSampleMap[pendingCtxId] = pendingSampleId; + } + } + + if (!IsAcceptedProcess(keyKernelProcessId)) { return; // Ignore events from other processes. } - var context = profile.RentTempContext(data.ProcessID, data.ThreadID, data.ProcessorNumber); + var context = profile.RentTempContext(keyKernelProcessId, data.ThreadID, data.ProcessorNumber); int contextId = profile.AddContext(context); int sampleId = perThreadLastSampleMap.GetValueOrDefault(data.ThreadID); @@ -569,11 +662,38 @@ public RawProfileData ProcessEvents(ProfileLoadProgressHandler progressCallback, }; kernel.StackWalkStackKeyUser += delegate(StackWalkRefTraceData data) { - if (!IsAcceptedProcess(data.ProcessID)) { + int keyUserProcessId = data.ProcessID; + + if (keyUserProcessId >= 0) { + lastKnownThreadPid[data.ThreadID] = keyUserProcessId; + } + else if (lastKnownThreadPid.TryGetValue(data.ThreadID, out int knownPid)) { + keyUserProcessId = knownPid; + } + + // Create any deferred sample whose PID was unknown at PerfInfoSample time. + if (pendingPidSamples.TryGetValue(data.ThreadID, out var pending)) { + pendingPidSamples.Remove(data.ThreadID); + + if (keyUserProcessId >= 0 && IsAcceptedProcess(keyUserProcessId)) { + var pendingCtx = profile.RentTempContext(keyUserProcessId, pending.ThreadId, pending.Cpu); + int pendingCtxId = profile.AddContext(pendingCtx); + var pendingSample = new ProfileSample(pending.IP, + TimeSpan.FromMilliseconds(pending.TimestampMs), + TimeSpan.FromMilliseconds(pending.WeightMs), + pending.IsKernelCode, pendingCtxId); + int pendingSampleId = profile.AddSample(pendingSample); + profile.ReturnContext(pendingCtxId); + perThreadLastSampleMap[data.ThreadID] = pendingSampleId; + perContextLastSampleMap[pendingCtxId] = pendingSampleId; + } + } + + if (!IsAcceptedProcess(keyUserProcessId)) { return; // Ignore events from other processes. } - var context = profile.RentTempContext(data.ProcessID, data.ThreadID, data.ProcessorNumber); + var context = profile.RentTempContext(keyUserProcessId, data.ThreadID, data.ProcessorNumber); int contextId = profile.AddContext(context); int sampleId = perThreadLastSampleMap.GetValueOrDefault(data.ThreadID); @@ -710,8 +830,11 @@ void HandlePerfInfoCollection(SampledProfileIntervalTraceData data, RawProfileDa }; kernel.PerfInfoSample += data => { - if (!IsAcceptedProcess(data.ProcessID)) { - return; // Ignore events from other processes. + int processId = data.ProcessID; + + // Resolve unknown ProcessID from cached StackWalk-based thread→process mapping. + if (processId < 0 && lastKnownThreadPid.TryGetValue(data.ThreadID, out int knownPid)) { + processId = knownPid; } // If the time since the last sample is greater than the sampling interval + some error margin, @@ -729,11 +852,6 @@ void HandlePerfInfoCollection(SampledProfileIntervalTraceData data, RawProfileDa perThreadLastTime = timestamp; - // Skip unknown process. - if (data.ProcessID < 0) { - return; - } - // Skip idle thread on non-kernel code. bool isKernelCode = data.ExecutingDPC || data.ExecutingISR; @@ -741,8 +859,20 @@ void HandlePerfInfoCollection(SampledProfileIntervalTraceData data, RawProfileDa return; } + if (processId < 0) { + // ProcessID still unknown — defer sample creation until the + // immediately-following StackWalk event provides a valid ProcessID. + pendingPidSamples[data.ThreadID] = ((long)data.InstructionPointer, timestamp, + weight, isKernelCode, data.ThreadID, cpu); + return; + } + + if (!IsAcceptedProcess(processId)) { + return; // Ignore events from other processes. + } + // Save sample. - var context = profile.RentTempContext(data.ProcessID, data.ThreadID, cpu); + var context = profile.RentTempContext(processId, data.ThreadID, cpu); int contextId = profile.AddContext(context); var sample = new ProfileSample((long)data.InstructionPointer, @@ -751,7 +881,6 @@ void HandlePerfInfoCollection(SampledProfileIntervalTraceData data, RawProfileDa isKernelCode, contextId); int sampleId = profile.AddSample(sample); profile.ReturnContext(contextId); - // Trace.WriteLine($"Sample {sampleId}, timestamp {timestamp}, IP {data.InstructionPointer:X} kernel {isKernelCode}, CPU {cpu}, thread {data.ThreadID}"); // Remember the sample, to be matched later with a call stack. perThreadLastSampleMap[data.ThreadID] = sampleId; @@ -781,11 +910,17 @@ void HandlePerfInfoCollection(SampledProfileIntervalTraceData data, RawProfileDa Trace.WriteLine("Enable PMC event handling"); kernel.PerfInfoPMCSample += data => { - if (!IsAcceptedProcess(data.ProcessID)) { + int pmcProcessId = data.ProcessID; + + if (pmcProcessId < 0) { + lastKnownThreadPid.TryGetValue(data.ThreadID, out pmcProcessId); + } + + if (!IsAcceptedProcess(pmcProcessId)) { return; // Ignore events from other processes. } - var context = profile.RentTempContext(data.ProcessID, data.ThreadID, data.ProcessorNumber); + var context = profile.RentTempContext(pmcProcessId, data.ThreadID, data.ProcessorNumber); int contextId = profile.AddContext(context); double timestamp = data.TimeStampRelativeMSec;