.NET profiler improvements & test fixes (#2968)

benchmarks/Sentry.Benchmarks/ProfilingBenchmarks.cs

@@ -18,7 +18,7 @@ public class ProfilingBenchmarks
     [GlobalSetup(Targets = new string[] { nameof(Transaction), nameof(DoHardWorkWhileProfiling) })]
     public void StartProfiler()
     {
-        _factory = SamplingTransactionProfilerFactory.Create(new());
+        _factory = new SamplingTransactionProfilerFactory(new(), TimeSpan.FromSeconds(5));
     }
 
     [GlobalCleanup(Targets = new string[] { nameof(Transaction), nameof(DoHardWorkWhileProfiling) })]

samples/Sentry.Samples.Console.Profiling/Program.cs

@@ -18,10 +18,13 @@ private static void Main()
             options.IsGlobalModeEnabled = true;
             options.EnableTracing = true;
 
+            // Make sure to reduce the sampling rate in production.
+            options.ProfilesSampleRate = 1.0;
+
             // Debugging
             options.ShutdownTimeout = TimeSpan.FromMinutes(5);
 
-            options.AddIntegration(new ProfilingIntegration());
+            options.AddIntegration(new ProfilingIntegration(TimeSpan.FromMilliseconds(500)));
         }))
         {
             var tx = SentrySdk.StartTransaction("app", "run");

src/Sentry.Profiling/Downsampler.cs

@@ -7,7 +7,6 @@
 internal class Downsampler
 {
     private static double _samplingRateMs = (double)1_000 / 101; // 101 Hz
-    private double _samplingGapMs = _samplingRateMs * 0.9;
 
     // Maps from ThreadIndex to the last sample timestamp for that thread.
     private GrowableArray<double> _prevThreadSamples = new(10);
@@ -17,7 +16,7 @@ public void NewThreadAdded(int threadIndex)
         if (threadIndex >= _prevThreadSamples.Count)
         {
             _prevThreadSamples.Count = threadIndex + 1;
-            _prevThreadSamples[threadIndex] = Double.MinValue;
+            _prevThreadSamples[threadIndex] = double.MinValue;
         }
     }
 

src/Sentry.Profiling/ProfilingIntegration.cs

@@ -1,4 +1,5 @@
 using Sentry.Integrations;
+using Sentry.Extensibility;
 
 namespace Sentry.Profiling;
 
@@ -7,12 +8,39 @@ namespace Sentry.Profiling;
 /// </summary>
 public class ProfilingIntegration : ISdkIntegration
 {
+    private TimeSpan _startupTimeout;
+
+    /// <summary>
+    /// Initializes the profiling integration.
+    /// </summary>
+    /// <param name="startupTimeout">
+    /// If not given or TimeSpan.Zero, then the profiler initialization is asynchronous.
+    /// This is useful for applications that need to start quickly. The profiler will start in the background
+    /// and will be ready to capture transactions that have started after the profiler has started.
+    ///
+    /// If given a non-zero timeout, profiling startup blocks up to the given amount of time. If the timeout is reached
+    /// and the profiler session hasn't started yet, the execution is unblocked and behaves as the async startup,
+    /// i.e. transactions will be profiled only after the session is eventually started.
+    /// </param>
+    public ProfilingIntegration(TimeSpan startupTimeout = default)
+    {
+        Debug.Assert(TimeSpan.Zero == default);
+        _startupTimeout = startupTimeout;
+    }
+
     /// <inheritdoc/>
     public void Register(IHub hub, SentryOptions options)
     {
         if (options.IsProfilingEnabled)
         {
-            options.TransactionProfilerFactory ??= SamplingTransactionProfilerFactory.Create(options);
+            try
+            {
+                options.TransactionProfilerFactory ??= new SamplingTransactionProfilerFactory(options, _startupTimeout);
+            }
+            catch (Exception e)
+            {
+                options.LogError(e, "Failed to initialize the profiler");
+            }
         }
     }
 }

src/Sentry.Profiling/SampleProfileBuilder.cs

@@ -17,15 +17,14 @@ internal class SampleProfileBuilder
     // Output profile being built.
     public readonly SampleProfile Profile = new();
 
-    // TODO reevaluate the use of SparseArray after setting up continous profiling. Dictionary might be better.
     // A sparse array that maps from StackSourceFrameIndex to an index in the output Profile.frames.
-    private readonly SparseScalarArray<int> _frameIndexes = new(-1, 1000);
+    private readonly Dictionary<int, int> _frameIndexes = new();
 
     // A dictionary from a CallStackIndex to an index in the output Profile.stacks.
-    private readonly SparseScalarArray<int> _stackIndexes = new(100);
+    private readonly Dictionary<int, int> _stackIndexes = new();
 
     // A sparse array mapping from a ThreadIndex to an index in Profile.Threads.
-    private readonly SparseScalarArray<int> _threadIndexes = new(-1, 10);
+    private readonly Dictionary<int, int> _threadIndexes = new();
 
     // TODO make downsampling conditional once this is available: https://github.com/dotnet/runtime/issues/82939
     private readonly Downsampler _downsampler = new();
@@ -39,7 +38,7 @@ public SampleProfileBuilder(SentryOptions options, TraceLog traceLog)
     internal void AddSample(TraceEvent data, double timestampMs)
     {
         var thread = data.Thread();
-        if (thread.ThreadIndex == ThreadIndex.Invalid)
+        if (thread is null || thread.ThreadIndex == ThreadIndex.Invalid)
         {
             _options.DiagnosticLogger?.LogDebug("Encountered a Profiler Sample without a correct thread. Skipping.");
             return;
@@ -163,8 +162,7 @@ private SentryStackFrame CreateStackFrame(CodeAddressIndex codeAddressIndex)
         {
             frame.Function = method.FullMethodName;
 
-            TraceModuleFile moduleFile = method.MethodModuleFile;
-            if (moduleFile is not null)
+            if (method.MethodModuleFile is { } moduleFile)
             {
                 frame.Module = moduleFile.Name;
             }
@@ -173,15 +171,20 @@ private SentryStackFrame CreateStackFrame(CodeAddressIndex codeAddressIndex)
         }
         else
         {
-            // native frame
-            frame.InApp = false;
-        }
+            // Fall back if the method info is unknown, see more info on Symbol resolution in
+            // https://github.com/getsentry/perfview/blob/031250ffb4f9fcadb9263525d6c9f274be19ca51/src/PerfView/SupportFiles/UsersGuide.htm#L7745-L7784
+            frame.InstructionAddress = (long?)_traceLog.CodeAddresses.Address(codeAddressIndex);
 
-        // TODO enable this once we implement symbolication (we will need to send debug_meta too), see StackTraceFactory.
-        // if (_traceLog.CodeAddresses.Address(codeAddressIndex) is { } address)
-        // {
-        //     frame.InstructionAddress = $"0x{address:x}";
-        // }
+            if (_traceLog.CodeAddresses.ModuleFile(codeAddressIndex) is { } moduleFile)
+            {
+                frame.Module = moduleFile.Name;
+                frame.ConfigureAppFrame(_options);
+            }
+            else
+            {
+                frame.InApp = false;
+            }
+        }
 
         return frame;
     }

src/Sentry.Profiling/SampleProfilerSession.cs

@@ -1,5 +1,6 @@
 using System.Diagnostics.Tracing;
 using Microsoft.Diagnostics.NETCore.Client;
+using Microsoft.Diagnostics.Tracing;
 using Microsoft.Diagnostics.Tracing.Etlx;
 using Microsoft.Diagnostics.Tracing.EventPipe;
 using Microsoft.Diagnostics.Tracing.Parsers;
@@ -50,17 +51,60 @@ private SampleProfilerSession(SentryStopwatch stopwatch, EventPipeSession sessio
 
     public TraceLog TraceLog => _eventSource.TraceLog;
 
+    internal static bool ThrowOnNextStartupForTests = false;
+
     public static SampleProfilerSession StartNew(IDiagnosticLogger? logger = null)
     {
-        var client = new DiagnosticsClient(Process.GetCurrentProcess().Id);
-        var session = client.StartEventPipeSession(Providers, requestRundown: false, CircularBufferMB);
-        var stopWatch = SentryStopwatch.StartNew();
-        var eventSource = TraceLog.CreateFromEventPipeSession(session, TraceLog.EventPipeRundownConfiguration.Enable(client));
+        try
+        {
+            var client = new DiagnosticsClient(Environment.ProcessId);
+
+            if (ThrowOnNextStartupForTests)
+            {
+                ThrowOnNextStartupForTests = false;
+                throw new Exception("Test exception");
+            }
 
-        // Process() blocks until the session is stopped so we need to run it on a separate thread.
-        Task.Factory.StartNew(eventSource.Process, TaskCreationOptions.LongRunning);
+            // Note: StartEventPipeSession() can time out after 30 seconds on resource constrained systems.
+            // See https://github.com/dotnet/diagnostics/blob/991c78895323a953008e15fe34b736c03706afda/src/Microsoft.Diagnostics.NETCore.Client/DiagnosticsIpc/IpcClient.cs#L40C52-L40C52
+            var session = client.StartEventPipeSession(Providers, requestRundown: false, CircularBufferMB);
 
-        return new SampleProfilerSession(stopWatch, session, eventSource, logger);
+            var stopWatch = SentryStopwatch.StartNew();
+            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)
+                .ContinueWith(_ =>
+                {
+                    if (_.Exception?.InnerException is { } e)
+                    {
+                        logger?.LogWarning(e, "Error during sampler profiler EventPipeSession processing.");
+                    }
+                }, TaskContinuationOptions.OnlyOnFaulted);
+
+            return new SampleProfilerSession(stopWatch, session, eventSource, logger);
+        }
+        catch (Exception ex)
+        {
+            logger?.LogWarning(ex, "Error during sampler profiler EventPipeSession startup.");
+            throw;
+        }
+    }
+
+    public async Task WaitForFirstEventAsync(CancellationToken cancellationToken = default)
+    {
+        var tcs = new TaskCompletionSource();
+        var cb = (TraceEvent _) => { tcs.TrySetResult(); };
+        _eventSource.AllEvents += cb;
+        try
+        {
+            // Wait for the first event to be processed.
+            await tcs.Task.WaitAsync(cancellationToken).ConfigureAwait(false);
+        }
+        finally
+        {
+            _eventSource.AllEvents -= cb;
+        }
     }
 
     public void Stop()
@@ -76,7 +120,7 @@ public void Stop()
             }
             catch (Exception ex)
             {
-                _logger?.LogWarning("Error during sampler profiler session shutdown.", ex);
+                _logger?.LogWarning(ex, "Error during sampler profiler session shutdown.");
             }
         }
     }

src/Sentry.Profiling/SamplingTransactionProfiler.cs

@@ -75,11 +75,12 @@ private void OnThreadSample(TraceEvent data)
                 }
                 catch (Exception e)
                 {
-                    _options.LogWarning("Failed to process a profile sample.", e);
+                    _options.LogWarning(e, "Failed to process a profile sample.");
                 }
             }
             else
             {
+                _options.LogDebug("Profiler has been stopped and has received all the samples up to the end time.");
                 _session.SampleEventParser.ThreadSample -= OnThreadSample;
                 _completionSource.TrySetResult();
             }

src/Sentry.Profiling/SamplingTransactionProfilerFactory.cs

@@ -15,36 +15,58 @@ internal class SamplingTransactionProfilerFactory : IDisposable, ITransactionPro
     private const int TIME_LIMIT_MS = 30_000;
 
     private readonly SentryOptions _options;
-    private SampleProfilerSession _session;
 
-    public static SamplingTransactionProfilerFactory Create(SentryOptions options)
-    {
-        var session = SampleProfilerSession.StartNew(options.DiagnosticLogger);
-        return new SamplingTransactionProfilerFactory(options, session);
-    }
+    internal Task<SampleProfilerSession> _sessionTask;
 
-    public static async Task<SamplingTransactionProfilerFactory> CreateAsync(SentryOptions options)
-    {
-        var session = await Task.Run(() => SampleProfilerSession.StartNew(options.DiagnosticLogger)).ConfigureAwait(false);
-        return new SamplingTransactionProfilerFactory(options, session);
-    }
+    private bool _errorLogged = false;
 
-    private SamplingTransactionProfilerFactory(SentryOptions options, SampleProfilerSession session)
+    public SamplingTransactionProfilerFactory(SentryOptions options, TimeSpan startupTimeout)
     {
         _options = options;
-        _session = session;
+
+        _sessionTask = Task.Run(async () =>
+        {
+            // This can block up to 30 seconds. The timeout is out of our hands.
+            var session = SampleProfilerSession.StartNew(options.DiagnosticLogger);
+
+            // This can block indefinitely.
+            await session.WaitForFirstEventAsync().ConfigureAwait(false);
+
+            return session;
+        });
+
+        Debug.Assert(TimeSpan.FromSeconds(0) == TimeSpan.Zero);
+        if (startupTimeout != TimeSpan.Zero && !_sessionTask.Wait(startupTimeout))
+        {
+            options.LogWarning("Profiler session startup took longer then the given timeout {0:c}. Profilling will start once the first event is received.", startupTimeout);
+        }
     }
 
     /// <inheritdoc />
     public ITransactionProfiler? Start(ITransactionTracer _, CancellationToken cancellationToken)
     {
         // Start a profiler if one wasn't running yet.
-        if (Interlocked.Exchange(ref _inProgress, TRUE) == FALSE)
+        if (!_errorLogged && Interlocked.Exchange(ref _inProgress, TRUE) == FALSE)
         {
+            if (!_sessionTask.IsCompleted)
+            {
+                _options.LogWarning("Cannot start a sampling profiler, the session hasn't started yet.");
+                _inProgress = FALSE;
+                return null;
+            }
+
+            if (!_sessionTask.IsCompletedSuccessfully)
+            {
+                _options.LogWarning("Cannot start a sampling profiler because the session startup has failed. This is a permanent error and no future transactions will be sampled.");
+                _errorLogged = true;
+                _inProgress = FALSE;
+                return null;
+            }
+
             _options.LogDebug("Starting a sampling profiler.");
             try
             {
-                return new SamplingTransactionProfiler(_options, _session, TIME_LIMIT_MS, cancellationToken)
+                return new SamplingTransactionProfiler(_options, _sessionTask.Result, TIME_LIMIT_MS, cancellationToken)
                 {
                     OnFinish = () => _inProgress = FALSE
                 };
@@ -60,6 +82,6 @@ private SamplingTransactionProfilerFactory(SentryOptions options, SampleProfiler
 
     public void Dispose()
     {
-        _session.Dispose();
+        _sessionTask.ContinueWith(session => session.Dispose());
     }
 }

src/Sentry/Platforms/Cocoa/CFunctions.cs

@@ -31,7 +31,7 @@ internal static Dictionary<long, DebugImage> LoadDebugImages(IDiagnosticLogger?
         }
         catch (Exception e)
         {
-            logger?.LogWarning("Error loading the list of debug images", e);
+            logger?.LogWarning(e, "Error loading the list of debug images");
         }
         return result;
     }

src/Sentry/Platforms/Native/CFunctions.cs

@@ -296,7 +296,7 @@ private static Dictionary<long, DebugImage> LoadDebugImagesOnce(IDiagnosticLogge
         }
         catch (Exception e)
         {
-            logger?.LogWarning("Error loading the list of debug images", e);
+            logger?.LogWarning(e, "Error loading the list of debug images");
         }
         return result;
     }