From 2e6630050623763bc9810d71c107364338504e76 Mon Sep 17 00:00:00 2001 From: froce Date: Mon, 16 Oct 2023 16:03:50 +0200 Subject: [PATCH 01/11] perf(core): Performance fixes in GameProfilingSystem and ChromeTracingProfileWriter - Fix busy-wait in `GameProfilingSystem` and make surrounding code clearer. - Add manual flushing to the JsonWriter, so the internal buffer doesn't grow indefinitely and put it on the fast path by skipping validation. --- .../Diagnostics/ChromeTracingProfileWriter.cs | 16 +- .../Profiling/GameProfilingSystem.cs | 143 +++++++++--------- 2 files changed, 82 insertions(+), 77 deletions(-) diff --git a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs b/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs index a42e7c622d..121e5642a3 100644 --- a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs +++ b/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs @@ -18,14 +18,14 @@ public void Start(string outputPath, bool indentOutput = false) { 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"); @@ -46,7 +46,7 @@ public void Start(string outputPath, bool indentOutput = false) 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) @@ -72,10 +72,15 @@ public void Start(string outputPath, bool indentOutput = false) 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.WriteEndArray(); @@ -92,6 +97,7 @@ public void Stop() writerTask?.Wait(); } } + #nullable enable ChannelReader? eventReader; Task? writerTask; diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index 4be1ba0d0a..19ea491292 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -51,7 +51,7 @@ public class GameProfilingSystem : GameSystemBase private Color4 textColor = Color.LightGreen; private GameProfilingResults filteringMode; - private Task stringBuilderTask; + private Task asyncUpdateTask; private Size2 renderTargetSize; private ChannelReader profilerChannel; private PresentInterval? userPresentInterval; @@ -101,10 +101,6 @@ public GameProfilingSystem(IServiceRegistry registry) : base(registry) gcProfiler = new GcProfiling(); } - private readonly Stopwatch dumpTiming = Stopwatch.StartNew(); - - - private void UpdateProfilingStrings(bool containsMarks) { profilersStringBuilder.Clear(); @@ -191,92 +187,95 @@ private void UpdateProfilingStrings(bool containsMarks) } } + private async Task UpdateAsync() + { + while(Enabled) + { + //In Fps filtering mode wait until it is time to update the output. + await Task.Delay((int)RefreshTime).ConfigureAwait(false); + + using (Profiler.Begin(UpdateStringsKey)) + { + UpdateProfilingStrings(false); + } + + if (profilerChannel == null || profilerChannel.Completion.IsCompleted) + continue; + + //If we're subscribed to the Profiler (Cpu/Gpu mode) start receiving events. + //Control flow will only return here once the profilerChannel is closed. + await ReadEventsAsync(); + } + } + private async Task ReadEventsAsync() { var containsMarks = false; + Task delayTask = Task.Delay((int)RefreshTime); - //TODO: Untangle this a bit. Currently fps display (FilteringMode == GameProfilingResults.Fps) - // depends on the timer/update logic, but it does not actually need the profiling events. - - while (Enabled) + await foreach (var e in profilerChannel.ReadAllAsync()) { - if (dumpTiming.ElapsedMilliseconds > RefreshTime) + if (delayTask.IsCompleted) { using (Profiler.Begin(UpdateStringsKey)) { UpdateProfilingStrings(containsMarks); - dumpTiming.Restart(); + delayTask = Task.Delay((int)RefreshTime); containsMarks = false; } } - if (profilerChannel == null) + if (FilteringMode == GameProfilingResults.Fps) continue; - await foreach (var e in profilerChannel.ReadAllAsync()) - { - if (dumpTiming.ElapsedMilliseconds > RefreshTime) - { - using (Profiler.Begin(UpdateStringsKey)) - { - UpdateProfilingStrings(containsMarks); - dumpTiming.Restart(); - containsMarks = false; - } - } - - if (FilteringMode == GameProfilingResults.Fps) - continue; - - if (e.IsGPUEvent() && FilteringMode != GameProfilingResults.GpuEvents) - continue; - if (!e.IsGPUEvent() && FilteringMode != GameProfilingResults.CpuEvents) - continue; - - //gc profiling is a special case - if (e.Key == GcProfiling.GcMemoryKey) - { - gcMemoryStringBuilder.Clear(); - e.Message?.ToString(gcMemoryStringBuilder); - continue; - } + if (e.IsGPUEvent() && FilteringMode != GameProfilingResults.GpuEvents) + continue; + if (!e.IsGPUEvent() && FilteringMode != GameProfilingResults.CpuEvents) + continue; - if (e.Key == GcProfiling.GcCollectionCountKey) - { - gcCollectionsStringBuilder.Clear(); - e.Message?.ToString(gcCollectionsStringBuilder); - continue; - } + //gc profiling is a special case + if (e.Key == GcProfiling.GcMemoryKey) + { + gcMemoryStringBuilder.Clear(); + e.Message?.ToString(gcMemoryStringBuilder); + continue; + } - if (e.Key == GameProfilingKeys.GameDrawFPS && e.Type == ProfilingMessageType.End) - continue; + if (e.Key == GcProfiling.GcCollectionCountKey) + { + gcCollectionsStringBuilder.Clear(); + e.Message?.ToString(gcCollectionsStringBuilder); + continue; + } - ProfilingResult profilingResult; - if (!profilingResultsDictionary.TryGetValue(e.Key, out profilingResult)) - { - profilingResult.MinTime = TimeSpan.MaxValue; - } + if (e.Key == GameProfilingKeys.GameDrawFPS && e.Type == ProfilingMessageType.End) + continue; - if (e.Type == ProfilingMessageType.End) - { - ++profilingResult.Count; - profilingResult.AccumulatedTime += e.ElapsedTime; + ProfilingResult profilingResult; + if (!profilingResultsDictionary.TryGetValue(e.Key, out profilingResult)) + { + profilingResult.MinTime = TimeSpan.MaxValue; + } - if (e.ElapsedTime < profilingResult.MinTime) - profilingResult.MinTime = e.ElapsedTime; - if (e.ElapsedTime > profilingResult.MaxTime) - profilingResult.MaxTime = e.ElapsedTime; + if (e.Type == ProfilingMessageType.End) + { + ++profilingResult.Count; + profilingResult.AccumulatedTime += e.ElapsedTime; - profilingResult.Event = e; - } - else if (e.Type == ProfilingMessageType.Mark) - { - profilingResult.MarkCount++; - containsMarks = true; - } + if (e.ElapsedTime < profilingResult.MinTime) + profilingResult.MinTime = e.ElapsedTime; + if (e.ElapsedTime > profilingResult.MaxTime) + profilingResult.MaxTime = e.ElapsedTime; - profilingResultsDictionary[e.Key] = profilingResult; + profilingResult.Event = e; } + else if (e.Type == ProfilingMessageType.Mark) + { + profilingResult.MarkCount++; + containsMarks = true; + } + + profilingResultsDictionary[e.Key] = profilingResult; } } @@ -323,9 +322,9 @@ protected override void Destroy() Profiler.Unsubscribe(profilerChannel); - if (stringBuilderTask != null && !stringBuilderTask.IsCompleted) + if (asyncUpdateTask != null && !asyncUpdateTask.IsCompleted) { - stringBuilderTask.Wait(); + asyncUpdateTask.Wait(); } gcProfiler.Dispose(); @@ -439,9 +438,9 @@ public void EnableProfiling(bool excludeKeys = false, params ProfilingKey[] keys gcProfiler.Enable(); - if (stringBuilderTask == null || stringBuilderTask.IsCompleted) + if (asyncUpdateTask == null || asyncUpdateTask.IsCompleted) { - stringBuilderTask = Task.Run(ReadEventsAsync); + asyncUpdateTask = Task.Run(UpdateAsync); } } From 5e005a97ae14d42856109d3e59d0ef48c9003b19 Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Wed, 15 Nov 2023 23:08:06 +0000 Subject: [PATCH 02/11] Switch between tasks in GameProfilingSystem for performance improvement --- .../Diagnostics/ChromeTracingProfileWriter.cs | 20 ++++- .../Profiling/GameProfilingSystem.cs | 75 ++++++++++++------- 2 files changed, 64 insertions(+), 31 deletions(-) diff --git a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs b/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs index 121e5642a3..23f81385f3 100644 --- a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs +++ b/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs @@ -9,8 +9,17 @@ namespace Stride.Core.Diagnostics { + /// + /// The chrome tracing profile writer exports diagnotic events into the chrome tracing format. + /// You view the file using chrome://tracing in your browser. + /// public class ChromeTracingProfileWriter { + /// + /// Create a tracing file at and start writing events to it. + /// + /// Path where to create the tracing file. + /// Whether to indent output JSON. False by default for perfomance/size over readability. public void Start(string outputPath, bool indentOutput = false) { eventReader = Profiler.Subscribe(); @@ -18,7 +27,7 @@ public void Start(string outputPath, bool indentOutput = false) { var pid = Process.GetCurrentProcess().Id; - using FileStream fs = File.Create(outputPath, 1024*1024); + 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(); @@ -64,12 +73,12 @@ public void Start(string outputPath, bool indentOutput = false) writer.WriteString("ph", "X"); writer.WriteNumber("ts", startTimeInMicroseconds); writer.WriteNumber("dur", durationInMicroseconds); - writer.WriteNumber("tid", e.ThreadId>=0?e.ThreadId: int.MaxValue); + 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) + foreach (var (k, v) in e.Attributes) { writer.WriteString(k, v.ToString()); } @@ -77,7 +86,7 @@ public void Start(string outputPath, bool indentOutput = false) } writer.WriteEndObject(); - if(writer.BytesPending >= 1024 * 1024) + if (writer.BytesPending >= 1024 * 1024) { await writer.FlushAsync(); } @@ -89,6 +98,9 @@ public void Start(string outputPath, bool indentOutput = false) }); } + /// + /// Stop the profiling session and wait for the file to be flushed. + /// public void Stop() { if (eventReader != null) diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index 19ea491292..2ed4acf741 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -4,6 +4,7 @@ using System.Collections.Generic; using System.Diagnostics; using System.Text; +using System.Threading; using System.Threading.Channels; using System.Threading.Tasks; using Stride.Core; @@ -66,6 +67,8 @@ public class GameProfilingSystem : GameSystemBase private uint trianglesCount; private uint drawCallsCount; + private CancellationTokenSource backgroundUpdateCancellationSource; + /// /// The render target where the profiling results should be rendered into. If null, the is used. /// @@ -103,6 +106,8 @@ public GameProfilingSystem(IServiceRegistry registry) : base(registry) private void UpdateProfilingStrings(bool containsMarks) { + using var _ = Profiler.Begin(UpdateStringsKey); + profilersStringBuilder.Clear(); fpsStatStringBuilder.Clear(); gpuInfoStringBuilder.Clear(); @@ -187,44 +192,36 @@ private void UpdateProfilingStrings(bool containsMarks) } } - private async Task UpdateAsync() + private async Task UpdateFpsAsync(CancellationToken cancellationToken) { - while(Enabled) + while (!backgroundUpdateCancellationSource.IsCancellationRequested) { //In Fps filtering mode wait until it is time to update the output. - await Task.Delay((int)RefreshTime).ConfigureAwait(false); - - using (Profiler.Begin(UpdateStringsKey)) - { - UpdateProfilingStrings(false); - } - - if (profilerChannel == null || profilerChannel.Completion.IsCompleted) - continue; + await Task.Delay((int)RefreshTime, cancellationToken).ConfigureAwait(false); - //If we're subscribed to the Profiler (Cpu/Gpu mode) start receiving events. - //Control flow will only return here once the profilerChannel is closed. - await ReadEventsAsync(); + UpdateProfilingStrings(false); } } - private async Task ReadEventsAsync() + //If we're subscribed to the Profiler (Cpu/Gpu mode) start receiving events. + //Control flow will only return here once the profilerChannel is closed. + private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) { var containsMarks = false; - Task delayTask = Task.Delay((int)RefreshTime); + Task delayTask = Task.Delay((int)RefreshTime, cancellationToken); - await foreach (var e in profilerChannel.ReadAllAsync()) + await foreach (var e in profilerChannel.ReadAllAsync(cancellationToken)) { if (delayTask.IsCompleted) { - using (Profiler.Begin(UpdateStringsKey)) - { - UpdateProfilingStrings(containsMarks); - delayTask = Task.Delay((int)RefreshTime); - containsMarks = false; - } + UpdateProfilingStrings(containsMarks); + delayTask = Task.Delay((int)RefreshTime); + containsMarks = false; } + if (cancellationToken.IsCancellationRequested) + continue; // skip events until they run out + if (FilteringMode == GameProfilingResults.Fps) continue; @@ -279,6 +276,28 @@ private async Task ReadEventsAsync() } } + private void RunBackgroundUpdate(bool restart) + { + if (restart || asyncUpdateTask == null || asyncUpdateTask.IsCompleted) + { + if (backgroundUpdateCancellationSource != null) + { + backgroundUpdateCancellationSource.Cancel(); + backgroundUpdateCancellationSource.Dispose(); + } + backgroundUpdateCancellationSource = new CancellationTokenSource(); + + if (FilteringMode == GameProfilingResults.Fps) + { + asyncUpdateTask = Task.Run(() => UpdateFpsAsync(backgroundUpdateCancellationSource.Token)); + } + else + { + asyncUpdateTask = Task.Run(() => UpdateWithEventsAsync(backgroundUpdateCancellationSource.Token)); + } + } + } + private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, bool displayMarkCount) { elapsedFrames = Math.Max(elapsedFrames, 1); @@ -321,6 +340,8 @@ protected override void Destroy() Visible = false; Profiler.Unsubscribe(profilerChannel); + backgroundUpdateCancellationSource?.Cancel(); + backgroundUpdateCancellationSource?.Dispose(); if (asyncUpdateTask != null && !asyncUpdateTask.IsCompleted) { @@ -438,10 +459,7 @@ public void EnableProfiling(bool excludeKeys = false, params ProfilingKey[] keys gcProfiler.Enable(); - if (asyncUpdateTask == null || asyncUpdateTask.IsCompleted) - { - asyncUpdateTask = Task.Run(UpdateAsync); - } + RunBackgroundUpdate(restart: false); } /// @@ -463,6 +481,7 @@ public void DisableProfiling() gcProfiler.Disable(); FilteringMode = GameProfilingResults.Fps; + backgroundUpdateCancellationSource.Cancel(); } /// @@ -502,6 +521,8 @@ public GameProfilingResults FilteringMode Profiler.Unsubscribe(profilerChannel); filteringMode = value; + + RunBackgroundUpdate(restart: true); } } } From d11075b26124316cd2e13c49878400f74bd1577c Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 10:35:07 +0000 Subject: [PATCH 03/11] Try improve performance --- .../core/Stride.Core/Diagnostics/Profiler.cs | 57 +++--- .../Diagnostics/ProfilingCustomValue.cs | 9 - .../Diagnostics/ProfilingEventMessage.cs | 41 ++++- .../Profiling/GameProfilingSystem.cs | 163 ++++++++++-------- 4 files changed, 159 insertions(+), 111 deletions(-) diff --git a/sources/core/Stride.Core/Diagnostics/Profiler.cs b/sources/core/Stride.Core/Diagnostics/Profiler.cs index a81a8918c0..afabf70863 100644 --- a/sources/core/Stride.Core/Diagnostics/Profiler.cs +++ b/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,14 @@ 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(options); + var channel = Channel.CreateBounded(new BoundedChannelOptions(capacity: 16_384) + { + SingleReader = singleReader, + SingleWriter = singleWriter, + FullMode = BoundedChannelFullMode.DropOldest, + }); return new ProfilingEventChannel { _channel = channel }; } @@ -79,7 +85,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,9 +116,8 @@ internal IAsyncEnumerable ReadEvents() private static bool enableAll; private static int profileId; private static ThreadLocal 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> subscriberChannels = new(); + private static ProfilingEventChannel collectorChannel = ProfilingEventChannel.Create(singleReader: true); + private static ConcurrentDictionary, Channel> subscriberChannels = new(); // key == value.Reader private static Task collectorTask = null; //TODO: Use TicksPerMicrosecond once .NET7 is available @@ -127,15 +132,10 @@ static Profiler() { await foreach (var item in collectorChannel.Reader.ReadAllAsync()) { - await subscriberChannelLock.WaitAsync(); - try + foreach (var subscriber in subscriberChannels) { - foreach (var subscriber in subscriberChannels) - { - await subscriber.Writer.WriteAsync(item); - } + await subscriber.Value.Writer.WriteAsync(item); } - finally { subscriberChannelLock.Release(); } } }); } @@ -147,12 +147,7 @@ static Profiler() public static ChannelReader Subscribe() { var channel = Channel.CreateUnbounded(new UnboundedChannelOptions { SingleReader = true, SingleWriter = true }); - subscriberChannelLock.Wait(); - try - { - subscriberChannels.Add(channel); - } - finally { subscriberChannelLock.Release(); } + subscriberChannels.TryAdd(channel.Reader, channel); return channel; } @@ -162,17 +157,10 @@ public static ChannelReader Subscribe() /// The reader previously returned by public static void Unsubscribe(ChannelReader 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(); } - finally { subscriberChannelLock.Release(); } } /// @@ -376,17 +364,24 @@ public static void AppendTime([NotNull] StringBuilder builder, long accumulatedT public static void AppendTime([NotNull] StringBuilder builder, TimeSpan accumulatedTimeSpan) { + Span 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 "); } } } diff --git a/sources/core/Stride.Core/Diagnostics/ProfilingCustomValue.cs b/sources/core/Stride.Core/Diagnostics/ProfilingCustomValue.cs index 41e95bc898..0caf25167e 100644 --- a/sources/core/Stride.Core/Diagnostics/ProfilingCustomValue.cs +++ b/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) }; diff --git a/sources/core/Stride.Core/Diagnostics/ProfilingEventMessage.cs b/sources/core/Stride.Core/Diagnostics/ProfilingEventMessage.cs index bec2cba11e..f5753648bb 100644 --- a/sources/core/Stride.Core/Diagnostics/ProfilingEventMessage.cs +++ b/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 /// 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 formatter0 = new(() => new ProfilingCustomValueFormatter()); + private static readonly ThreadLocal formatter1 = new(() => new ProfilingCustomValueFormatter()); + private static readonly ThreadLocal formatter2 = new(() => new ProfilingCustomValueFormatter()); + private static readonly ThreadLocal formatter3 = new(() => new ProfilingCustomValueFormatter()); + private static readonly ThreadLocal formatterParams = new(() => [formatter0.Value, formatter1.Value, formatter2.Value, formatter3.Value]); + /// /// The text supporting formatting of up to 4 numerical parameters. /// @@ -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 ""; + } } } } diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index 2ed4acf741..9b16f47bd3 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -27,13 +27,13 @@ public class GameProfilingSystem : GameSystemBase private readonly GcProfiling gcProfiler; - private readonly StringBuilder gcMemoryStringBuilder = new StringBuilder(); + private readonly StringBuilder gcMemoryStringBuilder = new StringBuilder(64); private string gcMemoryString = string.Empty; - private readonly StringBuilder gcCollectionsStringBuilder = new StringBuilder(); + private readonly StringBuilder gcCollectionsStringBuilder = new StringBuilder(64); private string gcCollectionsString = string.Empty; - private readonly StringBuilder fpsStatStringBuilder = new StringBuilder(); + private readonly StringBuilder fpsStatStringBuilder = new StringBuilder(64); private string fpsStatString = string.Empty; private readonly StringBuilder gpuGeneralInfoStringBuilder = new StringBuilder(); @@ -81,7 +81,8 @@ private struct ProfilingResult : IComparer public TimeSpan MaxTime; public int Count; public int MarkCount; - public ProfilingEvent? Event; + public ProfilingKey EventKey; + public ProfilingEventMessage? EventMessage; public int Compare(ProfilingResult x, ProfilingResult y) { @@ -90,8 +91,8 @@ public int Compare(ProfilingResult x, ProfilingResult y) } } - private readonly List profilingResults = new List(); - private readonly Dictionary profilingResultsDictionary = new Dictionary(); + private readonly List profilingResults = new List(256); + private readonly Dictionary profilingResultsDictionary = new Dictionary(256); /// /// Initializes a new instance of the class. @@ -104,49 +105,28 @@ public GameProfilingSystem(IServiceRegistry registry) : base(registry) gcProfiler = new GcProfiling(); } + private void UpdateInternalState(bool containsMarks) + { + CopyEventsForStringUpdateAndClear(); + + //Advance any profiler that needs it + gcProfiler.Tick(); + + // update strings on another thread so that we don't block the event loop in UpdateWithEventsAsync + _ = Task.Run(() => UpdateProfilingStrings(containsMarks)); + } + private void UpdateProfilingStrings(bool containsMarks) { using var _ = Profiler.Begin(UpdateStringsKey); profilersStringBuilder.Clear(); - fpsStatStringBuilder.Clear(); - gpuInfoStringBuilder.Clear(); - gpuGeneralInfoStringBuilder.Clear(); - - //Advance any profiler that needs it - gcProfiler.Tick(); // calculate elaspsed frames var newDraw = Game.DrawTime.FrameCount; var elapsedFrames = newDraw - lastFrame; lastFrame = newDraw; - profilersStringBuilder.Clear(); - profilingResults.Clear(); - - foreach (var profilingResult in profilingResultsDictionary) - { - if (!profilingResult.Value.Event.HasValue) continue; - profilingResults.Add(profilingResult.Value); - } - profilingResultsDictionary.Clear(); - - if (SortingMode == GameProfilingSorting.ByTime) - { - profilingResults.Sort((x, y) => x.Compare(x, y)); - } - else if(SortingMode == GameProfilingSorting.ByAverageTime) - { - profilingResults.Sort((x, y) => -TimeSpan.Compare(x.AccumulatedTime / x.Count, y.AccumulatedTime / y.Count)); - } - else - { - // Can't be null because we skip those events without values - // ReSharper disable PossibleInvalidOperationException - profilingResults.Sort((x1, x2) => string.Compare(x1.Event.Value.Key.Name, x2.Event.Value.Key.Name, StringComparison.Ordinal)); - // ReSharper restore PossibleInvalidOperationException - } - var availableDisplayHeight = viewportHeight - 2 * TextRowHeight - 3 * TopRowHeight; var elementsPerPage = (int)Math.Floor(availableDisplayHeight / TextRowHeight); numberOfPages = (uint)Math.Ceiling(profilingResults.Count / (float)elementsPerPage); @@ -164,31 +144,59 @@ private void UpdateProfilingStrings(bool containsMarks) { AppendEvent(profilingResults[((int)CurrentResultPage - 1) * elementsPerPage + i], elapsedFrames, containsMarks); } - profilingResults.Clear(); if (numberOfPages > 1) profilersStringBuilder.AppendFormat("PAGE {0} OF {1}", CurrentResultPage, numberOfPages); const float mb = 1 << 20; - gpuInfoStringBuilder.Clear(); - gpuInfoStringBuilder.AppendFormat("Drawn triangles: {0:0.0}k, Draw calls: {1}, Buffer memory: {2:0.00}[MB], Texture memory: {3:0.00}[MB]", trianglesCount / 1000f, drawCallsCount, GraphicsDevice.BuffersMemory / mb, GraphicsDevice.TextureMemory / mb); + var gpuInfoStringNew = $"Drawn triangles: {trianglesCount / 1000f:0.0}k, Draw calls: {drawCallsCount}, Buffer memory: {GraphicsDevice.BuffersMemory / mb:0.00}[MB], Texture memory: {GraphicsDevice.TextureMemory / mb:0.00}[MB]"; - gpuGeneralInfoStringBuilder.Clear(); //Note: renderTargetSize gets set in Draw(), without synchronization, so might be temporarily incorrect. - gpuGeneralInfoStringBuilder.AppendFormat("Device: {0}, Platform: {1}, Profile: {2}, Resolution: {3}", GraphicsDevice.Adapter.Description, GraphicsDevice.Platform, GraphicsDevice.ShaderProfile, renderTargetSize); + var gpuGeneralInfoStrinNew = $"Device: {GraphicsDevice.Adapter.Description}, Platform: {GraphicsDevice.Platform}, Profile: {GraphicsDevice.ShaderProfile}, Resolution: {renderTargetSize}"; + + var fpsStatStringBuilderNew = $"Displaying: {FilteringMode}, Frame: {Game.DrawTime.FrameCount}, Update: {Game.UpdateTime.TimePerFrame.TotalMilliseconds:0.00}ms, Draw: {Game.DrawTime.TimePerFrame.TotalMilliseconds:0.00}ms, FPS: {Game.DrawTime.FramePerSecond:0.00}"; - fpsStatStringBuilder.Clear(); - fpsStatStringBuilder.AppendFormat("Displaying: {0}, Frame: {1}, Update: {2:0.00}ms, Draw: {3:0.00}ms, FPS: {4:0.00}", FilteringMode, Game.DrawTime.FrameCount, Game.UpdateTime.TimePerFrame.TotalMilliseconds, Game.DrawTime.TimePerFrame.TotalMilliseconds, Game.DrawTime.FramePerSecond); + var gcCollectionsStringNew = gcCollectionsStringBuilder.ToString(); + var gcMemoryStringNew = gcMemoryStringBuilder.ToString(); + var profilersStringNew = profilersStringBuilder.ToString(); lock (stringLock) { - gcCollectionsString = gcCollectionsStringBuilder.ToString(); - gcMemoryString = gcMemoryStringBuilder.ToString(); - profilersString = profilersStringBuilder.ToString(); - fpsStatString = fpsStatStringBuilder.ToString(); - gpuInfoString = gpuInfoStringBuilder.ToString(); - gpuGeneralInfoString = gpuGeneralInfoStringBuilder.ToString(); + gcCollectionsString = gcCollectionsStringNew; + gcMemoryString = gcMemoryStringNew; + profilersString = profilersStringNew; + fpsStatString = fpsStatStringBuilderNew; + gpuInfoString = gpuInfoStringNew; + gpuGeneralInfoString = gpuGeneralInfoStrinNew; + } + } + + private void CopyEventsForStringUpdateAndClear() + { + profilingResults.Clear(); + + foreach (var profilingResult in profilingResultsDictionary) + { + if (profilingResult.Value.EventKey == null) continue; + profilingResults.Add(profilingResult.Value); + } + profilingResultsDictionary.Clear(); + + if (SortingMode == GameProfilingSorting.ByTime) + { + profilingResults.Sort((x, y) => x.Compare(x, y)); + } + else if (SortingMode == GameProfilingSorting.ByAverageTime) + { + profilingResults.Sort((x, y) => -TimeSpan.Compare(x.AccumulatedTime / x.Count, y.AccumulatedTime / y.Count)); + } + else + { + // Can't be null because we skip those events without values + // ReSharper disable PossibleInvalidOperationException + profilingResults.Sort((x1, x2) => string.Compare(x1.EventKey.Name, x2.EventKey.Name, StringComparison.Ordinal)); + // ReSharper restore PossibleInvalidOperationException } } @@ -199,7 +207,7 @@ private async Task UpdateFpsAsync(CancellationToken cancellationToken) //In Fps filtering mode wait until it is time to update the output. await Task.Delay((int)RefreshTime, cancellationToken).ConfigureAwait(false); - UpdateProfilingStrings(false); + UpdateInternalState(false); } } @@ -214,7 +222,7 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) { if (delayTask.IsCompleted) { - UpdateProfilingStrings(containsMarks); + UpdateInternalState(containsMarks); delayTask = Task.Delay((int)RefreshTime); containsMarks = false; } @@ -233,15 +241,21 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) //gc profiling is a special case if (e.Key == GcProfiling.GcMemoryKey) { - gcMemoryStringBuilder.Clear(); - e.Message?.ToString(gcMemoryStringBuilder); + lock (stringLock) // lock because string update can happen in parallel + { + gcMemoryStringBuilder.Clear(); + e.Message?.ToString(gcMemoryStringBuilder); + } continue; } if (e.Key == GcProfiling.GcCollectionCountKey) { - gcCollectionsStringBuilder.Clear(); - e.Message?.ToString(gcCollectionsStringBuilder); + lock (stringLock) // lock because string update can happen in parallel + { + gcCollectionsStringBuilder.Clear(); + e.Message?.ToString(gcCollectionsStringBuilder); + } continue; } @@ -264,7 +278,8 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) if (e.ElapsedTime > profilingResult.MaxTime) profilingResult.MaxTime = e.ElapsedTime; - profilingResult.Event = e; + profilingResult.EventKey = e.Key; + profilingResult.EventMessage = e.Message; } else if (e.Type == ProfilingMessageType.Mark) { @@ -300,9 +315,10 @@ private void RunBackgroundUpdate(bool restart) private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, bool displayMarkCount) { - elapsedFrames = Math.Max(elapsedFrames, 1); + Span formatBuffer = stackalloc char[8]; + int formatBufferUse = 0; - var profilingEvent = profilingResult.Event.Value; + elapsedFrames = Math.Max(elapsedFrames, 1); Profiler.AppendTime(profilersStringBuilder, profilingResult.AccumulatedTime / elapsedFrames); profilersStringBuilder.Append(" | "); @@ -312,22 +328,25 @@ private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, boo profilersStringBuilder.Append(" | "); Profiler.AppendTime(profilersStringBuilder, profilingResult.MaxTime); profilersStringBuilder.Append(" | "); - profilersStringBuilder.AppendFormat("{0,6:#00.00}", profilingResult.Count / (double)elapsedFrames); + + var callsPerFrame = profilingResult.Count / (double)elapsedFrames; + callsPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0,6:#00.00}"); + profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); profilersStringBuilder.Append(" | "); if (displayMarkCount) { - profilersStringBuilder.AppendFormat("{0:00.00}", profilingResult.MarkCount / (double)elapsedFrames); + var marksPerFrame = profilingResult.MarkCount / (double)elapsedFrames; + marksPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0:00.00}"); + profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); profilersStringBuilder.Append(" | "); } - profilersStringBuilder.Append(profilingEvent.Key); - // ReSharper disable once ReplaceWithStringIsNullOrEmpty - // This was creating memory allocation (GetEnumerable()) - if (profilingEvent.Message != null) + profilersStringBuilder.Append(profilingResult.EventKey); + if (profilingResult.EventMessage.HasValue) { profilersStringBuilder.Append(" / "); - profilingEvent.Message?.ToString(profilersStringBuilder); + profilingResult.EventMessage.Value.ToString(profilersStringBuilder); } profilersStringBuilder.Append("\n"); @@ -339,13 +358,19 @@ protected override void Destroy() Enabled = false; Visible = false; - Profiler.Unsubscribe(profilerChannel); + if (profilerChannel != null) + Profiler.Unsubscribe(profilerChannel); + backgroundUpdateCancellationSource?.Cancel(); backgroundUpdateCancellationSource?.Dispose(); if (asyncUpdateTask != null && !asyncUpdateTask.IsCompleted) { - asyncUpdateTask.Wait(); + try + { + asyncUpdateTask.Wait(); + } + catch { } // likely throws cancellation exception } gcProfiler.Dispose(); From 874560ca7998686103effd2bedb9eb6914167699 Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 13:24:17 +0000 Subject: [PATCH 04/11] Measurement and further investigation --- sources/core/Stride.Core/Diagnostics/Profiler.cs | 3 ++- .../Profiling/GameProfilingSystem.cs | 15 +++++++++------ 2 files changed, 11 insertions(+), 7 deletions(-) diff --git a/sources/core/Stride.Core/Diagnostics/Profiler.cs b/sources/core/Stride.Core/Diagnostics/Profiler.cs index afabf70863..f346f0397e 100644 --- a/sources/core/Stride.Core/Diagnostics/Profiler.cs +++ b/sources/core/Stride.Core/Diagnostics/Profiler.cs @@ -67,7 +67,8 @@ internal class ProfilingEventChannel { internal static ProfilingEventChannel Create(bool singleReader = false, bool singleWriter = false) { - var channel = Channel.CreateBounded(new BoundedChannelOptions(capacity: 16_384) + // bounded channel is supposed to have lower allocation overhead than unbounded + var channel = Channel.CreateBounded(new BoundedChannelOptions(capacity: short.MaxValue) { SingleReader = singleReader, SingleWriter = singleWriter, diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index 9b16f47bd3..fcfc90ac69 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -20,6 +20,7 @@ namespace Stride.Profiling public class GameProfilingSystem : GameSystemBase { private static readonly ProfilingKey UpdateStringsKey = new ProfilingKey($"{nameof(GameProfilingSystem)}.UpdateStrings"); + private static readonly ProfilingKey DrawKey = new ProfilingKey($"{nameof(GameProfilingSystem)}.Draw"); private readonly Point textDrawStartOffset = new Point(5, 10); private const int TextRowHeight = 16; @@ -27,22 +28,22 @@ public class GameProfilingSystem : GameSystemBase private readonly GcProfiling gcProfiler; - private readonly StringBuilder gcMemoryStringBuilder = new StringBuilder(64); + private readonly StringBuilder gcMemoryStringBuilder = new StringBuilder(128); private string gcMemoryString = string.Empty; - private readonly StringBuilder gcCollectionsStringBuilder = new StringBuilder(64); + private readonly StringBuilder gcCollectionsStringBuilder = new StringBuilder(128); private string gcCollectionsString = string.Empty; - private readonly StringBuilder fpsStatStringBuilder = new StringBuilder(64); + private readonly StringBuilder fpsStatStringBuilder = new StringBuilder(128); private string fpsStatString = string.Empty; - private readonly StringBuilder gpuGeneralInfoStringBuilder = new StringBuilder(); + private readonly StringBuilder gpuGeneralInfoStringBuilder = new StringBuilder(128); private string gpuGeneralInfoString = string.Empty; - private readonly StringBuilder gpuInfoStringBuilder = new StringBuilder(); + private readonly StringBuilder gpuInfoStringBuilder = new StringBuilder(128); private string gpuInfoString = string.Empty; - private readonly StringBuilder profilersStringBuilder = new StringBuilder(); + private readonly StringBuilder profilersStringBuilder = new StringBuilder(4096); private string profilersString = string.Empty; private FastTextRenderer fastTextRenderer; @@ -379,6 +380,8 @@ protected override void Destroy() /// public override void Draw(GameTime gameTime) { + using var _ = Profiler.Begin(DrawKey); + // Where to render the result? var renderTarget = RenderTarget ?? Game.GraphicsDevice.Presenter.BackBuffer; From 9dc95d9d67bacf4dbe08ce1bb060284ec5b0c063 Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 14:14:30 +0000 Subject: [PATCH 05/11] Refactor GameProfilingSystem --- .../Profiling/GameProfilingSystem.cs | 422 +++++++++--------- 1 file changed, 217 insertions(+), 205 deletions(-) diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index fcfc90ac69..83c08bb34b 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -2,7 +2,6 @@ // Distributed under the MIT license. See the LICENSE.md file in the project root for more information. using System; using System.Collections.Generic; -using System.Diagnostics; using System.Text; using System.Threading; using System.Threading.Channels; @@ -28,23 +27,7 @@ public class GameProfilingSystem : GameSystemBase private readonly GcProfiling gcProfiler; - private readonly StringBuilder gcMemoryStringBuilder = new StringBuilder(128); - private string gcMemoryString = string.Empty; - - private readonly StringBuilder gcCollectionsStringBuilder = new StringBuilder(128); - private string gcCollectionsString = string.Empty; - - private readonly StringBuilder fpsStatStringBuilder = new StringBuilder(128); - private string fpsStatString = string.Empty; - - private readonly StringBuilder gpuGeneralInfoStringBuilder = new StringBuilder(128); - private string gpuGeneralInfoString = string.Empty; - - private readonly StringBuilder gpuInfoStringBuilder = new StringBuilder(128); - private string gpuInfoString = string.Empty; - - private readonly StringBuilder profilersStringBuilder = new StringBuilder(4096); - private string profilersString = string.Empty; + private readonly GameProfilingSystemStrings gameProfilingSystemStrings; private FastTextRenderer fastTextRenderer; @@ -52,15 +35,12 @@ public class GameProfilingSystem : GameSystemBase private Color4 textColor = Color.LightGreen; - private GameProfilingResults filteringMode; private Task asyncUpdateTask; private Size2 renderTargetSize; private ChannelReader profilerChannel; private PresentInterval? userPresentInterval; private bool userMinimizedState = true; - private int lastFrame = -1; - private float viewportHeight = 1000; private uint numberOfPages; @@ -68,6 +48,8 @@ public class GameProfilingSystem : GameSystemBase private uint trianglesCount; private uint drawCallsCount; + private readonly Dictionary profilingResults = new Dictionary(256); + private CancellationTokenSource backgroundUpdateCancellationSource; /// @@ -75,26 +57,6 @@ public class GameProfilingSystem : GameSystemBase /// public Texture RenderTarget { get; set; } - private struct ProfilingResult : IComparer - { - public TimeSpan AccumulatedTime; - public TimeSpan MinTime; - public TimeSpan MaxTime; - public int Count; - public int MarkCount; - public ProfilingKey EventKey; - public ProfilingEventMessage? EventMessage; - - public int Compare(ProfilingResult x, ProfilingResult y) - { - //Flip sign so we get descending order. - return -TimeSpan.Compare(x.AccumulatedTime, y.AccumulatedTime); - } - } - - private readonly List profilingResults = new List(256); - private readonly Dictionary profilingResultsDictionary = new Dictionary(256); - /// /// Initializes a new instance of the class. /// @@ -104,101 +66,19 @@ public GameProfilingSystem(IServiceRegistry registry) : base(registry) DrawOrder = 0xfffffe; gcProfiler = new GcProfiling(); + gameProfilingSystemStrings = new GameProfilingSystemStrings(Game, GraphicsDevice); } private void UpdateInternalState(bool containsMarks) { - CopyEventsForStringUpdateAndClear(); + gameProfilingSystemStrings.CopyEventsForStringUpdate(profilingResults); + profilingResults.Clear(); //Advance any profiler that needs it gcProfiler.Tick(); // update strings on another thread so that we don't block the event loop in UpdateWithEventsAsync - _ = Task.Run(() => UpdateProfilingStrings(containsMarks)); - } - - private void UpdateProfilingStrings(bool containsMarks) - { - using var _ = Profiler.Begin(UpdateStringsKey); - - profilersStringBuilder.Clear(); - - // calculate elaspsed frames - var newDraw = Game.DrawTime.FrameCount; - var elapsedFrames = newDraw - lastFrame; - lastFrame = newDraw; - - var availableDisplayHeight = viewportHeight - 2 * TextRowHeight - 3 * TopRowHeight; - var elementsPerPage = (int)Math.Floor(availableDisplayHeight / TextRowHeight); - numberOfPages = (uint)Math.Ceiling(profilingResults.Count / (float)elementsPerPage); - CurrentResultPage = Math.Min(CurrentResultPage, numberOfPages); - - char sortByTimeIndicator = SortingMode == GameProfilingSorting.ByTime ? 'v' : ' '; - char sortByAvgTimeIndicator = SortingMode == GameProfilingSorting.ByAverageTime ? 'v' : ' '; - - profilersStringBuilder.AppendFormat("TOTAL {0}| AVG/CALL {1}| MIN/CALL | MAX/CALL | CALLS | ", sortByTimeIndicator, sortByAvgTimeIndicator); - if (containsMarks) - profilersStringBuilder.AppendFormat("MARKS | "); - profilersStringBuilder.AppendFormat("PROFILING KEY / EXTRA INFO\n"); - - for (int i = 0; i < Math.Min(profilingResults.Count - (CurrentResultPage - 1) * elementsPerPage, elementsPerPage); i++) - { - AppendEvent(profilingResults[((int)CurrentResultPage - 1) * elementsPerPage + i], elapsedFrames, containsMarks); - } - - if (numberOfPages > 1) - profilersStringBuilder.AppendFormat("PAGE {0} OF {1}", CurrentResultPage, numberOfPages); - - const float mb = 1 << 20; - - var gpuInfoStringNew = $"Drawn triangles: {trianglesCount / 1000f:0.0}k, Draw calls: {drawCallsCount}, Buffer memory: {GraphicsDevice.BuffersMemory / mb:0.00}[MB], Texture memory: {GraphicsDevice.TextureMemory / mb:0.00}[MB]"; - - //Note: renderTargetSize gets set in Draw(), without synchronization, so might be temporarily incorrect. - var gpuGeneralInfoStrinNew = $"Device: {GraphicsDevice.Adapter.Description}, Platform: {GraphicsDevice.Platform}, Profile: {GraphicsDevice.ShaderProfile}, Resolution: {renderTargetSize}"; - - var fpsStatStringBuilderNew = $"Displaying: {FilteringMode}, Frame: {Game.DrawTime.FrameCount}, Update: {Game.UpdateTime.TimePerFrame.TotalMilliseconds:0.00}ms, Draw: {Game.DrawTime.TimePerFrame.TotalMilliseconds:0.00}ms, FPS: {Game.DrawTime.FramePerSecond:0.00}"; - - var gcCollectionsStringNew = gcCollectionsStringBuilder.ToString(); - var gcMemoryStringNew = gcMemoryStringBuilder.ToString(); - var profilersStringNew = profilersStringBuilder.ToString(); - - lock (stringLock) - { - gcCollectionsString = gcCollectionsStringNew; - gcMemoryString = gcMemoryStringNew; - profilersString = profilersStringNew; - fpsStatString = fpsStatStringBuilderNew; - gpuInfoString = gpuInfoStringNew; - gpuGeneralInfoString = gpuGeneralInfoStrinNew; - } - } - - private void CopyEventsForStringUpdateAndClear() - { - profilingResults.Clear(); - - foreach (var profilingResult in profilingResultsDictionary) - { - if (profilingResult.Value.EventKey == null) continue; - profilingResults.Add(profilingResult.Value); - } - profilingResultsDictionary.Clear(); - - if (SortingMode == GameProfilingSorting.ByTime) - { - profilingResults.Sort((x, y) => x.Compare(x, y)); - } - else if (SortingMode == GameProfilingSorting.ByAverageTime) - { - profilingResults.Sort((x, y) => -TimeSpan.Compare(x.AccumulatedTime / x.Count, y.AccumulatedTime / y.Count)); - } - else - { - // Can't be null because we skip those events without values - // ReSharper disable PossibleInvalidOperationException - profilingResults.Sort((x1, x2) => string.Compare(x1.EventKey.Name, x2.EventKey.Name, StringComparison.Ordinal)); - // ReSharper restore PossibleInvalidOperationException - } + _ = Task.Run(() => gameProfilingSystemStrings.UpdateProfilingStrings(containsMarks, viewportHeight, trianglesCount, drawCallsCount, renderTargetSize)); } private async Task UpdateFpsAsync(CancellationToken cancellationToken) @@ -242,21 +122,13 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) //gc profiling is a special case if (e.Key == GcProfiling.GcMemoryKey) { - lock (stringLock) // lock because string update can happen in parallel - { - gcMemoryStringBuilder.Clear(); - e.Message?.ToString(gcMemoryStringBuilder); - } + gameProfilingSystemStrings.GcMemoryMessage = e.Message; continue; } if (e.Key == GcProfiling.GcCollectionCountKey) { - lock (stringLock) // lock because string update can happen in parallel - { - gcCollectionsStringBuilder.Clear(); - e.Message?.ToString(gcCollectionsStringBuilder); - } + gameProfilingSystemStrings.GcCollectionMessage = e.Message; continue; } @@ -264,7 +136,7 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) continue; ProfilingResult profilingResult; - if (!profilingResultsDictionary.TryGetValue(e.Key, out profilingResult)) + if (!profilingResults.TryGetValue(e.Key, out profilingResult)) { profilingResult.MinTime = TimeSpan.MaxValue; } @@ -288,7 +160,7 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) containsMarks = true; } - profilingResultsDictionary[e.Key] = profilingResult; + profilingResults[e.Key] = profilingResult; } } @@ -312,45 +184,6 @@ private void RunBackgroundUpdate(bool restart) asyncUpdateTask = Task.Run(() => UpdateWithEventsAsync(backgroundUpdateCancellationSource.Token)); } } - } - - private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, bool displayMarkCount) - { - Span formatBuffer = stackalloc char[8]; - int formatBufferUse = 0; - - elapsedFrames = Math.Max(elapsedFrames, 1); - - Profiler.AppendTime(profilersStringBuilder, profilingResult.AccumulatedTime / elapsedFrames); - profilersStringBuilder.Append(" | "); - Profiler.AppendTime(profilersStringBuilder, profilingResult.AccumulatedTime / profilingResult.Count); - profilersStringBuilder.Append(" | "); - Profiler.AppendTime(profilersStringBuilder, profilingResult.MinTime); - profilersStringBuilder.Append(" | "); - Profiler.AppendTime(profilersStringBuilder, profilingResult.MaxTime); - profilersStringBuilder.Append(" | "); - - var callsPerFrame = profilingResult.Count / (double)elapsedFrames; - callsPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0,6:#00.00}"); - profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); - profilersStringBuilder.Append(" | "); - - if (displayMarkCount) - { - var marksPerFrame = profilingResult.MarkCount / (double)elapsedFrames; - marksPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0:00.00}"); - profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); - profilersStringBuilder.Append(" | "); - } - - profilersStringBuilder.Append(profilingResult.EventKey); - if (profilingResult.EventMessage.HasValue) - { - profilersStringBuilder.Append(" / "); - profilingResult.EventMessage.Value.ToString(profilersStringBuilder); - } - - profilersStringBuilder.Append("\n"); } /// @@ -411,31 +244,36 @@ public override void Draw(GameTime gameTime) renderDrawContext.CommandList.SetRenderTargetAndViewport(null, renderTarget); viewportHeight = renderDrawContext.CommandList.Viewport.Height; fastTextRenderer.Begin(renderDrawContext.GraphicsContext); - lock (stringLock) - { - var currentHeight = textDrawStartOffset.Y; - fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, fpsStatString, textDrawStartOffset.X, currentHeight); - currentHeight += TopRowHeight; - if (FilteringMode == GameProfilingResults.CpuEvents) - { - fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gcMemoryString, textDrawStartOffset.X, currentHeight); - currentHeight += TopRowHeight; - fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gcCollectionsString, textDrawStartOffset.X, currentHeight); - currentHeight += TopRowHeight; - } - else if (FilteringMode == GameProfilingResults.GpuEvents) - { - fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gpuGeneralInfoString, textDrawStartOffset.X, currentHeight); - currentHeight += TopRowHeight; - fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gpuInfoString, textDrawStartOffset.X, currentHeight); - currentHeight += TopRowHeight; - } + var fpsStatString = gameProfilingSystemStrings.FpsStatString; + var gcMemoryString = gameProfilingSystemStrings.GcMemoryString; + var gcCollectionsString = gameProfilingSystemStrings.GcCollectionsString; + var gpuGeneralInfoString = gameProfilingSystemStrings.GpuGeneralInfoString; + var gpuInfoString = gameProfilingSystemStrings.GpuInfoString; + var profilersString = gameProfilingSystemStrings.ProfilersString; - if (FilteringMode != GameProfilingResults.Fps) - fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, profilersString, textDrawStartOffset.X, currentHeight); + var currentHeight = textDrawStartOffset.Y; + fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, fpsStatString, textDrawStartOffset.X, currentHeight); + currentHeight += TopRowHeight; + + if (FilteringMode == GameProfilingResults.CpuEvents) + { + fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gcMemoryString, textDrawStartOffset.X, currentHeight); + currentHeight += TopRowHeight; + fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gcCollectionsString, textDrawStartOffset.X, currentHeight); + currentHeight += TopRowHeight; + } + else if (FilteringMode == GameProfilingResults.GpuEvents) + { + fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gpuGeneralInfoString, textDrawStartOffset.X, currentHeight); + currentHeight += TopRowHeight; + fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, gpuInfoString, textDrawStartOffset.X, currentHeight); + currentHeight += TopRowHeight; } + if (FilteringMode != GameProfilingResults.Fps) + fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, profilersString, textDrawStartOffset.X, currentHeight); + fastTextRenderer.End(renderDrawContext.GraphicsContext); } } @@ -529,26 +367,30 @@ public Color4 TextColor /// /// Sets or gets the way the printed information will be sorted. /// - public GameProfilingSorting SortingMode { get; set; } = GameProfilingSorting.ByTime; + public GameProfilingSorting SortingMode + { + get => gameProfilingSystemStrings.SortingMode; + set => gameProfilingSystemStrings.SortingMode = value; + } /// /// Sets or gets which data should be displayed on screen. /// public GameProfilingResults FilteringMode { - get => filteringMode; + get => gameProfilingSystemStrings.FilteringMode; set { // Only Cpu and Gpu modes need to subscribe to profiling events, so we // subscribe when switching away from Fps mode and unsubscribe when switching to it. - if (filteringMode != value) + if (gameProfilingSystemStrings.FilteringMode != value) { - if (filteringMode == GameProfilingResults.Fps) + if (gameProfilingSystemStrings.FilteringMode == GameProfilingResults.Fps) profilerChannel = Profiler.Subscribe(); else if (value == GameProfilingResults.Fps) Profiler.Unsubscribe(profilerChannel); - filteringMode = value; + gameProfilingSystemStrings.FilteringMode = value; RunBackgroundUpdate(restart: true); } @@ -563,6 +405,176 @@ public GameProfilingResults FilteringMode /// /// Sets or gets the profiling result page to display. /// - public uint CurrentResultPage { get; set; } = 1; + public uint CurrentResultPage + { + get => gameProfilingSystemStrings.CurrentResultPage; + set => gameProfilingSystemStrings.CurrentResultPage = value; + } + + private struct ProfilingResult : IComparer + { + public TimeSpan AccumulatedTime; + public TimeSpan MinTime; + public TimeSpan MaxTime; + public int Count; + public int MarkCount; + public ProfilingKey EventKey; + public ProfilingEventMessage? EventMessage; + + public int Compare(ProfilingResult x, ProfilingResult y) + { + //Flip sign so we get descending order. + return -TimeSpan.Compare(x.AccumulatedTime, y.AccumulatedTime); + } + } + + private class GameProfilingSystemStrings + { + private IGame Game { get; } + private GraphicsDevice GraphicsDevice { get; } + + private readonly StringBuilder profilersStringBuilder = new StringBuilder(4096); + + private int lastFrame = -1; + + private readonly List profilingResults = new List(256); + + public GameProfilingSystemStrings(IGame game, GraphicsDevice graphicsDevice) + { + Game = game; + GraphicsDevice = graphicsDevice; + } + + public uint CurrentResultPage { get; set; } = 1; + public GameProfilingSorting SortingMode { get; set; } = GameProfilingSorting.ByTime; + public GameProfilingResults FilteringMode { get; set; } = GameProfilingResults.Fps; + + public string GcMemoryString { get; set; } + public string GcCollectionsString { get; set; } + public string FpsStatString { get; set; } + public string GpuGeneralInfoString { get; set; } + public string GpuInfoString { get; set; } + public string ProfilersString { get; set; } + + public ProfilingEventMessage? GcMemoryMessage; + public ProfilingEventMessage? GcCollectionMessage; + + public void CopyEventsForStringUpdate(Dictionary profilingData) + { + profilingResults.Clear(); + + foreach (var profilingResult in profilingData) + { + if (profilingResult.Value.EventKey == null) continue; + profilingResults.Add(profilingResult.Value); + } + + if (SortingMode == GameProfilingSorting.ByTime) + { + profilingResults.Sort((x, y) => x.Compare(x, y)); + } + else if (SortingMode == GameProfilingSorting.ByAverageTime) + { + profilingResults.Sort((x, y) => -TimeSpan.Compare(x.AccumulatedTime / x.Count, y.AccumulatedTime / y.Count)); + } + else + { + // Can't be null because we skip those events without values + // ReSharper disable PossibleInvalidOperationException + profilingResults.Sort((x1, x2) => string.Compare(x1.EventKey.Name, x2.EventKey.Name, StringComparison.Ordinal)); + // ReSharper restore PossibleInvalidOperationException + } + } + + public void UpdateProfilingStrings(bool containsMarks, float viewportHeight, uint trianglesCount, uint drawCallsCount, Size2 renderTargetSize) + { + using var _ = Profiler.Begin(UpdateStringsKey); + + profilersStringBuilder.Clear(); + + // calculate elaspsed frames + var newDraw = Game.DrawTime.FrameCount; + var elapsedFrames = newDraw - lastFrame; + lastFrame = newDraw; + + GenerateEventTable(containsMarks, viewportHeight, elapsedFrames); + + const float mb = 1 << 20; + + GpuInfoString = $"Drawn triangles: {trianglesCount / 1000f:0.0}k, Draw calls: {drawCallsCount}, Buffer memory: {GraphicsDevice.BuffersMemory / mb:0.00}[MB], Texture memory: {GraphicsDevice.TextureMemory / mb:0.00}[MB]"; + + //Note: renderTargetSize gets set in Draw(), without synchronization, so might be temporarily incorrect. + GpuGeneralInfoString = $"Device: {GraphicsDevice.Adapter.Description}, Platform: {GraphicsDevice.Platform}, Profile: {GraphicsDevice.ShaderProfile}, Resolution: {renderTargetSize}"; + + FpsStatString = $"Displaying: {FilteringMode}, Frame: {Game.DrawTime.FrameCount}, Update: {Game.UpdateTime.TimePerFrame.TotalMilliseconds:0.00}ms, Draw: {Game.DrawTime.TimePerFrame.TotalMilliseconds:0.00}ms, FPS: {Game.DrawTime.FramePerSecond:0.00}"; + + GcCollectionsString = GcCollectionMessage?.ToString() ?? string.Empty; + GcMemoryString = GcMemoryMessage?.ToString() ?? string.Empty; + ProfilersString = profilersStringBuilder.ToString(); + } + + private void GenerateEventTable(bool containsMarks, float viewportHeight, int elapsedFrames) + { + var availableDisplayHeight = viewportHeight - 2 * TextRowHeight - 3 * TopRowHeight; + var elementsPerPage = (int)Math.Floor(availableDisplayHeight / TextRowHeight); + var numberOfPages = (uint)Math.Ceiling(profilingResults.Count / (float)elementsPerPage); + CurrentResultPage = Math.Min(CurrentResultPage, numberOfPages); + + char sortByTimeIndicator = SortingMode == GameProfilingSorting.ByTime ? 'v' : ' '; + char sortByAvgTimeIndicator = SortingMode == GameProfilingSorting.ByAverageTime ? 'v' : ' '; + + profilersStringBuilder.AppendFormat("TOTAL {0}| AVG/CALL {1}| MIN/CALL | MAX/CALL | CALLS | ", sortByTimeIndicator, sortByAvgTimeIndicator); + if (containsMarks) + profilersStringBuilder.AppendFormat("MARKS | "); + profilersStringBuilder.AppendFormat("PROFILING KEY / EXTRA INFO\n"); + + for (int i = 0; i < Math.Min(profilingResults.Count - (CurrentResultPage - 1) * elementsPerPage, elementsPerPage); i++) + { + AppendEvent(profilingResults[((int)CurrentResultPage - 1) * elementsPerPage + i], elapsedFrames, containsMarks); + } + + if (numberOfPages > 1) + profilersStringBuilder.AppendFormat("PAGE {0} OF {1}", CurrentResultPage, numberOfPages); + } + + private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, bool displayMarkCount) + { + Span formatBuffer = stackalloc char[8]; + int formatBufferUse = 0; + + elapsedFrames = Math.Max(elapsedFrames, 1); + + Profiler.AppendTime(profilersStringBuilder, profilingResult.AccumulatedTime / elapsedFrames); + profilersStringBuilder.Append(" | "); + Profiler.AppendTime(profilersStringBuilder, profilingResult.AccumulatedTime / profilingResult.Count); + profilersStringBuilder.Append(" | "); + Profiler.AppendTime(profilersStringBuilder, profilingResult.MinTime); + profilersStringBuilder.Append(" | "); + Profiler.AppendTime(profilersStringBuilder, profilingResult.MaxTime); + profilersStringBuilder.Append(" | "); + + var callsPerFrame = profilingResult.Count / (double)elapsedFrames; + callsPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0,6:#00.00}"); + profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); + profilersStringBuilder.Append(" | "); + + if (displayMarkCount) + { + var marksPerFrame = profilingResult.MarkCount / (double)elapsedFrames; + marksPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0:00.00}"); + profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); + profilersStringBuilder.Append(" | "); + } + + profilersStringBuilder.Append(profilingResult.EventKey); + if (profilingResult.EventMessage.HasValue) + { + profilersStringBuilder.Append(" / "); + profilingResult.EventMessage.Value.ToString(profilersStringBuilder); + } + + profilersStringBuilder.Append("\n"); + } + } } } From 742eceab97a9f68b2ff17c4bab1fe60d1d96d5bd Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 14:23:35 +0000 Subject: [PATCH 06/11] Add cancellation to chrome tracing writer --- .../Diagnostics/ChromeTracingProfileWriter.cs | 67 +++++++++++-------- .../core/Stride.Core/Diagnostics/Profiler.cs | 5 +- 2 files changed, 42 insertions(+), 30 deletions(-) diff --git a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs b/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs index 23f81385f3..33c61797c6 100644 --- a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs +++ b/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs @@ -6,6 +6,8 @@ using System.Text.Json; using System.Threading.Channels; using System.Threading.Tasks; +using System.Threading; +using System; namespace Stride.Core.Diagnostics { @@ -23,6 +25,7 @@ public class ChromeTracingProfileWriter public void Start(string outputPath, bool indentOutput = false) { eventReader = Profiler.Subscribe(); + cts = new CancellationTokenSource(); writerTask = Task.Run(async () => { var pid = Process.GetCurrentProcess().Id; @@ -54,43 +57,47 @@ public void Start(string outputPath, bool indentOutput = false) writer.WriteEndObject(); writer.WriteEndObject(); - await foreach (var e in eventReader.ReadAllAsync()) + try { - //gc scopes currently start at negative timestamps and should be filtered out, - //because they don't represent durations. - if (e.TimeStamp.Ticks < 0) - continue; + 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(); - } - writer.WriteEndObject(); - if (writer.BytesPending >= 1024 * 1024) - { - await writer.FlushAsync(); + if (writer.BytesPending >= 1024 * 1024) + { + await writer.FlushAsync(); + } } } + catch (OperationCanceledException) { } // cancellation was requested, let's finish writer.WriteEndArray(); writer.WriteEndObject(); @@ -106,6 +113,11 @@ public void Stop() if (eventReader != null) { Profiler.Unsubscribe(eventReader); + eventReader = null; + + cts?.Cancel(); + cts?.Dispose(); + writerTask?.Wait(); } } @@ -113,6 +125,7 @@ public void Stop() #nullable enable ChannelReader? eventReader; Task? writerTask; + CancellationTokenSource? cts; #nullable disable } diff --git a/sources/core/Stride.Core/Diagnostics/Profiler.cs b/sources/core/Stride.Core/Diagnostics/Profiler.cs index f346f0397e..7d04d0bc35 100644 --- a/sources/core/Stride.Core/Diagnostics/Profiler.cs +++ b/sources/core/Stride.Core/Diagnostics/Profiler.cs @@ -72,7 +72,7 @@ internal static ProfilingEventChannel Create(bool singleReader = false, bool sin { SingleReader = singleReader, SingleWriter = singleWriter, - FullMode = BoundedChannelFullMode.DropOldest, + FullMode = BoundedChannelFullMode.DropWrite, }); return new ProfilingEventChannel { _channel = channel }; @@ -121,11 +121,10 @@ internal IAsyncEnumerable ReadEvents() private static ConcurrentDictionary, Channel> subscriberChannels = new(); // key == value.Reader private static Task collectorTask = null; - //TODO: Use TicksPerMicrosecond once .NET7 is available /// /// The minimum duration of events that will be captured. Defaults to 1 µs. /// - public static TimeSpan MinimumProfileDuration { get; set; } = new TimeSpan(TimeSpan.TicksPerMillisecond / 1000); + public static TimeSpan MinimumProfileDuration { get; set; } = new TimeSpan(TimeSpan.TicksPerMicrosecond); static Profiler() { From 3ac1516b39673f0eff8c0f8d606ce95256a6f4f9 Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 14:36:30 +0000 Subject: [PATCH 07/11] Initialize empty strings --- .../Stride.Engine/Profiling/GameProfilingSystem.cs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index 83c08bb34b..feb3692337 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -449,12 +449,12 @@ public GameProfilingSystemStrings(IGame game, GraphicsDevice graphicsDevice) public GameProfilingSorting SortingMode { get; set; } = GameProfilingSorting.ByTime; public GameProfilingResults FilteringMode { get; set; } = GameProfilingResults.Fps; - public string GcMemoryString { get; set; } - public string GcCollectionsString { get; set; } - public string FpsStatString { get; set; } - public string GpuGeneralInfoString { get; set; } - public string GpuInfoString { get; set; } - public string ProfilersString { get; set; } + public string GcMemoryString { get; set; } = string.Empty; + public string GcCollectionsString { get; set; } = string.Empty; + public string FpsStatString { get; set; } = string.Empty; + public string GpuGeneralInfoString { get; set; } = string.Empty; + public string GpuInfoString { get; set; } = string.Empty; + public string ProfilersString { get; set; } = string.Empty; public ProfilingEventMessage? GcMemoryMessage; public ProfilingEventMessage? GcCollectionMessage; From 41d1deab3cee774cacdc716834f065444b696a42 Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 18:36:01 +0000 Subject: [PATCH 08/11] Optimize profiler for allocations --- .../core/Stride.Core/Diagnostics/Profiler.cs | 27 ++++++++++++++++--- 1 file changed, 24 insertions(+), 3 deletions(-) diff --git a/sources/core/Stride.Core/Diagnostics/Profiler.cs b/sources/core/Stride.Core/Diagnostics/Profiler.cs index 7d04d0bc35..98352dfa6f 100644 --- a/sources/core/Stride.Core/Diagnostics/Profiler.cs +++ b/sources/core/Stride.Core/Diagnostics/Profiler.cs @@ -119,6 +119,7 @@ internal IAsyncEnumerable ReadEvents() private static ThreadLocal events = new(() => new ThreadEventCollection(), true); private static ProfilingEventChannel collectorChannel = ProfilingEventChannel.Create(singleReader: true); private static ConcurrentDictionary, Channel> subscriberChannels = new(); // key == value.Reader + private static long subscriberChannelsModified = 0; private static Task collectorTask = null; /// @@ -128,13 +129,26 @@ internal IAsyncEnumerable ReadEvents() static Profiler() { + // Collector tasks aggregates data from producers from multiple threads and forwards this data to subscribers collectorTask = Task.Run(async () => { + List> subscriberChannelsLocal = new List>(); await foreach (var item in collectorChannel.Reader.ReadAllAsync()) { - foreach (var subscriber in subscriberChannels) + // 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) { - await subscriber.Value.Writer.WriteAsync(item); + while (Interlocked.Exchange(ref subscriberChannelsModified, 0) > 0) + { + subscriberChannelsLocal.Clear(); + subscriberChannelsLocal.AddRange(subscriberChannels.Values); + } + } + + foreach (var subscriber in subscriberChannelsLocal) + { + await subscriber.Writer.WriteAsync(item); } } }); @@ -146,8 +160,14 @@ static Profiler() /// The which will receive the events. public static ChannelReader Subscribe() { - var channel = Channel.CreateUnbounded(new UnboundedChannelOptions { SingleReader = true, SingleWriter = true }); + var channel = Channel.CreateBounded(new BoundedChannelOptions(short.MaxValue) + { + SingleReader = true, + SingleWriter = true, + FullMode = BoundedChannelFullMode.DropNewest + }); subscriberChannels.TryAdd(channel.Reader, channel); + Interlocked.Increment(ref subscriberChannelsModified); return channel; } @@ -160,6 +180,7 @@ public static void Unsubscribe(ChannelReader eventReader) if (subscriberChannels.TryRemove(eventReader, out var channel)) { channel.Writer.Complete(); + Interlocked.Increment(ref subscriberChannelsModified); } } From a8c880bdfc8385c32a27094b9ffc9e454ea80484 Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 18:36:44 +0000 Subject: [PATCH 09/11] Optimize UpdateWithEventsAsync for allocations --- .../Profiling/GameProfilingSystem.cs | 108 ++++++++++-------- 1 file changed, 59 insertions(+), 49 deletions(-) diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index feb3692337..196c73eb1e 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -99,68 +99,75 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) var containsMarks = false; Task delayTask = Task.Delay((int)RefreshTime, cancellationToken); - await foreach (var e in profilerChannel.ReadAllAsync(cancellationToken)) + while (await profilerChannel.WaitToReadAsync(cancellationToken)) { - if (delayTask.IsCompleted) + while (profilerChannel.TryRead(out var e)) { - UpdateInternalState(containsMarks); - delayTask = Task.Delay((int)RefreshTime); - containsMarks = false; - } + if (delayTask.IsCompleted) + { + UpdateInternalState(containsMarks); + delayTask = Task.Delay((int)RefreshTime); + containsMarks = false; + } - if (cancellationToken.IsCancellationRequested) - continue; // skip events until they run out + if (cancellationToken.IsCancellationRequested) + continue; // skip events until they run out - if (FilteringMode == GameProfilingResults.Fps) - continue; + if (FilteringMode == GameProfilingResults.Fps) + continue; - if (e.IsGPUEvent() && FilteringMode != GameProfilingResults.GpuEvents) - continue; - if (!e.IsGPUEvent() && FilteringMode != GameProfilingResults.CpuEvents) - continue; + if (e.IsGPUEvent() && FilteringMode != GameProfilingResults.GpuEvents) + continue; + if (!e.IsGPUEvent() && FilteringMode != GameProfilingResults.CpuEvents) + continue; - //gc profiling is a special case - if (e.Key == GcProfiling.GcMemoryKey) - { - gameProfilingSystemStrings.GcMemoryMessage = e.Message; - continue; - } + //gc profiling is a special case + if (e.Key == GcProfiling.GcMemoryKey) + { + gameProfilingSystemStrings.GcMemoryMessage = e.Message; + continue; + } - if (e.Key == GcProfiling.GcCollectionCountKey) - { - gameProfilingSystemStrings.GcCollectionMessage = e.Message; - continue; - } + if (e.Key == GcProfiling.GcCollectionCountKey) + { + gameProfilingSystemStrings.GcCollectionMessage = e.Message; + continue; + } - if (e.Key == GameProfilingKeys.GameDrawFPS && e.Type == ProfilingMessageType.End) - continue; + if (e.Key == GameProfilingKeys.GameDrawFPS && e.Type == ProfilingMessageType.End) + continue; - ProfilingResult profilingResult; - if (!profilingResults.TryGetValue(e.Key, out profilingResult)) - { - profilingResult.MinTime = TimeSpan.MaxValue; - } + ProfilingResult profilingResult; + if (!profilingResults.TryGetValue(e.Key, out profilingResult)) + { + profilingResult.MinTime = TimeSpan.MaxValue; + } - if (e.Type == ProfilingMessageType.End) - { - ++profilingResult.Count; - profilingResult.AccumulatedTime += e.ElapsedTime; + if (e.Type == ProfilingMessageType.End) + { + ++profilingResult.Count; + profilingResult.AccumulatedTime += e.ElapsedTime; - if (e.ElapsedTime < profilingResult.MinTime) - profilingResult.MinTime = e.ElapsedTime; - if (e.ElapsedTime > profilingResult.MaxTime) - profilingResult.MaxTime = e.ElapsedTime; + if (e.ElapsedTime < profilingResult.MinTime) + profilingResult.MinTime = e.ElapsedTime; + if (e.ElapsedTime > profilingResult.MaxTime) + profilingResult.MaxTime = e.ElapsedTime; - profilingResult.EventKey = e.Key; - profilingResult.EventMessage = e.Message; - } - else if (e.Type == ProfilingMessageType.Mark) - { - profilingResult.MarkCount++; - containsMarks = true; + profilingResult.EventKey = e.Key; + profilingResult.EventMessage = e.Message; + } + else if (e.Type == ProfilingMessageType.Mark) + { + profilingResult.MarkCount++; + containsMarks = true; + } + + profilingResults[e.Key] = profilingResult; } - profilingResults[e.Key] = profilingResult; + // we don't want to await on WaitToReadAsync too often because it allocates + // thus after we have read a batch of events we wait for a bit before reading more + await Task.Delay((int)RefreshTime / 10, cancellationToken); } } @@ -431,7 +438,7 @@ public int Compare(ProfilingResult x, ProfilingResult y) private class GameProfilingSystemStrings { private IGame Game { get; } - private GraphicsDevice GraphicsDevice { get; } + private GraphicsDevice GraphicsDevice { get; set; } private readonly StringBuilder profilersStringBuilder = new StringBuilder(4096); @@ -499,6 +506,9 @@ public void UpdateProfilingStrings(bool containsMarks, float viewportHeight, uin GenerateEventTable(containsMarks, viewportHeight, elapsedFrames); + if (GraphicsDevice == null) + GraphicsDevice = Game.GraphicsDevice; + const float mb = 1 << 20; GpuInfoString = $"Drawn triangles: {trianglesCount / 1000f:0.0}k, Draw calls: {drawCallsCount}, Buffer memory: {GraphicsDevice.BuffersMemory / mb:0.00}[MB], Texture memory: {GraphicsDevice.TextureMemory / mb:0.00}[MB]"; From db2732179ec2c1e73dd4adbdbb863d70fe317330 Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Sun, 19 Nov 2023 19:14:20 +0000 Subject: [PATCH 10/11] Final fixes --- .../core/Stride.Core/Diagnostics/Profiler.cs | 8 +++---- .../Profiling/GameProfilingSystem.cs | 24 +++++++++---------- 2 files changed, 15 insertions(+), 17 deletions(-) diff --git a/sources/core/Stride.Core/Diagnostics/Profiler.cs b/sources/core/Stride.Core/Diagnostics/Profiler.cs index 98352dfa6f..afe70dc4d1 100644 --- a/sources/core/Stride.Core/Diagnostics/Profiler.cs +++ b/sources/core/Stride.Core/Diagnostics/Profiler.cs @@ -72,7 +72,7 @@ internal static ProfilingEventChannel Create(bool singleReader = false, bool sin { SingleReader = singleReader, SingleWriter = singleWriter, - FullMode = BoundedChannelFullMode.DropWrite, + FullMode = BoundedChannelFullMode.DropWrite, // optimize caller to not block }); return new ProfilingEventChannel { _channel = channel }; @@ -164,7 +164,7 @@ public static ChannelReader Subscribe() { SingleReader = true, SingleWriter = true, - FullMode = BoundedChannelFullMode.DropNewest + FullMode = BoundedChannelFullMode.DropNewest, // dropping newer events so that we don't mess with events continuity }); subscriberChannels.TryAdd(channel.Reader, channel); Interlocked.Increment(ref subscriberChannelsModified); @@ -355,7 +355,7 @@ private static void AddThread(ThreadEventCollection eventCollection) /// The event. private static void SendEventToSubscribers(ProfilingEvent e) { - if (subscriberChannels.Count >= 1) + if (!subscriberChannels.IsEmpty) collectorChannel.Writer.TryWrite(e); } @@ -402,7 +402,7 @@ public static void AppendTime([NotNull] StringBuilder builder, TimeSpan accumula { accumulatedTimeSpan.TotalMilliseconds.TryFormat(buffer, out _, "000.000"); builder.Append(buffer); - builder.Append("ms "); + builder.Append("ms"); } } } diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index 196c73eb1e..9104e5bdb7 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -69,16 +69,15 @@ public GameProfilingSystem(IServiceRegistry registry) : base(registry) gameProfilingSystemStrings = new GameProfilingSystemStrings(Game, GraphicsDevice); } - private void UpdateInternalState(bool containsMarks) + private void UpdateStringsAndProfilers(bool containsMarks) { gameProfilingSystemStrings.CopyEventsForStringUpdate(profilingResults); profilingResults.Clear(); + gameProfilingSystemStrings.UpdateProfilingStrings(containsMarks, viewportHeight, trianglesCount, drawCallsCount, renderTargetSize); + //Advance any profiler that needs it gcProfiler.Tick(); - - // update strings on another thread so that we don't block the event loop in UpdateWithEventsAsync - _ = Task.Run(() => gameProfilingSystemStrings.UpdateProfilingStrings(containsMarks, viewportHeight, trianglesCount, drawCallsCount, renderTargetSize)); } private async Task UpdateFpsAsync(CancellationToken cancellationToken) @@ -88,13 +87,11 @@ private async Task UpdateFpsAsync(CancellationToken cancellationToken) //In Fps filtering mode wait until it is time to update the output. await Task.Delay((int)RefreshTime, cancellationToken).ConfigureAwait(false); - UpdateInternalState(false); + UpdateStringsAndProfilers(containsMarks: false); } } - //If we're subscribed to the Profiler (Cpu/Gpu mode) start receiving events. - //Control flow will only return here once the profilerChannel is closed. - private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) + private async Task UpdateWithProfilerEventsAsync(CancellationToken cancellationToken) { var containsMarks = false; Task delayTask = Task.Delay((int)RefreshTime, cancellationToken); @@ -105,7 +102,7 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) { if (delayTask.IsCompleted) { - UpdateInternalState(containsMarks); + UpdateStringsAndProfilers(containsMarks); delayTask = Task.Delay((int)RefreshTime); containsMarks = false; } @@ -167,7 +164,8 @@ private async Task UpdateWithEventsAsync(CancellationToken cancellationToken) // we don't want to await on WaitToReadAsync too often because it allocates // thus after we have read a batch of events we wait for a bit before reading more - await Task.Delay((int)RefreshTime / 10, cancellationToken); + // (division by 5 is arbitrary - with default 500ms refresh time it means we wait 100ms) + await Task.Delay((int)RefreshTime / 5, cancellationToken); } } @@ -188,7 +186,7 @@ private void RunBackgroundUpdate(bool restart) } else { - asyncUpdateTask = Task.Run(() => UpdateWithEventsAsync(backgroundUpdateCancellationSource.Token)); + asyncUpdateTask = Task.Run(() => UpdateWithProfilerEventsAsync(backgroundUpdateCancellationSource.Token)); } } } @@ -564,14 +562,14 @@ private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, boo profilersStringBuilder.Append(" | "); var callsPerFrame = profilingResult.Count / (double)elapsedFrames; - callsPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0,6:#00.00}"); + callsPerFrame.TryFormat(formatBuffer, out formatBufferUse, "#00.00"); profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); profilersStringBuilder.Append(" | "); if (displayMarkCount) { var marksPerFrame = profilingResult.MarkCount / (double)elapsedFrames; - marksPerFrame.TryFormat(formatBuffer, out formatBufferUse, "{0:00.00}"); + marksPerFrame.TryFormat(formatBuffer, out formatBufferUse, "#00.00"); profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); profilersStringBuilder.Append(" | "); } From a6d4ee6b0226ab68eb9885f4ca12b9de6a1e1b4e Mon Sep 17 00:00:00 2001 From: Marian Dziubiak Date: Mon, 20 Nov 2023 21:55:43 +0000 Subject: [PATCH 11/11] Fix table layout --- sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs index 9104e5bdb7..8f4086cda7 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -563,6 +563,8 @@ private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, boo var callsPerFrame = profilingResult.Count / (double)elapsedFrames; callsPerFrame.TryFormat(formatBuffer, out formatBufferUse, "#00.00"); + if (callsPerFrame < 100) + profilersStringBuilder.Append(' '); profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); profilersStringBuilder.Append(" | ");