Skip to content

perf(core): Performance fixes in GameProfilingSystem and ChromeTracingProfileWriter #1953

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
froce wants to merge 1 commit into from
Closed

perf(core): Performance fixes in GameProfilingSystem and ChromeTracingProfileWriter #1953

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 11 additions & 5 deletions sources/core/Stride.Core/Diagnostics/ChromeTracingProfileWriter.cs
View file
Open in desktop

@Kryptos-FR Kryptos-FR Nov 19, 2023

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This also need a CancellationTokenSource to stop the task at the earliest opportunity. There should also be a protection against calling Start() or Stop() multiple times on the same instance.

Original file line number Diff line number Diff line change
Expand Up @@ -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");
Expand All @@ -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)
Expand All @@ -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();
Expand All @@ -92,6 +97,7 @@ public void Stop()
writerTask?.Wait();

@Kryptos-FR Kryptos-FR Nov 19, 2023

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why does it need to wait after Stop() has been called. Can't it just signal a cancellation and return immediately?

@manio143 manio143 Nov 19, 2023

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be good to wait here in order to observe any exception which may have been thrown

}
}

#nullable enable
ChannelReader<ProfilingEvent>? eventReader;
Task? writerTask;
Expand Down
143 changes: 71 additions & 72 deletions sources/engine/Stride.Engine/Profiling/GameProfilingSystem.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<ProfilingEvent> profilerChannel;
private PresentInterval? userPresentInterval;
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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;
}
}

Expand Down Expand Up @@ -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();

@Kryptos-FR Kryptos-FR Nov 19, 2023 •
edited
Loading

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any long-running operation should have a TaskCancellationSource and pass the associated CancellationToken everywhere. Destroy() should not hang on the next RefreshTime tick.

}

gcProfiler.Dispose();
Expand Down Expand Up @@ -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);
}
}

Expand Down