From 7a8dde88c0a26445ef42eeea8bbbc671702048e2 Mon Sep 17 00:00:00 2001 From: botoddly <250804054+botoddly@users.noreply.github.com> Date: Mon, 5 Oct 2026 11:04:27 +0200 Subject: [PATCH 1/3] Register diagnostics last in Build so they no longer create the logger factory and GPU device ahead of the app's services, and test the frame loop, console and dispose wiring --- DECISIONS.md | 2 +- docs/diagnostics.md | 2 +- src/Pixely/App/PerformanceReport.cs | 11 ++- src/Pixely/App/PixelyAppBuilder.cs | 16 +++-- .../RenderingExtensions.cs | 3 +- .../InputAutomationConsoleTests.cs | 35 +++++++++- .../Pixely.Tests/PixelyAppDiagnosticsTests.cs | 69 +++++++++++++++++++ tests/Pixely.Tests/RecordingLoggerFactory.cs | 20 ++++++ 8 files changed, 145 insertions(+), 13 deletions(-) create mode 100644 tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs create mode 100644 tests/Pixely.Tests/RecordingLoggerFactory.cs diff --git a/DECISIONS.md b/DECISIONS.md index 3308996b..196ec379 100644 --- a/DECISIONS.md +++ b/DECISIONS.md @@ -17,7 +17,7 @@ Cost: a shader that needs a start reads it from a uniform, and a draw over a lat ## 2026-10-05: Performance diagnostics are logged, measured at three points, and count no draws -With `PIXELY_DIAGNOSTICS`, `PixelyApp.RunFrame` and `RenderCoordinator` record the update, the render and the swapchain wait of every frame in `FrameTimings`, through `IFrameTimingRecorder`. `PerformanceReport`, an updatable, logs the average, 95th percentile and maximum of each every 5 seconds, together with gen0 collections and GPU memory, and the GPU device at startup and each window's swapchain. Without diagnostics the recorder is `NullFrameTimingRecorder` and no report is registered. This replaces `PerformanceTracker`, which Pixely never registered and which read the frame clock, so in headless mode it reported the fixed step. +With `PIXELY_DIAGNOSTICS`, `PixelyApp.RunFrame` and `RenderCoordinator` record the update, the render and the swapchain wait of every frame in `FrameTimings`, through `IFrameTimingRecorder`. `PerformanceReport`, an updatable, logs the average, 95th percentile and maximum of each every 5 seconds, together with gen0 collections and GPU memory, and the GPU device at startup and each window's swapchain. Without diagnostics the recorder is `NullFrameTimingRecorder` and no report is created. `Build()` registers them last, and the report resolves the logger factory and the GPU device only while diagnostics are on, so diagnostics change neither when the app's services are created nor when they are disposed. This replaces `PerformanceTracker`, which Pixely never registered and which read the frame clock, so in headless mode it reported the fixed step. - The numbers must be readable on a kiosk compositor, where the screen is the game, so they go to the log instead of an overlay. - .NET metrics with `dotnet-counters` would give percentiles and gen0 collections for free, but a NativeAOT app needs `EventSourceSupport` at build time. Diagnostics must turn on in the shipped build with an environment variable. diff --git a/docs/diagnostics.md b/docs/diagnostics.md index 3b59aa73..efa5a4ed 100644 --- a/docs/diagnostics.md +++ b/docs/diagnostics.md @@ -4,7 +4,7 @@ Pixely can report where a frame's time goes, which GPU device it runs on, and ho ## Turning it on -Set `PIXELY_DIAGNOSTICS` to `1` or `true`, or register `new PixelyConfig(EnableDiagnostics: true)`. The variable overrides the configured value, like the other variables in [headless.md](headless.md#environment-variables). Diagnostics are off by default. When they are off, nothing is created and each frame pays only a few null checks. +Set `PIXELY_DIAGNOSTICS` to `1` or `true`, or register `new PixelyConfig(EnableDiagnostics: true)`. The variable overrides the configured value, like the other variables in [headless.md](headless.md#environment-variables). Diagnostics are off by default. When they are off, each frame calls a recorder that does nothing, and no report is created. The report is written to the logger category `Pixely.Diagnostics` at the `Information` level when the app registers a logger factory (see [logging.md](logging.md)), and to standard output otherwise. diff --git a/src/Pixely/App/PerformanceReport.cs b/src/Pixely/App/PerformanceReport.cs index 19139b81..51ed17c4 100644 --- a/src/Pixely/App/PerformanceReport.cs +++ b/src/Pixely/App/PerformanceReport.cs @@ -18,7 +18,8 @@ internal sealed class PerformanceReport : IUpdatable, IDisposable private readonly ILogger? _logger; private readonly GpuDevice? _gpuDevice; private readonly double[] _sortedTimes = new double[FrameTimings.Capacity]; - private int _periodStartGen0Collections = GC.CollectionCount(0); + private bool _hasGen0Baseline; + private int _periodStartGen0Collections; internal PerformanceReport(FrameTimings timings, ILogger? logger, GpuDevice? gpuDevice) { @@ -35,6 +36,14 @@ internal PerformanceReport(FrameTimings timings, ILogger? logger, GpuDevice? gpu public void Update() { + // Taken on the first frame rather than at construction, so the collections of building the app and loading its content + // are not counted against the first period. + if (!_hasGen0Baseline) + { + _periodStartGen0Collections = GC.CollectionCount(0); + _hasGen0Baseline = true; + } + WriteSwapchainChanges(); if (_timings.Duration >= PeriodSeconds || _timings.IsFull) { diff --git a/src/Pixely/App/PixelyAppBuilder.cs b/src/Pixely/App/PixelyAppBuilder.cs index bdc8b2dc..3b887237 100644 --- a/src/Pixely/App/PixelyAppBuilder.cs +++ b/src/Pixely/App/PixelyAppBuilder.cs @@ -27,13 +27,6 @@ public PixelyAppBuilder() AddRegistry(); AddRegistry>(static renderer => renderer.RenderOrder); AddRegistry(static updatable => updatable.UpdateOrder); - - // Diagnostics, see docs/diagnostics.md. While they are off, the frame records its timings to a recorder that does - // nothing and nothing reports them. - AddSingleton(static (PixelyConfig? config) => config is { EnableDiagnostics: true } ? new FrameTimings() : null); - AddSingleton(static (FrameTimings? timings) => timings ?? (IFrameTimingRecorder)NullFrameTimingRecorder.Instance); - AddSingleton(static (FrameTimings? timings, ILoggerFactory? loggerFactory, GpuDevice? gpuDevice) => - timings is null ? null : new PerformanceReport(timings, loggerFactory?.CreateLogger(PerformanceReport.LoggerCategoryName), gpuDevice)); } public PixelyAppBuilder ConfigureContent(Action configure) @@ -104,6 +97,15 @@ public IPixelyApp Build() AddSingleton(); } + // Diagnostics, see docs/diagnostics.md. Registered last, and the report resolves the logger factory and the GPU device only + // while diagnostics are on, so they change neither when the app's services are created nor when they are disposed. While + // they are off, the frame records its timings to a recorder that does nothing and no report is created. + AddSingleton(static provider => provider.GetRequiredService().EnableDiagnostics ? new FrameTimings() : null); + AddSingleton(static provider => provider.GetService() ?? (IFrameTimingRecorder)NullFrameTimingRecorder.Instance); + AddSingleton(static provider => provider.GetService() is { } timings + ? new PerformanceReport(timings, provider.GetService()?.CreateLogger(PerformanceReport.LoggerCategoryName), provider.GetService()) + : null); + ServiceProvider serviceProvider = BuildServiceProvider(); return new PixelyApp( serviceProvider, diff --git a/src/Pixely/RenderOrchestration/RenderingExtensions.cs b/src/Pixely/RenderOrchestration/RenderingExtensions.cs index f7075b1a..7484e06d 100644 --- a/src/Pixely/RenderOrchestration/RenderingExtensions.cs +++ b/src/Pixely/RenderOrchestration/RenderingExtensions.cs @@ -47,6 +47,7 @@ private static void ConfigureWindowRendering(ServiceCollection s new RenderCoordinatorGpu(provider.GetRequiredService(), provider.GetRequiredService()), provider.GetRequiredService>(), provider.GetRequiredService>>(), - provider.GetRequiredService())); + // PixelyAppBuilder.Build() registers the recorder; a provider built without it records nothing. + provider.GetService() ?? NullFrameTimingRecorder.Instance)); } } diff --git a/tests/Pixely.Tests/InputAutomationConsoleTests.cs b/tests/Pixely.Tests/InputAutomationConsoleTests.cs index 08066109..8739ce91 100644 --- a/tests/Pixely.Tests/InputAutomationConsoleTests.cs +++ b/tests/Pixely.Tests/InputAutomationConsoleTests.cs @@ -128,12 +128,33 @@ public void Update_PartialCommand_BlocksUntilItsSemicolonWithinOneUpdate() }); } + [Test] + public void Update_RecordsTheReadsAsInputWait() + { + long now = 0; + FrameTimings timings = new(() => now, FrameTimingsTests.Frequency); + Fixture fixture = CreateConsole(new AdvancingReader("key press A;", () => now += 100), timings); + + timings.BeginFrame(); + fixture.Console.Update(); + timings.EndUpdate(); + timings.EndRender(); + timings.EndFrame(); + + Assert.Multiple(() => + { + Assert.That(now, Is.Positive); + Assert.That(timings.UpdateTimes[0], Is.Zero); + Assert.That(timings.FrameTimes[0], Is.Zero); + }); + } + private static Fixture CreateConsole(string input) { return CreateConsole(new StringReader(input)); } - private static Fixture CreateConsole(TextReader input) + private static Fixture CreateConsole(TextReader input, IFrameTimingRecorder? frameTimingRecorder = null) { WindowRegistry windowRegistry = new(); windowRegistry.Register(InputAutomationTests.CreateWindow(default, 42)); @@ -145,7 +166,17 @@ private static Fixture CreateConsole(TextReader input) AppControl appControl = new(); InputAutomationCommandInterpreter interpreter = new(automation, windowRegistry, new NoImageWriter(), appControl); - return new Fixture(new InputAutomationConsole(interpreter, input, appControl, NullFrameTimingRecorder.Instance), presses, appControl); + return new Fixture(new InputAutomationConsole(interpreter, input, appControl, frameTimingRecorder ?? NullFrameTimingRecorder.Instance), presses, appControl); + } + + // Advances a clock on every character read, standing in for a read that blocks. + private sealed class AdvancingReader(string input, Action advance) : StringReader(input) + { + public override int Read() + { + advance(); + return base.Read(); + } } private sealed record Fixture(InputAutomationConsole Console, ConcurrentQueue Presses, AppControl AppControl); diff --git a/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs b/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs new file mode 100644 index 00000000..fa9d131b --- /dev/null +++ b/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs @@ -0,0 +1,69 @@ +using Microsoft.Extensions.Logging; +using Pixely.App; +using SDL; + +namespace Pixely.Tests; + +// Builds real apps, which initializes SDL video with the dummy driver. +[NonParallelizable] +public class PixelyAppDiagnosticsTests +{ + // The logger factory stands in for the GPU device, which a test cannot create without a GPU: both are services the report + // resolves, so registering diagnostics must not create either ahead of the app's own services. + [TestCase(false)] + [TestCase(true)] + public void Build_KeepsTheCreationOrderOfTheAppsServices(bool enableDiagnostics) + { + List created = new(); + object appService = new(); + RecordingLoggerFactory loggerFactory = new(new RecordingLogger()); + PixelyAppBuilder builder = CreateBuilder(new PixelyConfig(EnableDiagnostics: enableDiagnostics)); + builder.OnActivated((instance, _) => created.Add(instance)); + builder.AddSingleton(_ => appService); + builder.AddSingleton(_ => loggerFactory); + + using IPixelyApp app = builder.Build(); + + Assert.That(created.IndexOf(appService), Is.LessThan(created.IndexOf(loggerFactory))); + } + + [Test] + public void RunFrame_RecordsTheFrameAndDisposeReportsIt() + { + long now = 0; + RecordingLogger logger = new(); + // Diagnostics stay off, so Build() registers no FrameTimings of its own and this one, on a fake clock, is used. + FrameTimings timings = new(() => now, FrameTimingsTests.Frequency); + PixelyAppBuilder builder = CreateBuilder(new PixelyConfig()); + builder.AddSingleton(_ => new RecordingLoggerFactory(logger)); + builder.AddSingleton(_ => timings); + builder.AddSingleton(_ => new ClockUpdatable(() => now += 200)); + IPixelyApp app = builder.Build(); + + app.RunFrame(); + app.RunFrame(); + app.Dispose(); + + Assert.That(logger.Messages.Last(), Does.StartWith( + "5.0 FPS over 2 frames, ms average/95th percentile/maximum: frame 200.00/200.00/200.00, update 200.00/200.00/200.00, " + + "render 0.00/0.00/0.00, swapchain wait 0.00/0.00/0.00; gen0 collections ")); + } + + private static PixelyAppBuilder CreateBuilder(PixelyConfig config) + { + SDL3.SDL_SetHintWithPriority(SDL3.SDL_HINT_VIDEO_DRIVER, "dummy", SDL_HintPriority.SDL_HINT_DEFAULT); + PixelyAppBuilder builder = new(); + builder.AddSingleton(config); + return builder; + } + + private sealed class ClockUpdatable(Action advance) : IUpdatable + { + public int UpdateOrder => UpdateOrders.Default; + + public void Update() + { + advance(); + } + } +} diff --git a/tests/Pixely.Tests/RecordingLoggerFactory.cs b/tests/Pixely.Tests/RecordingLoggerFactory.cs new file mode 100644 index 00000000..4be30334 --- /dev/null +++ b/tests/Pixely.Tests/RecordingLoggerFactory.cs @@ -0,0 +1,20 @@ +using Microsoft.Extensions.Logging; + +namespace Pixely.Tests; + +// Hands out the same recording logger for every category. +internal sealed class RecordingLoggerFactory(RecordingLogger logger) : ILoggerFactory +{ + public ILogger CreateLogger(string categoryName) + { + return logger; + } + + public void AddProvider(ILoggerProvider provider) + { + } + + public void Dispose() + { + } +} From 1c8361f1d313d3274652aa33b334df773e4d478e Mon Sep 17 00:00:00 2001 From: botoddly <250804054+botoddly@users.noreply.github.com> Date: Mon, 5 Oct 2026 11:18:46 +0200 Subject: [PATCH 2/3] Isolate the app diagnostics tests from PIXELY_* variables, check the GPU device position, fail on logging after the logger factory is disposed, and report GPU memory on dispose --- docs/diagnostics.md | 2 +- src/Pixely/App/PerformanceReport.cs | 16 ++-- tests/Pixely.Tests/PerformanceReportTests.cs | 37 -------- .../Pixely.Tests/PixelyAppDiagnosticsTests.cs | 91 +++++++++++++++++-- tests/Pixely.Tests/RecordingLogger.cs | 8 ++ tests/Pixely.Tests/RecordingLoggerFactory.cs | 1 + 6 files changed, 99 insertions(+), 56 deletions(-) diff --git a/docs/diagnostics.md b/docs/diagnostics.md index efa5a4ed..f5b8622a 100644 --- a/docs/diagnostics.md +++ b/docs/diagnostics.md @@ -37,7 +37,7 @@ Every 5 seconds of frames, or every 4096 frames if that comes first, and once mo | `render` | Every render coordinator, without the swapchain wait: recording commands, uploads and submits. | | `swapchain wait` | Waiting for each window's swapchain texture, added up over the windows. | | `gen0 collections` | Garbage collections of generation 0, per frame. | -| `GPU memory` | The textures and buffers Pixely created on the root GPU device, at the time of the report. The report on dispose leaves it out, because stages and windows have released theirs by then. | +| `GPU memory` | The textures and buffers Pixely created on the root GPU device, at the time of the report. In the report on dispose, stages have already released theirs. | ## Reading the numbers diff --git a/src/Pixely/App/PerformanceReport.cs b/src/Pixely/App/PerformanceReport.cs index 51ed17c4..851b305b 100644 --- a/src/Pixely/App/PerformanceReport.cs +++ b/src/Pixely/App/PerformanceReport.cs @@ -6,7 +6,7 @@ namespace Pixely.App; -// Writes FrameTimings to the log: the GPU device at startup, each swapchain change, and the frames of every period. Registered +// Writes FrameTimings to the log: the GPU device at startup, each swapchain change, and the frames of every period. Created // only while PixelyConfig.EnableDiagnostics is on. See docs/diagnostics.md for what the numbers mean. internal sealed class PerformanceReport : IUpdatable, IDisposable { @@ -47,19 +47,19 @@ public void Update() WriteSwapchainChanges(); if (_timings.Duration >= PeriodSeconds || _timings.IsFull) { - WritePeriod(true); + WritePeriod(); } } - // Reports the frames since the last report, so a run shorter than a period still reports. The provider disposes this before - // the logger factory and the GPU device it was created from, but after the stages and the services created after it, which - // have released their GPU memory by then, so the GPU memory is left out. + // Reports the frames since the last report, so a run shorter than a period still reports. Build() registers this last, so + // the root provider disposes it before its own services, among them the logger factory and the GPU device. Stages are + // disposed before it, so their GPU memory is no longer counted. public void Dispose() { WriteSwapchainChanges(); if (_timings.Count > 0) { - WritePeriod(false); + WritePeriod(); } } @@ -78,7 +78,7 @@ private void WriteSwapchainChanges() _timings.ClearSwapchainChanges(); } - private void WritePeriod(bool withGpuMemory) + private void WritePeriod() { int gen0Collections = GC.CollectionCount(0) - _periodStartGen0Collections; StringBuilder builder = new(); @@ -88,7 +88,7 @@ private void WritePeriod(bool withGpuMemory) AppendTimes(builder, ", render ", _timings.RenderTimes); AppendTimes(builder, ", swapchain wait ", _timings.SwapchainWaitTimes); builder.Append(CultureInfo.InvariantCulture, $"; gen0 collections {(double)gen0Collections / _timings.Count:F2} per frame"); - if (withGpuMemory && _gpuDevice != null) + if (_gpuDevice != null) { GpuMemoryStats memory = _gpuDevice.MemoryStats; builder.Append($"; GPU memory {FormatBytes(memory.TotalBytes)}, textures {FormatBytes(memory.TextureBytes)}"); diff --git a/tests/Pixely.Tests/PerformanceReportTests.cs b/tests/Pixely.Tests/PerformanceReportTests.cs index 4eefc25c..244e15db 100644 --- a/tests/Pixely.Tests/PerformanceReportTests.cs +++ b/tests/Pixely.Tests/PerformanceReportTests.cs @@ -1,6 +1,4 @@ using Pixely.App; -using Pixely.DependencyInjection; -using SDL; using static Pixely.Tests.FrameTimingsTests; namespace Pixely.Tests; @@ -130,39 +128,4 @@ public void Update_WritesEachSwapchainChangeOnce() "Swapchain of view 0: 800x600, B8G8R8A8Unorm, offscreen" })); } - - [Test] - [NonParallelizable] - public void Build_WithoutDiagnostics_RecordsNothingAndReportsNothing() - { - using PixelyApp app = BuildApp(new PixelyConfig(Headless: true)); - - Assert.Multiple(() => - { - Assert.That(app.ServiceProvider.GetRequiredService(), Is.SameAs(NullFrameTimingRecorder.Instance)); - Assert.That(app.ServiceProvider.GetRequiredService>().OfType(), Is.Empty); - }); - } - - [Test] - [NonParallelizable] - public void Build_WithDiagnostics_RecordsFrameTimingsAndUpdatesTheReport() - { - using PixelyApp app = BuildApp(new PixelyConfig(Headless: true, EnableDiagnostics: true)); - - Assert.Multiple(() => - { - Assert.That(app.ServiceProvider.GetRequiredService(), Is.SameAs(app.ServiceProvider.GetRequiredService())); - Assert.That(app.ServiceProvider.GetRequiredService>().OfType().Count(), Is.EqualTo(1)); - }); - } - - // Building initializes SDL video; the dummy driver needs no display, and an environment override still wins. - private static PixelyApp BuildApp(PixelyConfig config) - { - SDL3.SDL_SetHintWithPriority(SDL3.SDL_HINT_VIDEO_DRIVER, "dummy", SDL_HintPriority.SDL_HINT_DEFAULT); - PixelyAppBuilder builder = new(); - builder.AddSingleton(config); - return (PixelyApp)builder.Build(); - } } diff --git a/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs b/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs index fa9d131b..f39b9ec6 100644 --- a/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs +++ b/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs @@ -1,5 +1,7 @@ using Microsoft.Extensions.Logging; using Pixely.App; +using Pixely.DependencyInjection; +using Pixely.Gpu; using SDL; namespace Pixely.Tests; @@ -8,31 +10,98 @@ namespace Pixely.Tests; [NonParallelizable] public class PixelyAppDiagnosticsTests { - // The logger factory stands in for the GPU device, which a test cannot create without a GPU: both are services the report - // resolves, so registering diagnostics must not create either ahead of the app's own services. + private static readonly string[] ConfigVariables = + [ + PixelyConfigEnvironment.GpuBackendVariable, + PixelyConfigEnvironment.HeadlessVariable, + PixelyConfigEnvironment.SdlLoggingVariable, + PixelyConfigEnvironment.GpuValidationVariable, + PixelyConfigEnvironment.PreferLowPowerGpuVariable, + PixelyConfigEnvironment.DiagnosticsVariable + ]; + + private readonly Dictionary _savedVariables = new(); + + // The variables override the config each test builds with, so they are cleared for the test and restored after it. + [SetUp] + public void ClearConfigVariables() + { + foreach (string variable in ConfigVariables) + { + _savedVariables[variable] = Environment.GetEnvironmentVariable(variable); + Environment.SetEnvironmentVariable(variable, null); + } + } + + [TearDown] + public void RestoreConfigVariables() + { + foreach ((string variable, string? value) in _savedVariables) + { + Environment.SetEnvironmentVariable(variable, value); + } + } + + // The report resolves the logger factory and the GPU device, so registering diagnostics must not create either ahead of the + // app's own services. The device factory returns no device, so no GPU is needed, but still records when it runs. [TestCase(false)] [TestCase(true)] public void Build_KeepsTheCreationOrderOfTheAppsServices(bool enableDiagnostics) { - List created = new(); - object appService = new(); - RecordingLoggerFactory loggerFactory = new(new RecordingLogger()); + List created = new(); PixelyAppBuilder builder = CreateBuilder(new PixelyConfig(EnableDiagnostics: enableDiagnostics)); - builder.OnActivated((instance, _) => created.Add(instance)); - builder.AddSingleton(_ => appService); - builder.AddSingleton(_ => loggerFactory); + builder.AddSingleton(_ => + { + created.Add("app service"); + return new AppService(); + }); + builder.AddSingleton(_ => + { + created.Add("logger factory"); + return new RecordingLoggerFactory(new RecordingLogger()); + }); + builder.AddSingleton(_ => + { + created.Add("GPU device"); + return null; + }); using IPixelyApp app = builder.Build(); - Assert.That(created.IndexOf(appService), Is.LessThan(created.IndexOf(loggerFactory))); + Assert.That(created, Is.EqualTo(new[] { "app service", "logger factory", "GPU device" })); + } + + [Test] + public void Build_WithoutDiagnostics_RecordsNothingAndReportsNothing() + { + using PixelyApp app = (PixelyApp)CreateBuilder(new PixelyConfig()).Build(); + + Assert.Multiple(() => + { + Assert.That(app.ServiceProvider.GetRequiredService(), Is.SameAs(NullFrameTimingRecorder.Instance)); + Assert.That(app.ServiceProvider.GetRequiredService>().OfType(), Is.Empty); + }); + } + + [Test] + public void Build_WithDiagnostics_RecordsFrameTimingsAndUpdatesTheReport() + { + using PixelyApp app = (PixelyApp)CreateBuilder(new PixelyConfig(EnableDiagnostics: true)).Build(); + + Assert.Multiple(() => + { + Assert.That(app.ServiceProvider.GetRequiredService(), Is.SameAs(app.ServiceProvider.GetRequiredService())); + Assert.That(app.ServiceProvider.GetRequiredService>().OfType().Count(), Is.EqualTo(1)); + }); } + // The recording logger throws once its factory is disposed, so the final report must come before the logger factory goes. [Test] public void RunFrame_RecordsTheFrameAndDisposeReportsIt() { long now = 0; RecordingLogger logger = new(); - // Diagnostics stay off, so Build() registers no FrameTimings of its own and this one, on a fake clock, is used. + // Diagnostics stay off, so the FrameTimings that Build() registers comes back null and this one, on a fake clock, is used. FrameTimings timings = new(() => now, FrameTimingsTests.Frequency); PixelyAppBuilder builder = CreateBuilder(new PixelyConfig()); builder.AddSingleton(_ => new RecordingLoggerFactory(logger)); @@ -57,6 +126,8 @@ private static PixelyAppBuilder CreateBuilder(PixelyConfig config) return builder; } + private sealed class AppService; + private sealed class ClockUpdatable(Action advance) : IUpdatable { public int UpdateOrder => UpdateOrders.Default; diff --git a/tests/Pixely.Tests/RecordingLogger.cs b/tests/Pixely.Tests/RecordingLogger.cs index 58a68f39..e1cd3d93 100644 --- a/tests/Pixely.Tests/RecordingLogger.cs +++ b/tests/Pixely.Tests/RecordingLogger.cs @@ -8,8 +8,16 @@ internal sealed class RecordingLogger : ILogger public IEnumerable Messages => Entries.Select(entry => entry.Message); + // Set when the factory that handed the logger out is disposed, after which a real logger drops what it is given. + public bool IsClosed { get; set; } + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { + if (IsClosed) + { + throw new ObjectDisposedException(nameof(RecordingLogger), "Logged after its logger factory was disposed."); + } + Entries.Add((logLevel, formatter(state, exception))); } diff --git a/tests/Pixely.Tests/RecordingLoggerFactory.cs b/tests/Pixely.Tests/RecordingLoggerFactory.cs index 4be30334..1fcee649 100644 --- a/tests/Pixely.Tests/RecordingLoggerFactory.cs +++ b/tests/Pixely.Tests/RecordingLoggerFactory.cs @@ -16,5 +16,6 @@ public void AddProvider(ILoggerProvider provider) public void Dispose() { + logger.IsClosed = true; } } From 6ea9bc006307755726298286b0d5f16507e2cf66 Mon Sep 17 00:00:00 2001 From: botoddly <250804054+botoddly@users.noreply.github.com> Date: Mon, 5 Oct 2026 13:17:51 +0200 Subject: [PATCH 3/3] Record only the report's log category in the dispose test and document the container's singleton creation order --- docs/class-registration.md | 2 +- tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs | 3 ++- tests/Pixely.Tests/RecordingLoggerFactory.cs | 8 +++++--- 3 files changed, 8 insertions(+), 5 deletions(-) diff --git a/docs/class-registration.md b/docs/class-registration.md index e26da6b9..3d412826 100644 --- a/docs/class-registration.md +++ b/docs/class-registration.md @@ -486,7 +486,7 @@ A throwing `OnDisposing` callback, service `Dispose()`, or child provider does n ## Lifecycle 1. **Registration** — call `AddSingleton`, `AddTransient`, `AddAlias`, `OnBuilt`, `OnActivated`, `OnDisposing` on `ServiceCollection`. -2. **`BuildServiceProvider`** — singleton services are instantiated in dependency order; `OnActivated` callbacks fire per singleton instance. +2. **`BuildServiceProvider`** — singleton services are instantiated type by type, in the order each service type was first registered, and in registration order within a type. A singleton that another one depends on is created first, when it is first needed. `OnActivated` callbacks fire per singleton instance. 3. **`OnBuilt` callbacks** — fire in registration order after all singleton services exist. 4. **Freeze** — the provider becomes immutable; build-time resolvers are cleared. 5. **Runtime resolution** — `GetRequiredService`, `GetService`, `GetServices` serve singletons from frozen arrays and construct transients on demand. diff --git a/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs b/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs index f39b9ec6..eb933213 100644 --- a/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs +++ b/tests/Pixely.Tests/PixelyAppDiagnosticsTests.cs @@ -104,7 +104,8 @@ public void RunFrame_RecordsTheFrameAndDisposeReportsIt() // Diagnostics stay off, so the FrameTimings that Build() registers comes back null and this one, on a fake clock, is used. FrameTimings timings = new(() => now, FrameTimingsTests.Frequency); PixelyAppBuilder builder = CreateBuilder(new PixelyConfig()); - builder.AddSingleton(_ => new RecordingLoggerFactory(logger)); + // Only the report's category, so SDL's messages, such as those it logs on quit, cannot come after the report. + builder.AddSingleton(_ => new RecordingLoggerFactory(logger, PerformanceReport.LoggerCategoryName)); builder.AddSingleton(_ => timings); builder.AddSingleton(_ => new ClockUpdatable(() => now += 200)); IPixelyApp app = builder.Build(); diff --git a/tests/Pixely.Tests/RecordingLoggerFactory.cs b/tests/Pixely.Tests/RecordingLoggerFactory.cs index 1fcee649..0aaac3e5 100644 --- a/tests/Pixely.Tests/RecordingLoggerFactory.cs +++ b/tests/Pixely.Tests/RecordingLoggerFactory.cs @@ -1,13 +1,15 @@ using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Pixely.Tests; -// Hands out the same recording logger for every category. -internal sealed class RecordingLoggerFactory(RecordingLogger logger) : ILoggerFactory +// Hands out the recording logger for one category, or for every category when none is given. Other categories get a logger +// that drops everything. +internal sealed class RecordingLoggerFactory(RecordingLogger logger, string? category = null) : ILoggerFactory { public ILogger CreateLogger(string categoryName) { - return logger; + return category is null || categoryName == category ? logger : NullLogger.Instance; } public void AddProvider(ILoggerProvider provider)