diff --git a/src/Management/src/Endpoint/Actuators/ThreadDump/EventPipeThreadDumper.cs b/src/Management/src/Endpoint/Actuators/ThreadDump/EventPipeThreadDumper.cs index 4270877b40..9acde2baca 100644 --- a/src/Management/src/Endpoint/Actuators/ThreadDump/EventPipeThreadDumper.cs +++ b/src/Management/src/Endpoint/Actuators/ThreadDump/EventPipeThreadDumper.cs @@ -88,12 +88,12 @@ public async Task> DumpThreadsAsync(CancellationToken cancella internal async Task CaptureLogOutputAsync(Func> action, CancellationToken cancellationToken) { - bool isLogEnabled = _logger.IsEnabled(LogLevel.Trace); + bool isTraceLogEnabled = _logger.IsEnabled(LogLevel.Trace); using var logStream = new MemoryStream(); Exception? error = null; TResult? result = default; - await using (TextWriter logWriter = isLogEnabled ? new StreamWriter(logStream, leaveOpen: true) : TextWriter.Null) + await using (TextWriter logWriter = isTraceLogEnabled ? new StreamWriter(logStream, leaveOpen: true) : TextWriter.Null) { try { @@ -108,7 +108,7 @@ internal async Task CaptureLogOutputAsync(Func CaptureLogOutputAsync(Func> GetThreadsFromEventPipeSessionAsync(EventPi var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); - List results = ReadStackSource(stackSource, symbolReader).ToList(); + List results = ReadStackSource(stackSource, symbolReader, logWriter).ToList(); - _logger.LogTrace("Finished thread walk."); + _logger.LogTrace("Finished thread walk, found {Count} results.", results.Count); return results; } finally @@ -231,12 +231,14 @@ private static SymbolReader CreateSymbolReader(TextWriter logWriter) }; } - private IEnumerable ReadStackSource(MutableTraceEventStackSource stackSource, SymbolReader symbolReader) + private IEnumerable ReadStackSource(MutableTraceEventStackSource stackSource, SymbolReader symbolReader, TextWriter logWriter) { var samplesForThread = new Dictionary>(); stackSource.ForEach(sample => { + logWriter.WriteLine($"[Steeltoe] Tracking sample: {sample}"); + StackSourceCallStackIndex stackIndex = sample.StackIndex; while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith(ThreadIdTemplate, StringComparison.Ordinal)) @@ -257,10 +259,17 @@ private IEnumerable ReadStackSource(MutableTraceEventStackSource sta } }); + // Workaround for Sonar bug, which incorrectly flags the code as unreachable. +#pragma warning disable S2589 // Boolean expressions should not be gratuitous + logWriter.WriteLine(samplesForThread.Count == 0 + ? "[Steeltoe] WARN: No managed samples found in memory dump." + : $"[Steeltoe] Start analyzing all {samplesForThread.Count} threads."); +#pragma warning restore S2589 // Boolean expressions should not be gratuitous + // For every thread recorded in our trace, use the first stack. foreach ((int threadId, List samples) in samplesForThread) { - _logger.LogDebug("Found {Stacks} stacks for thread {Thread}.", samples.Count, threadId); + logWriter.WriteLine($"[Steeltoe] Found {samples.Count} samples for thread {threadId}, analyzing the first one."); var threadInfo = new ThreadInfo { @@ -269,7 +278,13 @@ private IEnumerable ReadStackSource(MutableTraceEventStackSource sta ThreadName = $"Thread-{threadId:D5}" }; - List stackTrace = GetStackTrace(threadId, samples[0], stackSource, symbolReader).ToList(); + List stackTrace = GetStackTrace(threadId, samples[0], stackSource, symbolReader, logWriter).ToList(); + + if (logWriter != TextWriter.Null) + { + int managedCount = stackTrace.Count(frame => !frame.IsNativeMethod); + logWriter.WriteLine($"[Steeltoe] Found {managedCount} of {stackTrace.Count} frames in managed code for thread {threadId}."); + } foreach (StackTraceElement stackFrame in stackTrace) { @@ -289,10 +304,10 @@ private static int ExtractThreadId(string frameName) return int.Parse(frameName.AsSpan(ThreadIdTemplate.Length, firstIndex - ThreadIdTemplate.Length), CultureInfo.InvariantCulture); } - private IEnumerable GetStackTrace(int threadId, StackSourceSample stackSourceSample, TraceEventStackSource stackSource, - SymbolReader symbolReader) + private static IEnumerable GetStackTrace(int threadId, StackSourceSample stackSourceSample, TraceEventStackSource stackSource, + SymbolReader symbolReader, TextWriter logWriter) { - _logger.LogDebug("Processing thread with ID: {Thread}.", threadId); + logWriter.WriteLine($"[Steeltoe] Walking stack frames of thread {threadId}."); StackSourceCallStackIndex stackIndex = stackSourceSample.StackIndex; StackSourceFrameIndex frameIndex = stackSource.GetFrameIndex(stackIndex); diff --git a/src/Management/test/Endpoint.Test/Actuators/ThreadDump/EventPipeThreadDumperTest.cs b/src/Management/test/Endpoint.Test/Actuators/ThreadDump/EventPipeThreadDumperTest.cs index 01346608b3..0cedf51ef4 100644 --- a/src/Management/test/Endpoint.Test/Actuators/ThreadDump/EventPipeThreadDumperTest.cs +++ b/src/Management/test/Endpoint.Test/Actuators/ThreadDump/EventPipeThreadDumperTest.cs @@ -35,7 +35,12 @@ public async Task Can_resolve_source_location_from_pdb() StackTraceElement? backgroundThreadFrame = threads.SelectMany(thread => thread.StackTrace) .FirstOrDefault(frame => frame.MethodName == "BackgroundThreadCallback(class System.Object)"); - backgroundThreadFrame.Should().NotBeNull(); + if (backgroundThreadFrame == null) + { + string logs = loggerProvider.GetAsText(); + throw new InvalidOperationException($"Failed to find expected stack frame. Captured log:{System.Environment.NewLine}{logs}"); + } + backgroundThreadFrame.IsNativeMethod.Should().BeFalse(); backgroundThreadFrame.ModuleName.Should().Be(GetType().Assembly.GetName().Name); backgroundThreadFrame.ClassName.Should().Be(typeof(NestedType).FullName);