WIP: task profiling

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

@@ -3,7 +3,7 @@
 
 internal static class Program
 {
-    private static void Main()
+    private static async Task Main()
     {
         // Enable the SDK
         using (SentrySdk.Init(options =>
@@ -12,7 +12,7 @@ private static void Main()
                 // NOTE: ADD YOUR OWN DSN BELOW so you can see the events in your own Sentry account
                 "https://[email protected]/5428537";
 
-            options.Debug = true;
+            options.Debug = false;
             // options.AutoSessionTracking = true;
             options.IsGlobalModeEnabled = true;
             options.TracesSampleRate = 1.0;
@@ -26,32 +26,31 @@ private static void Main()
             options.AddIntegration(new ProfilingIntegration(TimeSpan.FromMilliseconds(500)));
         }))
         {
-            var tx = SentrySdk.StartTransaction("app", "run");
             var count = 10;
+
+            var sw = Stopwatch.StartNew();
+            var tx = SentrySdk.StartTransaction("FindPrimeNumber", "Sequential");
             for (var i = 0; i < count; i++)
             {
                 FindPrimeNumber(100000);
             }
-
             tx.Finish();
-            var sw = Stopwatch.StartNew();
-
-            // Flushing takes 10 seconds consistently?
+            Console.WriteLine("Sequential computation finished in " + sw.Elapsed);
             SentrySdk.Flush(TimeSpan.FromMinutes(5));
             Console.WriteLine("Flushed in " + sw.Elapsed);
+            await Task.Delay(500);
 
-            // is the second profile faster?
-            tx = SentrySdk.StartTransaction("app", "run");
-            count = 10;
-            for (var i = 0; i < count; i++)
+            sw.Restart();
+            tx = SentrySdk.StartTransaction("FindPrimeNumber", "Parallel");
+            var tasks = Enumerable.Range(1, count).ToList().Select(_ => Task.Run(async () =>
             {
                 FindPrimeNumber(100000);
-            }
-
+                await Task.Delay(500);
+                FindPrimeNumber(100000);
+            }));
+            await Task.WhenAll(tasks).ConfigureAwait(false);
             tx.Finish();
-            sw = Stopwatch.StartNew();
-
-            // Flushing takes 10 seconds consistently?
+            Console.WriteLine("Parallel computation finished in " + sw.Elapsed);
             SentrySdk.Flush(TimeSpan.FromMinutes(5));
             Console.WriteLine("Flushed in " + sw.Elapsed);
         }  // On Dispose: SDK closed, events queued are flushed/sent to Sentry

src/Sentry.Profiling/SampleProfileBuilder.cs

@@ -1,5 +1,6 @@
 using Microsoft.Diagnostics.Tracing;
 using Microsoft.Diagnostics.Tracing.Etlx;
+using Microsoft.Diagnostics.Tracing.Stacks;
 using Sentry.Extensibility;
 using Sentry.Protocol;
 
@@ -12,6 +13,9 @@ internal class SampleProfileBuilder
 {
     private readonly SentryOptions _options;
     private readonly TraceLog _traceLog;
+    private readonly ActivityComputer _activityComputer;
+    // private readonly StartStopActivityComputer _startStopActivityComputer;
+    private readonly MutableTraceEventStackSource _stackSource;
 
     // Output profile being built.
     public readonly SampleProfile Profile = new();
@@ -22,16 +26,28 @@ internal class SampleProfileBuilder
     // A dictionary from a CallStackIndex to an index in the output Profile.stacks.
     private readonly Dictionary<int, int> _stackIndexes = new();
 
+    // A dictionary from a StackSourceCallStackIndex to an index in the output Profile.stacks.
+    private readonly Dictionary<int, int> _stackSourceStackIndexes = new();
+
     // A sparse array mapping from a ThreadIndex to an index in Profile.Threads.
     private readonly Dictionary<int, int> _threadIndexes = new();
 
+    // A sparse array mapping from an ActivityIndex to an index in Profile.Threads.
+    private readonly Dictionary<int, int> _activityIndexes = new();
+
     // TODO make downsampling conditional once this is available: https://github.com/dotnet/runtime/issues/82939
     private readonly Downsampler _downsampler = new();
 
-    public SampleProfileBuilder(SentryOptions options, TraceLog traceLog)
+    public SampleProfileBuilder(
+        SentryOptions options,
+        TraceLog traceLog,
+        MutableTraceEventStackSource stackSource,
+        ActivityComputer activityComputer)
     {
         _options = options;
         _traceLog = traceLog;
+        _activityComputer = activityComputer;
+        _stackSource = stackSource;
     }
 
     internal void AddSample(TraceEvent data, double timestampMs)
@@ -43,29 +59,48 @@ internal void AddSample(TraceEvent data, double timestampMs)
             return;
         }
 
-        var callStackIndex = data.CallStackIndex();
-        if (callStackIndex == CallStackIndex.Invalid)
+        var activity = _activityComputer.GetCurrentActivity(thread);
+        if (activity is null)
         {
-            _options.DiagnosticLogger?.LogDebug("Encountered a Profiler Sample without an associated call stack. Skipping.");
+            _options.DiagnosticLogger?.LogDebug("Failed to get activity for a profiler sample. Skipping.");
             return;
         }
 
-        var threadIndex = AddThread(thread);
+        int threadIndex;
+        if (activity.IsThreadActivity)
+        {
+            threadIndex = AddThread(thread);
+        }
+        else
+        {
+            threadIndex = AddActivity(activity);
+        }
+
         if (threadIndex < 0)
         {
             _options.DiagnosticLogger?.LogDebug("Profiler Sample threadIndex is invalid. Skipping.");
             return;
         }
 
+        // We need custom sampling because the TraceLog dispatches events from a queue with a delay of about 2 seconds.
         if (!_downsampler.ShouldSample(threadIndex, timestampMs))
         {
             return;
         }
 
-        var stackIndex = AddStackTrace(callStackIndex);
+        int stackIndex;
+        if (activity.IsThreadActivity)
+        {
+            stackIndex = AddThreadStackTrace(data);
+        }
+        else
+        {
+            stackIndex = AddActivityStackTrace(thread, data);
+        }
+
         if (stackIndex < 0)
         {
-            _options.DiagnosticLogger?.LogDebug("Invalid stackIndex for Profiler Sample. Skipping.");
+            _options.DiagnosticLogger?.LogDebug("Encountered a Profiler Sample without an associated call stack. Skipping.");
             return;
         }
 
@@ -81,17 +116,50 @@ internal void AddSample(TraceEvent data, double timestampMs)
     /// Adds stack trace and frames, if missing.
     /// </summary>
     /// <returns>The index into the Profile's stacks list</returns>
-    private int AddStackTrace(CallStackIndex callstackIndex)
+    private int AddThreadStackTrace(TraceEvent data)
     {
-        var key = (int)callstackIndex;
+        var callStackIndex = data.CallStackIndex();
+        if (callStackIndex == CallStackIndex.Invalid)
+        {
+            return -1;
+        }
+
+        var key = (int)callStackIndex;
+        if (!_stackIndexes.TryGetValue(key, out var value))
+        {
+            Profile.Stacks.Add(CreateStackTrace(callStackIndex));
+            value = Profile.Stacks.Count - 1;
+            _stackIndexes[key] = value;
+        }
+        return value;
+    }
 
-        if (!_stackIndexes.ContainsKey(key))
+    /// <summary>
+    /// Adds stack trace and frames, if missing.
+    /// </summary>
+    /// <returns>The index into the Profile's stacks list</returns>
+    private int AddActivityStackTrace(TraceThread thread, TraceEvent data)
+    {
+        var stackSourceCallStackIndex = StackSourceCallStackIndex.Invalid;
+        lock (_stackSource)
+        {
+            stackSourceCallStackIndex = _activityComputer.GetCallStack(_stackSource, data,
+                null // TODO topThread => _startStopActivityComputer.GetCurrentStartStopActivityStack(_stackSource, thread, topThread)
+            );
+        }
+        if (stackSourceCallStackIndex == StackSourceCallStackIndex.Invalid)
         {
-            Profile.Stacks.Add(CreateStackTrace(callstackIndex));
-            _stackIndexes[key] = Profile.Stacks.Count - 1;
+            return -1;
         }
 
-        return _stackIndexes[key];
+        var key = (int)stackSourceCallStackIndex;
+        if (!_stackSourceStackIndexes.TryGetValue(key, out var value))
+        {
+            Profile.Stacks.Add(CreateStackTrace(stackSourceCallStackIndex));
+            value = Profile.Stacks.Count - 1;
+            _stackIndexes[key] = value;
+        }
+        return value;
     }
 
     private Internal.GrowableArray<int> CreateStackTrace(CallStackIndex callstackIndex)
@@ -100,16 +168,42 @@ private Internal.GrowableArray<int> CreateStackTrace(CallStackIndex callstackInd
         while (callstackIndex != CallStackIndex.Invalid)
         {
             var codeAddressIndex = _traceLog.CallStacks.CodeAddressIndex(callstackIndex);
-            if (codeAddressIndex != CodeAddressIndex.Invalid)
-            {
-                stackTrace.Add(AddStackFrame(codeAddressIndex));
-                callstackIndex = _traceLog.CallStacks.Caller(callstackIndex);
-            }
-            else
+            if (codeAddressIndex == CodeAddressIndex.Invalid)
             {
                 // No need to traverse further up the stack when we're on the thread/process.
                 break;
             }
+
+            stackTrace.Add(AddStackFrame(codeAddressIndex));
+            callstackIndex = _traceLog.CallStacks.Caller(callstackIndex);
+        }
+
+        stackTrace.Trim(10);
+        return stackTrace;
+    }
+
+    private Internal.GrowableArray<int> CreateStackTrace(StackSourceCallStackIndex callstackIndex)
+    {
+        var stackTrace = new Internal.GrowableArray<int>(10);
+        CodeAddressIndex codeAddressIndex;
+        while (callstackIndex != StackSourceCallStackIndex.Invalid
+            // GetFrameIndex() throws... seems to be happening on top thread frames for some reason...
+            && (callstackIndex - _stackSource.Interner.CallStackStartIndex) < _stackSource.Interner.CallStackCount)
+        {
+            lock (_stackSource)
+            {
+                var frameIndex = _stackSource.GetFrameIndex(callstackIndex);
+                codeAddressIndex = _stackSource.GetFrameCodeAddress(frameIndex);
+                if (codeAddressIndex == CodeAddressIndex.Invalid)
+                {
+                    // No need to traverse further up the stack when we're on the thread/process.
+                    break;
+                }
+
+                callstackIndex = _stackSource.GetCallerIndex(callstackIndex);
+            }
+
+            stackTrace.Add(AddStackFrame(codeAddressIndex));
         }
 
         stackTrace.Trim(10);
@@ -124,34 +218,58 @@ private int AddStackFrame(CodeAddressIndex codeAddressIndex)
     {
         var key = (int)codeAddressIndex;
 
-        if (!_frameIndexes.ContainsKey(key))
+        if (!_frameIndexes.TryGetValue(key, out var value))
         {
             Profile.Frames.Add(CreateStackFrame(codeAddressIndex));
-            _frameIndexes[key] = Profile.Frames.Count - 1;
+            value = Profile.Frames.Count - 1;
+            _frameIndexes[key] = value;
         }
 
-        return _frameIndexes[key];
+        return value;
     }
 
     /// <summary>
-    /// Check if the thread is already stored in the output Profile, or adds it.
+    /// Ensures the thread is stored in the output Profile.
     /// </summary>
-    /// <returns>The index to the output Profile frames array.</returns>
+    /// <returns>The index to the output Profile thread array.</returns>
     private int AddThread(TraceThread thread)
     {
         var key = (int)thread.ThreadIndex;
 
-        if (!_threadIndexes.ContainsKey(key))
+        if (!_threadIndexes.TryGetValue(key, out var value))
         {
-            Profile.Threads.Add(new()
-            {
-                Name = thread.ThreadInfo ?? $"Thread {thread.ThreadID}",
-            });
-            _threadIndexes[key] = Profile.Threads.Count - 1;
-            _downsampler.NewThreadAdded(_threadIndexes[key]);
+            value = AddSampleProfileThread(thread.ThreadInfo ?? $"Thread {thread.ThreadID}");
+            _threadIndexes[key] = value;
+        }
+
+        return value;
+    }
+
+    /// <summary>
+    /// Ensures the activity is stored in the output Profile as a Thread.
+    /// </summary>
+    /// <returns>The index to the output Profile thread array.</returns>
+    private int AddActivity(TraceActivity activity)
+    {
+        var key = (int)activity.Index;
+
+        if (!_activityIndexes.TryGetValue(key, out var value))
+        {
+            // Note: there's also activity.Name but it's rather verbose:
+            // '<Activity (continuation) Index="8" Thread="Thread (1652)" Create="216.744" Start="216.938" kind="TaskScheduled" RawID="0x2072a40000000004"/>'
+            value = AddSampleProfileThread($"Activity {activity.Path}");
+            _activityIndexes[key] = value;
         }
 
-        return _threadIndexes[key];
+        return value;
+    }
+
+    private int AddSampleProfileThread(string name)
+    {
+        Profile.Threads.Add(new() { Name = name });
+        var value = Profile.Threads.Count - 1;
+        _downsampler.NewThreadAdded(value);
+        return value;
     }
 
     private SentryStackFrame CreateStackFrame(CodeAddressIndex codeAddressIndex)