From 71c61ca1253fa25100210b5216867d1e68458da2 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Thu, 6 Feb 2025 14:29:07 +0100 Subject: [PATCH 1/5] fix: net8 unknown stack trace methods for JIT methods --- src/Sentry.Profiling/SampleProfilerSession.cs | 30 ++++++++------- .../SamplingTransactionProfilerTests.cs | 38 ++++++++++++++++++- 2 files changed, 53 insertions(+), 15 deletions(-) diff --git a/src/Sentry.Profiling/SampleProfilerSession.cs b/src/Sentry.Profiling/SampleProfilerSession.cs index 3bb606a960..fda42d3c31 100644 --- a/src/Sentry.Profiling/SampleProfilerSession.cs +++ b/src/Sentry.Profiling/SampleProfilerSession.cs @@ -12,7 +12,6 @@ namespace Sentry.Profiling; internal class SampleProfilerSession : IDisposable { private readonly EventPipeSession _session; - private readonly TraceLogEventSource _eventSource; private readonly SampleProfilerTraceEventParser _sampleEventParser; private readonly IDiagnosticLogger? _logger; private readonly SentryStopwatch _stopwatch; @@ -22,21 +21,21 @@ private SampleProfilerSession(SentryStopwatch stopwatch, EventPipeSession sessio { _session = session; _logger = logger; - _eventSource = eventSource; - _sampleEventParser = new SampleProfilerTraceEventParser(_eventSource); + EventSource = eventSource; + _sampleEventParser = new SampleProfilerTraceEventParser(EventSource); _stopwatch = stopwatch; } // Exposed only for benchmarks. internal static EventPipeProvider[] Providers = new[] { - // Note: all events we need issued by "DotNETRuntime" provider are at "EventLevel.Informational" - // see https://learn.microsoft.com/en-us/dotnet/fundamentals/diagnostics/runtime-events - // TODO replace Keywords.Default with a subset. Currently it is: - // Default = GC | Type | GCHeapSurvivalAndMovement | Binder | Loader | Jit | NGen | SupressNGen - // | StopEnumeration | Security | AppDomainResourceManagement | Exception | Threading | Contention | Stack | JittedMethodILToNativeMap - // | ThreadTransfer | GCHeapAndTypeNames | Codesymbols | Compilation, - new EventPipeProvider(ClrTraceEventParser.ProviderName, EventLevel.Informational, (long) ClrTraceEventParser.Keywords.Default), + new EventPipeProvider(ClrTraceEventParser.ProviderName, EventLevel.Verbose, (long) ( + ClrTraceEventParser.Keywords.Jit + | ClrTraceEventParser.Keywords.NGen + | ClrTraceEventParser.Keywords.Loader + | ClrTraceEventParser.Keywords.Binder + | ClrTraceEventParser.Keywords.JittedMethodILToNativeMap + )), new EventPipeProvider(SampleProfilerTraceEventParser.ProviderName, EventLevel.Informational), // new EventPipeProvider(TplEtwProviderTraceEventParser.ProviderName, EventLevel.Informational, (long) TplEtwProviderTraceEventParser.Keywords.Default) }; @@ -46,11 +45,14 @@ private SampleProfilerSession(SentryStopwatch stopwatch, EventPipeSession sessio // need a large buffer if we're connecting righ away. Leaving it too large increases app memory usage. internal static int CircularBufferMB = 16; + // Exposed for tests + internal TraceLogEventSource EventSource { get; } + public SampleProfilerTraceEventParser SampleEventParser => _sampleEventParser; public TimeSpan Elapsed => _stopwatch.Elapsed; - public TraceLog TraceLog => _eventSource.TraceLog; + public TraceLog TraceLog => EventSource.TraceLog; // default is false, set 1 for true. private static int _throwOnNextStartupForTests = 0; @@ -108,7 +110,7 @@ public async Task WaitForFirstEventAsync(CancellationToken cancellationToken = d { var tcs = new TaskCompletionSource(); var cb = (TraceEvent _) => { tcs.TrySetResult(); }; - _eventSource.AllEvents += cb; + EventSource.AllEvents += cb; try { // Wait for the first event to be processed. @@ -116,7 +118,7 @@ public async Task WaitForFirstEventAsync(CancellationToken cancellationToken = d } finally { - _eventSource.AllEvents -= cb; + EventSource.AllEvents -= cb; } } @@ -128,8 +130,8 @@ public void Stop() { _stopped = true; _session.Stop(); + EventSource.Dispose(); _session.Dispose(); - _eventSource.Dispose(); } catch (Exception ex) { diff --git a/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs b/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs index 12bdcc5995..1a87e4c844 100644 --- a/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs +++ b/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs @@ -1,4 +1,5 @@ -using System.IO.Abstractions.TestingHelpers; +using Microsoft.Diagnostics.Tracing; +using Microsoft.Diagnostics.Tracing.Parsers.Clr; using Sentry.Internal.Http; namespace Sentry.Profiling.Tests; @@ -180,6 +181,41 @@ public async Task Profiler_AfterTimeout_Stops() } } + [SkippableFact] + public async Task EventPipeSession_ReceivesExpectedCLREvents() + { + SampleProfilerSession? session = null; + SkipIfFailsInCI(() => session = SampleProfilerSession.StartNew(_testOutputLogger)); + using (session) + { + var eventsReceived = new HashSet(); + session!.EventSource.Clr.All += (TraceEvent ev) => eventsReceived.Add(ev.EventName); + + var loadedMethods = new HashSet(); + session!.EventSource.Clr.MethodLoadVerbose += (MethodLoadUnloadVerboseTraceData ev) => loadedMethods.Add(ev.MethodName); + + + await session.WaitForFirstEventAsync(CancellationToken.None); + var limitMs = 50; + var sut = new SamplingTransactionProfiler(_testSentryOptions, session, limitMs, CancellationToken.None); + RunForMs(limitMs * 5); + MethodToBeLoaded(100); + RunForMs(limitMs * 5); + sut.Finish(); + + Assert.Contains("Method/LoadVerbose", eventsReceived); + Assert.Contains("Method/ILToNativeMap", eventsReceived); + Assert.Contains("Method/UnloadVerbose", eventsReceived); + + Assert.Contains("MethodToBeLoaded", loadedMethods); + } + } + + private static long MethodToBeLoaded(int n) + { + return -n; + } + [SkippableTheory] [InlineData(true)] [InlineData(false)] From ec27490a39e744dda99918dc25ee43b9b461bbb5 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Thu, 6 Feb 2025 14:39:12 +0100 Subject: [PATCH 2/5] chore: changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index af09754d95..6fdc6517ae 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,6 +22,7 @@ - Prevent Native EXC_BAD_ACCESS signal errors from being captured when managed NullRefrenceExceptions occur ([#3909](https://github.com/getsentry/sentry-dotnet/pull/3909)) - Fixed duplicate SentryMauiEventProcessors ([#3905](https://github.com/getsentry/sentry-dotnet/pull/3905)) - Fixed invalid string.Format index in Debug logs for the DiagnosticSource integration ([#3923](https://github.com/getsentry/sentry-dotnet/pull/3923)) +- Unknown stack frames in profiles on .NET 8+ ([#3942](https://github.com/getsentry/sentry-dotnet/pull/3942)) ### Dependencies From bd58c2180790b0d53cb3065b292dbeb99d14cbfa Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Thu, 6 Feb 2025 14:54:37 +0100 Subject: [PATCH 3/5] chore: fix changelog --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6fdc6517ae..53aab718fa 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ ### Fixes - OTel activities that are marked as not recorded are no longer sent to Sentry ([#3890](https://github.com/getsentry/sentry-dotnet/pull/3890)) +- Unknown stack frames in profiles on .NET 8+ ([#3942](https://github.com/getsentry/sentry-dotnet/pull/3942)) ## 5.1.0 @@ -22,7 +23,6 @@ - Prevent Native EXC_BAD_ACCESS signal errors from being captured when managed NullRefrenceExceptions occur ([#3909](https://github.com/getsentry/sentry-dotnet/pull/3909)) - Fixed duplicate SentryMauiEventProcessors ([#3905](https://github.com/getsentry/sentry-dotnet/pull/3905)) - Fixed invalid string.Format index in Debug logs for the DiagnosticSource integration ([#3923](https://github.com/getsentry/sentry-dotnet/pull/3923)) -- Unknown stack frames in profiles on .NET 8+ ([#3942](https://github.com/getsentry/sentry-dotnet/pull/3942)) ### Dependencies From d865e36922ebc986b00164a17e01183bd24ba2c6 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Thu, 6 Feb 2025 15:46:18 +0100 Subject: [PATCH 4/5] remove problematic assertion --- test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs b/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs index 1a87e4c844..ac1855c6be 100644 --- a/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs +++ b/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs @@ -205,7 +205,6 @@ public async Task EventPipeSession_ReceivesExpectedCLREvents() Assert.Contains("Method/LoadVerbose", eventsReceived); Assert.Contains("Method/ILToNativeMap", eventsReceived); - Assert.Contains("Method/UnloadVerbose", eventsReceived); Assert.Contains("MethodToBeLoaded", loadedMethods); } From 4efb3840deefd76d51c30d2aa14f09d62a7eddf7 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Thu, 6 Feb 2025 18:01:00 +0100 Subject: [PATCH 5/5] fix: dispose before processing is done --- src/Sentry.Profiling/SampleProfilerSession.cs | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/src/Sentry.Profiling/SampleProfilerSession.cs b/src/Sentry.Profiling/SampleProfilerSession.cs index fda42d3c31..6cd9a9242a 100644 --- a/src/Sentry.Profiling/SampleProfilerSession.cs +++ b/src/Sentry.Profiling/SampleProfilerSession.cs @@ -16,14 +16,16 @@ internal class SampleProfilerSession : IDisposable private readonly IDiagnosticLogger? _logger; private readonly SentryStopwatch _stopwatch; private bool _stopped = false; + private Task _processing; - private SampleProfilerSession(SentryStopwatch stopwatch, EventPipeSession session, TraceLogEventSource eventSource, IDiagnosticLogger? logger) + private SampleProfilerSession(SentryStopwatch stopwatch, EventPipeSession session, TraceLogEventSource eventSource, Task processing, IDiagnosticLogger? logger) { _session = session; _logger = logger; EventSource = eventSource; _sampleEventParser = new SampleProfilerTraceEventParser(EventSource); _stopwatch = stopwatch; + _processing = processing; } // Exposed only for benchmarks. @@ -88,7 +90,7 @@ public static SampleProfilerSession StartNew(IDiagnosticLogger? logger = null) var eventSource = TraceLog.CreateFromEventPipeSession(session, TraceLog.EventPipeRundownConfiguration.Enable(client)); // Process() blocks until the session is stopped so we need to run it on a separate thread. - Task.Factory.StartNew(eventSource.Process, TaskCreationOptions.LongRunning) + var processing = Task.Factory.StartNew(eventSource.Process, TaskCreationOptions.LongRunning) .ContinueWith(_ => { if (_.Exception?.InnerException is { } e) @@ -97,7 +99,7 @@ public static SampleProfilerSession StartNew(IDiagnosticLogger? logger = null) } }, TaskContinuationOptions.OnlyOnFaulted); - return new SampleProfilerSession(stopWatch, session, eventSource, logger); + return new SampleProfilerSession(stopWatch, session, eventSource, processing, logger); } catch (Exception ex) { @@ -130,8 +132,9 @@ public void Stop() { _stopped = true; _session.Stop(); - EventSource.Dispose(); + _processing.Wait(); _session.Dispose(); + EventSource.Dispose(); } catch (Exception ex) {