diff --git a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs b/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs index a42e7c622d..33c61797c6 100644 --- a/sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs +++ b/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 { + /// + /// 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(); + 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,38 +57,47 @@ 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(); @@ -84,17 +105,27 @@ 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) { Profiler.Unsubscribe(eventReader); + eventReader = null; + + cts?.Cancel(); + cts?.Dispose(); + writerTask?.Wait(); } } + #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 a81a8918c0..afe70dc4d1 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,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(options); + // bounded channel is supposed to have lower allocation overhead than unbounded + var channel = Channel.CreateBounded(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 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 long subscriberChannelsModified = 0; 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() { + // 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()) { - 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() /// The which will receive the events. public static ChannelReader Subscribe() { - var channel = Channel.CreateUnbounded(new UnboundedChannelOptions { SingleReader = true, SingleWriter = true }); - subscriberChannelLock.Wait(); - try + var channel = Channel.CreateBounded(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 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(); + Interlocked.Increment(ref subscriberChannelsModified); } - finally { subscriberChannelLock.Release(); } } /// @@ -346,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); } @@ -376,17 +385,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 4be1ba0d0a..8f4086cda7 100644 --- a/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs +++ b/sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs @@ -2,8 +2,8 @@ // 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; using System.Threading.Tasks; using Stride.Core; @@ -19,6 +19,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; @@ -26,23 +27,7 @@ public class GameProfilingSystem : GameSystemBase private readonly GcProfiling gcProfiler; - private readonly StringBuilder gcMemoryStringBuilder = new StringBuilder(); - private string gcMemoryString = string.Empty; - - private readonly StringBuilder gcCollectionsStringBuilder = new StringBuilder(); - private string gcCollectionsString = string.Empty; - - private readonly StringBuilder fpsStatStringBuilder = new StringBuilder(); - private string fpsStatString = string.Empty; - - private readonly StringBuilder gpuGeneralInfoStringBuilder = new StringBuilder(); - private string gpuGeneralInfoString = string.Empty; - - private readonly StringBuilder gpuInfoStringBuilder = new StringBuilder(); - private string gpuInfoString = string.Empty; - - private readonly StringBuilder profilersStringBuilder = new StringBuilder(); - private string profilersString = string.Empty; + private readonly GameProfilingSystemStrings gameProfilingSystemStrings; private FastTextRenderer fastTextRenderer; @@ -50,15 +35,12 @@ 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; private bool userMinimizedState = true; - private int lastFrame = -1; - private float viewportHeight = 1000; private uint numberOfPages; @@ -66,30 +48,15 @@ public class GameProfilingSystem : GameSystemBase private uint trianglesCount; private uint drawCallsCount; + private readonly Dictionary profilingResults = new Dictionary(256); + + private CancellationTokenSource backgroundUpdateCancellationSource; + /// /// The render target where the profiling results should be rendered into. If null, the is used. /// 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 ProfilingEvent? Event; - - 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(); - private readonly Dictionary profilingResultsDictionary = new Dictionary(); - /// /// Initializes a new instance of the class. /// @@ -99,131 +66,49 @@ public GameProfilingSystem(IServiceRegistry registry) : base(registry) DrawOrder = 0xfffffe; gcProfiler = new GcProfiling(); + gameProfilingSystemStrings = new GameProfilingSystemStrings(Game, GraphicsDevice); } - private readonly Stopwatch dumpTiming = Stopwatch.StartNew(); - - - - private void UpdateProfilingStrings(bool containsMarks) + private void UpdateStringsAndProfilers(bool containsMarks) { - 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(); + gameProfilingSystemStrings.CopyEventsForStringUpdate(profilingResults); 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); - CurrentResultPage = Math.Min(CurrentResultPage, numberOfPages); + gameProfilingSystemStrings.UpdateProfilingStrings(containsMarks, viewportHeight, trianglesCount, drawCallsCount, renderTargetSize); - 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"); + //Advance any profiler that needs it + gcProfiler.Tick(); + } - for (int i = 0; i < Math.Min(profilingResults.Count - (CurrentResultPage - 1) * elementsPerPage, elementsPerPage); i++) + private async Task UpdateFpsAsync(CancellationToken cancellationToken) + { + while (!backgroundUpdateCancellationSource.IsCancellationRequested) { - AppendEvent(profilingResults[((int)CurrentResultPage - 1) * elementsPerPage + i], elapsedFrames, containsMarks); - } - profilingResults.Clear(); - - if (numberOfPages > 1) - profilersStringBuilder.AppendFormat("PAGE {0} OF {1}", CurrentResultPage, numberOfPages); + //In Fps filtering mode wait until it is time to update the output. + await Task.Delay((int)RefreshTime, cancellationToken).ConfigureAwait(false); - 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); - - 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); - - 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); - - lock (stringLock) - { - gcCollectionsString = gcCollectionsStringBuilder.ToString(); - gcMemoryString = gcMemoryStringBuilder.ToString(); - profilersString = profilersStringBuilder.ToString(); - fpsStatString = fpsStatStringBuilder.ToString(); - gpuInfoString = gpuInfoStringBuilder.ToString(); - gpuGeneralInfoString = gpuGeneralInfoStringBuilder.ToString(); + UpdateStringsAndProfilers(containsMarks: false); } } - private async Task ReadEventsAsync() + private async Task UpdateWithProfilerEventsAsync(CancellationToken cancellationToken) { var containsMarks = false; + Task delayTask = Task.Delay((int)RefreshTime, cancellationToken); - //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) + while (await profilerChannel.WaitToReadAsync(cancellationToken)) { - if (dumpTiming.ElapsedMilliseconds > RefreshTime) + while (profilerChannel.TryRead(out var e)) { - using (Profiler.Begin(UpdateStringsKey)) + if (delayTask.IsCompleted) { - UpdateProfilingStrings(containsMarks); - dumpTiming.Restart(); + UpdateStringsAndProfilers(containsMarks); + delayTask = Task.Delay((int)RefreshTime); containsMarks = false; } - } - if (profilerChannel == null) - continue; - - await foreach (var e in profilerChannel.ReadAllAsync()) - { - if (dumpTiming.ElapsedMilliseconds > RefreshTime) - { - using (Profiler.Begin(UpdateStringsKey)) - { - UpdateProfilingStrings(containsMarks); - dumpTiming.Restart(); - containsMarks = false; - } - } + if (cancellationToken.IsCancellationRequested) + continue; // skip events until they run out if (FilteringMode == GameProfilingResults.Fps) continue; @@ -236,15 +121,13 @@ private async Task ReadEventsAsync() //gc profiling is a special case if (e.Key == GcProfiling.GcMemoryKey) { - gcMemoryStringBuilder.Clear(); - e.Message?.ToString(gcMemoryStringBuilder); + gameProfilingSystemStrings.GcMemoryMessage = e.Message; continue; } if (e.Key == GcProfiling.GcCollectionCountKey) { - gcCollectionsStringBuilder.Clear(); - e.Message?.ToString(gcCollectionsStringBuilder); + gameProfilingSystemStrings.GcCollectionMessage = e.Message; continue; } @@ -252,7 +135,7 @@ private async Task ReadEventsAsync() continue; ProfilingResult profilingResult; - if (!profilingResultsDictionary.TryGetValue(e.Key, out profilingResult)) + if (!profilingResults.TryGetValue(e.Key, out profilingResult)) { profilingResult.MinTime = TimeSpan.MaxValue; } @@ -267,7 +150,8 @@ private async Task ReadEventsAsync() 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) { @@ -275,44 +159,36 @@ private async Task ReadEventsAsync() containsMarks = true; } - profilingResultsDictionary[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 + // (division by 5 is arbitrary - with default 500ms refresh time it means we wait 100ms) + await Task.Delay((int)RefreshTime / 5, cancellationToken); } } - private void AppendEvent(ProfilingResult profilingResult, int elapsedFrames, bool displayMarkCount) + private void RunBackgroundUpdate(bool restart) { - elapsedFrames = Math.Max(elapsedFrames, 1); - - var profilingEvent = profilingResult.Event.Value; - - 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(" | "); - profilersStringBuilder.AppendFormat("{0,6:#00.00}", profilingResult.Count / (double)elapsedFrames); - profilersStringBuilder.Append(" | "); - - if (displayMarkCount) + if (restart || asyncUpdateTask == null || asyncUpdateTask.IsCompleted) { - profilersStringBuilder.AppendFormat("{0:00.00}", profilingResult.MarkCount / (double)elapsedFrames); - profilersStringBuilder.Append(" | "); - } + if (backgroundUpdateCancellationSource != null) + { + backgroundUpdateCancellationSource.Cancel(); + backgroundUpdateCancellationSource.Dispose(); + } + backgroundUpdateCancellationSource = new CancellationTokenSource(); - profilersStringBuilder.Append(profilingEvent.Key); - // ReSharper disable once ReplaceWithStringIsNullOrEmpty - // This was creating memory allocation (GetEnumerable()) - if (profilingEvent.Message != null) - { - profilersStringBuilder.Append(" / "); - profilingEvent.Message?.ToString(profilersStringBuilder); + if (FilteringMode == GameProfilingResults.Fps) + { + asyncUpdateTask = Task.Run(() => UpdateFpsAsync(backgroundUpdateCancellationSource.Token)); + } + else + { + asyncUpdateTask = Task.Run(() => UpdateWithProfilerEventsAsync(backgroundUpdateCancellationSource.Token)); + } } - - profilersStringBuilder.Append("\n"); } /// @@ -321,11 +197,19 @@ protected override void Destroy() Enabled = false; Visible = false; - Profiler.Unsubscribe(profilerChannel); + if (profilerChannel != null) + Profiler.Unsubscribe(profilerChannel); + + backgroundUpdateCancellationSource?.Cancel(); + backgroundUpdateCancellationSource?.Dispose(); - if (stringBuilderTask != null && !stringBuilderTask.IsCompleted) + if (asyncUpdateTask != null && !asyncUpdateTask.IsCompleted) { - stringBuilderTask.Wait(); + try + { + asyncUpdateTask.Wait(); + } + catch { } // likely throws cancellation exception } gcProfiler.Dispose(); @@ -334,6 +218,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; @@ -363,30 +249,35 @@ 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; + + var currentHeight = textDrawStartOffset.Y; + fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, fpsStatString, textDrawStartOffset.X, currentHeight); + currentHeight += TopRowHeight; - if (FilteringMode != GameProfilingResults.Fps) - fastTextRenderer.DrawString(renderDrawContext.GraphicsContext, profilersString, textDrawStartOffset.X, currentHeight); + 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); } @@ -439,10 +330,7 @@ public void EnableProfiling(bool excludeKeys = false, params ProfilingKey[] keys gcProfiler.Enable(); - if (stringBuilderTask == null || stringBuilderTask.IsCompleted) - { - stringBuilderTask = Task.Run(ReadEventsAsync); - } + RunBackgroundUpdate(restart: false); } /// @@ -464,6 +352,7 @@ public void DisableProfiling() gcProfiler.Disable(); FilteringMode = GameProfilingResults.Fps; + backgroundUpdateCancellationSource.Cancel(); } /// @@ -483,26 +372,32 @@ 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); } } } @@ -515,6 +410,181 @@ 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; set; } + + 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; } = 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; + + 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); + + 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]"; + + //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, "#00.00"); + if (callsPerFrame < 100) + profilersStringBuilder.Append(' '); + profilersStringBuilder.Append(formatBuffer[..formatBufferUse]); + profilersStringBuilder.Append(" | "); + + if (displayMarkCount) + { + var marksPerFrame = profilingResult.MarkCount / (double)elapsedFrames; + marksPerFrame.TryFormat(formatBuffer, out formatBufferUse, "#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"); + } + } } }