[Core] Performance fixes in GameProfilingSystem and ChromeTracingProfileWriter

sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs

@@ -6,26 +6,38 @@
 using System.Text.Json;
 using System.Threading.Channels;
 using System.Threading.Tasks;
+using System.Threading;
+using System;
 
 namespace Stride.Core.Diagnostics
 {
+    /// <summary>
+    /// The chrome tracing profile writer exports diagnotic events into the chrome tracing format.
+    /// You view the file using chrome://tracing in your browser.
+    /// </summary>
     public class ChromeTracingProfileWriter
     {
+        /// <summary>
+        /// Create a tracing file at <paramref name="outputPath"/> and start writing events to it.
+        /// </summary>
+        /// <param name="outputPath">Path where to create the tracing file.</param>
+        /// <param name="indentOutput">Whether to indent output JSON. False by default for perfomance/size over readability.</param>
         public void Start(string outputPath, bool indentOutput = false)
         {
             eventReader = Profiler.Subscribe();
+            cts = new CancellationTokenSource();
             writerTask = Task.Run(async () =>
             {
                 var pid = Process.GetCurrentProcess().Id;
 
-                using FileStream fs = File.Create(outputPath);
-                using var writer = new Utf8JsonWriter(fs, options: new JsonWriterOptions { Indented = indentOutput });
+                using FileStream fs = File.Create(outputPath, 1024 * 1024);
+                using var writer = new Utf8JsonWriter(fs, options: new JsonWriterOptions { Indented = indentOutput, SkipValidation = true });
 
                 JsonObject root = new JsonObject();
 
                 writer.WriteStartObject();
                 writer.WriteStartArray("traceEvents");
-  
+
                 writer.WriteStartObject();
                 writer.WriteString("name", "thread_name");
                 writer.WriteString("ph", "M");
@@ -45,56 +57,75 @@ public void Start(string outputPath, bool indentOutput = false)
                 writer.WriteEndObject();
                 writer.WriteEndObject();
 
-                await foreach (var e in eventReader.ReadAllAsync())
-                {                    
-                    //gc scopes currently start at negative timestamps and should be filtered out,
-                    //because they don't represent durations.
-                    if (e.TimeStamp.Ticks < 0)
-                        continue;
+                try
+                {
+                    await foreach (var e in eventReader.ReadAllAsync(cts.Token))
+                    {
+                        //gc scopes currently start at negative timestamps and should be filtered out,
+                        //because they don't represent durations.
+                        if (e.TimeStamp.Ticks < 0)
+                            continue;
 
-                    double startTimeInMicroseconds = e.TimeStamp.TotalMilliseconds * 1000.0;
-                    double durationInMicroseconds = e.ElapsedTime.TotalMilliseconds * 1000.0;
+                        double startTimeInMicroseconds = e.TimeStamp.TotalMilliseconds * 1000.0;
+                        double durationInMicroseconds = e.ElapsedTime.TotalMilliseconds * 1000.0;
 
-                    Debug.Assert(durationInMicroseconds >= 0);
+                        Debug.Assert(durationInMicroseconds >= 0);
 
-                    writer.WriteStartObject();
-                    writer.WriteString("name", e.Key.Name);
-                    if (e.Key.Parent != null)
-                        writer.WriteString("cat", e.Key.Parent.Name);
-                    writer.WriteString("ph", "X");
-                    writer.WriteNumber("ts", startTimeInMicroseconds);
-                    writer.WriteNumber("dur", durationInMicroseconds);
-                    writer.WriteNumber("tid", e.ThreadId>=0?e.ThreadId: int.MaxValue);
-                    writer.WriteNumber("pid", pid);
-                    if (e.Attributes.Count > 0)
-                    {
-                        writer.WriteStartObject("args");
-                        foreach (var (k,v) in e.Attributes)
+                        writer.WriteStartObject();
+                        writer.WriteString("name", e.Key.Name);
+                        if (e.Key.Parent != null)
+                            writer.WriteString("cat", e.Key.Parent.Name);
+                        writer.WriteString("ph", "X");
+                        writer.WriteNumber("ts", startTimeInMicroseconds);
+                        writer.WriteNumber("dur", durationInMicroseconds);
+                        writer.WriteNumber("tid", e.ThreadId >= 0 ? e.ThreadId : int.MaxValue);
+                        writer.WriteNumber("pid", pid);
+                        if (e.Attributes.Count > 0)
                         {
-                            writer.WriteString(k, v.ToString());
-                        }                        
+                            writer.WriteStartObject("args");
+                            foreach (var (k, v) in e.Attributes)
+                            {
+                                writer.WriteString(k, v.ToString());
+                            }
+                            writer.WriteEndObject();
+                        }
                         writer.WriteEndObject();
+
+                        if (writer.BytesPending >= 1024 * 1024)
+                        {
+                            await writer.FlushAsync();
+                        }
                     }
-                    writer.WriteEndObject();
                 }
+                catch (OperationCanceledException) { } // cancellation was requested, let's finish
 
                 writer.WriteEndArray();
                 writer.WriteEndObject();
                 writer.Flush();
             });
         }
 
+        /// <summary>
+        /// Stop the profiling session and wait for the file to be flushed.
+        /// </summary>
         public void Stop()
         {
             if (eventReader != null)
             {
                 Profiler.Unsubscribe(eventReader);
+                eventReader = null;
+
+                cts?.Cancel();
+                cts?.Dispose();
+
                 writerTask?.Wait();
             }
         }
+
 #nullable enable
         ChannelReader<ProfilingEvent>? eventReader;
         Task? writerTask;
+        CancellationTokenSource? cts;
 #nullable disable
     }
 

sources/core/Stride.Core/Diagnostics/Profiler.cs

@@ -1,6 +1,7 @@
 // Copyright (c) .NET Foundation and Contributors (https://dotnetfoundation.org/ & https://stride3d.net) and Silicon Studio Corp. (https://www.siliconstudio.co.jp)
 // Distributed under the MIT license. See the LICENSE.md file in the project root for more information.
 using System;
+using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Text;
@@ -64,9 +65,15 @@ public static class Profiler
     {
         internal class ProfilingEventChannel
         {
-            internal static ProfilingEventChannel Create(UnboundedChannelOptions options)
+            internal static ProfilingEventChannel Create(bool singleReader = false, bool singleWriter = false)
             {
-                var channel = Channel.CreateUnbounded<ProfilingEvent>(options);
+                // bounded channel is supposed to have lower allocation overhead than unbounded
+                var channel = Channel.CreateBounded<ProfilingEvent>(new BoundedChannelOptions(capacity: short.MaxValue)
+                {
+                    SingleReader = singleReader,
+                    SingleWriter = singleWriter,
+                    FullMode = BoundedChannelFullMode.DropWrite, // optimize caller to not block
+                });
 
                 return new ProfilingEventChannel { _channel = channel };
             }
@@ -79,7 +86,7 @@ internal static ProfilingEventChannel Create(UnboundedChannelOptions options)
 
         private class ThreadEventCollection
         {
-            private ProfilingEventChannel channel = ProfilingEventChannel.Create(new UnboundedChannelOptions { SingleReader = true, SingleWriter = true });
+            private ProfilingEventChannel channel = ProfilingEventChannel.Create(singleReader: true, singleWriter: true);
 
             internal ThreadEventCollection()
             {
@@ -110,32 +117,39 @@ internal IAsyncEnumerable<ProfilingEvent> ReadEvents()
         private static bool enableAll;
         private static int profileId;
         private static ThreadLocal<ThreadEventCollection> events = new(() => new ThreadEventCollection(), true);
-        private static ProfilingEventChannel collectorChannel = ProfilingEventChannel.Create(new UnboundedChannelOptions { SingleReader = true });
-        private static SemaphoreSlim subscriberChannelLock = new SemaphoreSlim(1, 1);
-        private static List<Channel<ProfilingEvent>> subscriberChannels = new();
+        private static ProfilingEventChannel collectorChannel = ProfilingEventChannel.Create(singleReader: true);
+        private static ConcurrentDictionary<ChannelReader<ProfilingEvent>, Channel<ProfilingEvent>> subscriberChannels = new(); // key == value.Reader
+        private static long subscriberChannelsModified = 0;
         private static Task collectorTask = null;
 
-        //TODO: Use TicksPerMicrosecond once .NET7 is available
         /// <summary>
         /// The minimum duration of events that will be captured. Defaults to 1 µs.
         /// </summary>
-        public static TimeSpan MinimumProfileDuration { get; set; } = new TimeSpan(TimeSpan.TicksPerMillisecond / 1000);
+        public static TimeSpan MinimumProfileDuration { get; set; } = new TimeSpan(TimeSpan.TicksPerMicrosecond);
 
         static Profiler()
         {
+            // Collector tasks aggregates data from producers from multiple threads and forwards this data to subscribers
             collectorTask = Task.Run(async () =>
             {
+                List<Channel<ProfilingEvent>> subscriberChannelsLocal = new List<Channel<ProfilingEvent>>();
                 await foreach (var item in collectorChannel.Reader.ReadAllAsync())
                 {
-                    await subscriberChannelLock.WaitAsync();
-                    try
+                    // Update the local list of subscribers if it has been modified
+                    // This is to minimize the enumerations of the concurrent dictionary which allocates the enumerator
+                    if (subscriberChannelsModified > 0)
                     {
-                        foreach (var subscriber in subscriberChannels)
+                        while (Interlocked.Exchange(ref subscriberChannelsModified, 0) > 0)
                         {
-                            await subscriber.Writer.WriteAsync(item);
+                            subscriberChannelsLocal.Clear();
+                            subscriberChannelsLocal.AddRange(subscriberChannels.Values);
                         }
                     }
-                    finally { subscriberChannelLock.Release(); }
+
+                    foreach (var subscriber in subscriberChannelsLocal)
+                    {
+                        await subscriber.Writer.WriteAsync(item);
+                    }
                 }
             });
         }
@@ -146,13 +160,14 @@ static Profiler()
         /// <returns>The <see cref="System.Threading.Channels.ChannelReader{ProfilingEvent}"/> which will receive the events.</returns>
         public static ChannelReader<ProfilingEvent> Subscribe()
         {
-            var channel = Channel.CreateUnbounded<ProfilingEvent>(new UnboundedChannelOptions { SingleReader = true, SingleWriter = true });
-            subscriberChannelLock.Wait();
-            try
+            var channel = Channel.CreateBounded<ProfilingEvent>(new BoundedChannelOptions(short.MaxValue)
             {
-                subscriberChannels.Add(channel);
-            }
-            finally { subscriberChannelLock.Release(); }
+                SingleReader = true,
+                SingleWriter = true,
+                FullMode = BoundedChannelFullMode.DropNewest, // dropping newer events so that we don't mess with events continuity
+            });
+            subscriberChannels.TryAdd(channel.Reader, channel);
+            Interlocked.Increment(ref subscriberChannelsModified);
             return channel;
         }
 
@@ -162,17 +177,11 @@ public static ChannelReader<ProfilingEvent> Subscribe()
         /// <param name="eventReader">The reader previously returned by <see cref="Subscribe"/></param>
         public static void Unsubscribe(ChannelReader<ProfilingEvent> eventReader)
         {
-            subscriberChannelLock.Wait();
-            try
+            if (subscriberChannels.TryRemove(eventReader, out var channel))
             {
-                var channel = subscriberChannels.Find((c) => c.Reader == eventReader);
-                if (channel != null)
-                {
-                    subscriberChannels.Remove(channel);
-                    channel.Writer.Complete();
-                }
+                channel.Writer.Complete();
+                Interlocked.Increment(ref subscriberChannelsModified);
             }
-            finally { subscriberChannelLock.Release(); }
         }
 
         /// <summary>
@@ -346,7 +355,7 @@ private static void AddThread(ThreadEventCollection eventCollection)
         /// <param name="e">The event.</param>
         private static void SendEventToSubscribers(ProfilingEvent e)
         {
-            if (subscriberChannels.Count >= 1)
+            if (!subscriberChannels.IsEmpty)
                 collectorChannel.Writer.TryWrite(e);
         }
 
@@ -376,17 +385,24 @@ public static void AppendTime([NotNull] StringBuilder builder, long accumulatedT
 
         public static void AppendTime([NotNull] StringBuilder builder, TimeSpan accumulatedTimeSpan)
         {
+            Span<char> buffer = stackalloc char[7];
             if (accumulatedTimeSpan > new TimeSpan(0, 0, 1, 0))
             {
-                builder.AppendFormat("{0:000.000}m ", accumulatedTimeSpan.TotalMinutes);
+                accumulatedTimeSpan.TotalMinutes.TryFormat(buffer, out _, "000.000");
+                builder.Append(buffer);
+                builder.Append("m ");
             }
             else if (accumulatedTimeSpan > new TimeSpan(0, 0, 0, 0, 1000))
             {
-                builder.AppendFormat("{0:000.000}s ", accumulatedTimeSpan.TotalSeconds);
+                accumulatedTimeSpan.TotalSeconds.TryFormat(buffer, out _, "000.000");
+                builder.Append(buffer);
+                builder.Append("s ");
             }
             else
             {
-                builder.AppendFormat("{0:000.000}ms", accumulatedTimeSpan.TotalMilliseconds);
+                accumulatedTimeSpan.TotalMilliseconds.TryFormat(buffer, out _, "000.000");
+                builder.Append(buffer);
+                builder.Append("ms");
             }
         }
     }

sources/core/Stride.Core/Diagnostics/ProfilingCustomValue.cs

@@ -23,15 +23,6 @@ public struct ProfilingCustomValue
         [FieldOffset(8)]
         public Type ValueType;
 
-        public object ToObject()
-        {
-            if (ValueType == typeof(int)) return IntValue;
-            else if (ValueType == typeof(float)) return FloatValue;
-            else if (ValueType == typeof(long)) return LongValue;
-            else if (ValueType == typeof(double)) return DoubleValue;
-            else throw new InvalidOperationException($"{nameof(ValueType)} is not one of the expected types.");
-        }
-
         public static implicit operator ProfilingCustomValue(int value)
         {
             return new ProfilingCustomValue { IntValue = value, ValueType = typeof(int) };

sources/core/Stride.Core/Diagnostics/ProfilingEventMessage.cs

@@ -2,6 +2,7 @@
 // Distributed under the MIT license. See the LICENSE.md file in the project root for more information.
 
 using System.Text;
+using System.Threading;
 
 namespace Stride.Core.Diagnostics
 {
@@ -10,6 +11,14 @@ namespace Stride.Core.Diagnostics
     /// </summary>
     public struct ProfilingEventMessage
     {
+        // The ProfilingCustomValue holds a struct which would need to be boxed for string formatting.
+        // To avoid this, we use a custom formatter object which can allocate statically.
+        private static readonly ThreadLocal<ProfilingCustomValueFormatter> formatter0 = new(() => new ProfilingCustomValueFormatter());
+        private static readonly ThreadLocal<ProfilingCustomValueFormatter> formatter1 = new(() => new ProfilingCustomValueFormatter());
+        private static readonly ThreadLocal<ProfilingCustomValueFormatter> formatter2 = new(() => new ProfilingCustomValueFormatter());
+        private static readonly ThreadLocal<ProfilingCustomValueFormatter> formatter3 = new(() => new ProfilingCustomValueFormatter());
+        private static readonly ThreadLocal<object[]> formatterParams = new(() => [formatter0.Value, formatter1.Value, formatter2.Value, formatter3.Value]);
+
         /// <summary>
         /// The text supporting formatting of up to 4 numerical parameters.
         /// </summary>
@@ -44,12 +53,40 @@ public ProfilingEventMessage(
 
         public override string ToString()
         {
-            return string.Format(Text, Custom0?.ToObject(), Custom1?.ToObject(), Custom2?.ToObject(), Custom3?.ToObject());
+            PopulateFormatters();
+            return string.Format(Text, formatterParams.Value);
         }
 
         public void ToString(StringBuilder builder)
         {
-            builder.AppendFormat(Text, Custom0?.ToObject(), Custom1?.ToObject(), Custom2?.ToObject(), Custom3?.ToObject());
+            PopulateFormatters();
+            builder.AppendFormat(Text, formatterParams.Value);
+        }
+
+        private void PopulateFormatters()
+        {
+            if (Custom0.HasValue)
+                formatter0.Value.Value = Custom0.Value;
+            if (Custom1.HasValue)
+                formatter1.Value.Value = Custom1.Value;
+            if (Custom2.HasValue)
+                formatter2.Value.Value = Custom2.Value;
+            if (Custom3.HasValue)
+                formatter3.Value.Value = Custom3.Value;
+        }
+
+        private class ProfilingCustomValueFormatter
+        {
+            public ProfilingCustomValue Value { get; set; }
+
+            public override string ToString()
+            {
+                if (Value.ValueType == typeof(int)) return Value.IntValue.ToString();
+                else if (Value.ValueType == typeof(float)) return Value.FloatValue.ToString();
+                else if (Value.ValueType == typeof(long)) return Value.LongValue.ToString();
+                else if (Value.ValueType == typeof(double)) return Value.DoubleValue.ToString();
+                else return "<unknown>";
+            }
         }
     }
 }