From d8c2155774ba2e3d917042af4ed15fa06a2fc6e4 Mon Sep 17 00:00:00 2001 From: Maximilien Noal Date: Sat, 9 Nov 2024 18:05:09 +0100 Subject: [PATCH 1/7] fix: <1ms performance measurement support Signed-off-by: Maximilien Noal --- .../Diagnostics/PerformanceMeasurer.cs | 26 +++++++++++++++---- 1 file changed, 21 insertions(+), 5 deletions(-) diff --git a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs index e8d6bad58..d21029f1a 100644 --- a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs +++ b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs @@ -31,14 +31,16 @@ public class PerformanceMeasurer : IPerformanceMeasurer { /// public void UpdateValue(long newMeasure) { long newTimeInMilliseconds = GetCurrentTime(); - if (_firstMeasureTimeInTicks == 0) { + if (IsFirstMeasurement()) { _firstMeasureTimeInTicks = newTimeInMilliseconds; - } else if((TimeSpan.FromTicks(newTimeInMilliseconds) - TimeSpan.FromTicks(_firstMeasureTimeInTicks)).TotalSeconds >= WindowSizeInSeconds) { - _firstMeasureTimeInTicks = newTimeInMilliseconds; - _sampledMetricsCount = 0; - AverageValuePerSecond = 0; + } else if (IsLastMeasurementExpired(newTimeInMilliseconds)) { + ResetMetrics(newTimeInMilliseconds); } + long millisecondsDelta = newTimeInMilliseconds - _lastTimeInMilliseconds; + if (millisecondsDelta == 0) { + return; + } _lastTimeInMilliseconds = newTimeInMilliseconds; long valueDelta = newMeasure - _measure; _measure = newMeasure; @@ -46,6 +48,20 @@ public void UpdateValue(long newMeasure) { AverageValuePerSecond = ApproxRollingAverage(AverageValuePerSecond, ValuePerSecond, _sampledMetricsCount++); } + private bool IsFirstMeasurement() { + return _firstMeasureTimeInTicks == 0; + } + + private void ResetMetrics(long newTimeInMilliseconds) { + _firstMeasureTimeInTicks = newTimeInMilliseconds; + _sampledMetricsCount = 0; + AverageValuePerSecond = 0; + } + + private bool IsLastMeasurementExpired(long newTimeInMilliseconds) { + return (TimeSpan.FromTicks(newTimeInMilliseconds) - TimeSpan.FromTicks(_firstMeasureTimeInTicks)).TotalSeconds >= WindowSizeInSeconds; + } + private static long ApproxRollingAverage(long measureAverage, long valuePerSecond, long sampledMetricsCount) { measureAverage -= measureAverage / Math.Max(sampledMetricsCount, 1); measureAverage += valuePerSecond / Math.Max(sampledMetricsCount, 1); From 0a83dd96ed30860808cf19d4cf8bce4943c66389 Mon Sep 17 00:00:00 2001 From: Maximilien Noal Date: Sat, 9 Nov 2024 18:06:09 +0100 Subject: [PATCH 2/7] refactor: OutputPerfStats uses PerformanceMeasurer Signed-off-by: Maximilien Noal --- src/Spice86.Core/Emulator/VM/EmulationLoop.cs | 30 +++++++++---------- 1 file changed, 14 insertions(+), 16 deletions(-) diff --git a/src/Spice86.Core/Emulator/VM/EmulationLoop.cs b/src/Spice86.Core/Emulator/VM/EmulationLoop.cs index af113522b..1a4f701a7 100644 --- a/src/Spice86.Core/Emulator/VM/EmulationLoop.cs +++ b/src/Spice86.Core/Emulator/VM/EmulationLoop.cs @@ -1,17 +1,14 @@ +namespace Spice86.Core.Emulator.VM; + using Spice86.Core.Emulator.CPU; -using Spice86.Core.Emulator.Devices.DirectMemoryAccess; +using Timer = Spice86.Core.Emulator.Devices.Timer.Timer; using Spice86.Core.Emulator.Errors; using Spice86.Core.Emulator.Function; - -namespace Spice86.Core.Emulator.VM; - using Spice86.Core.Emulator.CPU.CfgCpu; -using Spice86.Core.Emulator.Gdb; using Spice86.Shared.Interfaces; - +using Spice86.Shared.Diagnostics; using System.Diagnostics; -using Timer = Spice86.Core.Emulator.Devices.Timer.Timer; /// /// Runs the emulation loop in a dedicated thread.
@@ -24,8 +21,9 @@ public class EmulationLoop { private readonly State _cpuState; private readonly Timer _timer; private readonly EmulatorBreakpointsManager _emulatorBreakpointsManager; - private readonly Stopwatch _stopwatch; private readonly IPauseHandler _pauseHandler; + private readonly PerformanceMeasurer _performanceMeasurer; + private readonly Stopwatch _stopwatch; /// /// Whether the emulation is paused. @@ -50,6 +48,7 @@ public EmulationLoop(ILoggerService loggerService, FunctionHandler functionHandl _timer = timer; _emulatorBreakpointsManager = emulatorBreakpointsManager; _pauseHandler = pauseHandler; + _performanceMeasurer = new PerformanceMeasurer(); _stopwatch = new(); } @@ -87,14 +86,15 @@ private void StartRunLoop(FunctionHandler functionHandler) { } private void RunLoop() { - _stopwatch.Start(); if (_cpu is CfgCpu cfgCpu) { cfgCpu.SignalEntry(); } + _stopwatch.Start(); while (_cpuState.IsRunning) { _emulatorBreakpointsManager.CheckBreakPoint(); _pauseHandler.WaitIfPaused(); _cpu.ExecuteNext(); + _performanceMeasurer.UpdateValue(_cpuState.Cycles); _timer.Tick(); } _stopwatch.Stop(); @@ -103,13 +103,11 @@ private void RunLoop() { private void OutputPerfStats() { if (_loggerService.IsEnabled(Serilog.Events.LogEventLevel.Warning)) { - long elapsedTimeMilliSeconds = _stopwatch.ElapsedMilliseconds; - long cycles = _cpuState.Cycles; - long cyclesPerSeconds = 0; - if (elapsedTimeMilliSeconds > 0) { - cyclesPerSeconds = (_cpuState.Cycles * 1000) / elapsedTimeMilliSeconds; - } - _loggerService.Warning("Executed {Cycles} instructions in {ElapsedTimeMilliSeconds}ms. {CyclesPerSeconds} Instructions per seconds on average over run.", cycles, elapsedTimeMilliSeconds, cyclesPerSeconds); + long cyclesPerSeconds = _performanceMeasurer.AverageValuePerSecond; + long elapsedTimeInMilliseconds = _stopwatch.ElapsedMilliseconds; + _loggerService.Warning( + "Executed {Cycles} instructions in {ElapsedTimeMilliSeconds}ms. {CyclesPerSeconds} Instructions per seconds on average over run.", + _cpuState.Cycles, elapsedTimeInMilliseconds, cyclesPerSeconds); } } } \ No newline at end of file From a01929d8a9db2aa85cfbb62a5de5ff9cbd0beb2c Mon Sep 17 00:00:00 2001 From: Maximilien Noal Date: Sat, 9 Nov 2024 18:12:35 +0100 Subject: [PATCH 3/7] chore: Rename variable for code coherence Signed-off-by: Maximilien Noal --- src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs index d21029f1a..72107a59a 100644 --- a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs +++ b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs @@ -22,7 +22,7 @@ public class PerformanceMeasurer : IPerformanceMeasurer { /// public PerformanceMeasurer() => _lastTimeInMilliseconds = GetCurrentTime(); - private long _firstMeasureTimeInTicks = 0; + private long _firstMeasureTimeInMilliseconds = 0; private const int WindowSizeInSeconds = 30; @@ -32,7 +32,7 @@ public class PerformanceMeasurer : IPerformanceMeasurer { public void UpdateValue(long newMeasure) { long newTimeInMilliseconds = GetCurrentTime(); if (IsFirstMeasurement()) { - _firstMeasureTimeInTicks = newTimeInMilliseconds; + _firstMeasureTimeInMilliseconds = newTimeInMilliseconds; } else if (IsLastMeasurementExpired(newTimeInMilliseconds)) { ResetMetrics(newTimeInMilliseconds); } @@ -49,17 +49,17 @@ public void UpdateValue(long newMeasure) { } private bool IsFirstMeasurement() { - return _firstMeasureTimeInTicks == 0; + return _firstMeasureTimeInMilliseconds == 0; } private void ResetMetrics(long newTimeInMilliseconds) { - _firstMeasureTimeInTicks = newTimeInMilliseconds; + _firstMeasureTimeInMilliseconds = newTimeInMilliseconds; _sampledMetricsCount = 0; AverageValuePerSecond = 0; } private bool IsLastMeasurementExpired(long newTimeInMilliseconds) { - return (TimeSpan.FromTicks(newTimeInMilliseconds) - TimeSpan.FromTicks(_firstMeasureTimeInTicks)).TotalSeconds >= WindowSizeInSeconds; + return (TimeSpan.FromTicks(newTimeInMilliseconds) - TimeSpan.FromTicks(_firstMeasureTimeInMilliseconds)).TotalSeconds >= WindowSizeInSeconds; } private static long ApproxRollingAverage(long measureAverage, long valuePerSecond, long sampledMetricsCount) { From 744e7559d1f5dd813b269db386b846b58ed71364 Mon Sep 17 00:00:00 2001 From: Maximilien Noal Date: Sun, 10 Nov 2024 15:03:36 +0100 Subject: [PATCH 4/7] feat: Instructions Per Ms in Main Window Title Signed-off-by: Maximilien Noal --- src/Spice86/Spice86DependencyInjection.cs | 2 +- src/Spice86/ViewModels/MainWindowViewModel.cs | 18 +++++++++++++----- src/Spice86/ViewModels/PerformanceViewModel.cs | 4 ++++ 3 files changed, 18 insertions(+), 6 deletions(-) diff --git a/src/Spice86/Spice86DependencyInjection.cs b/src/Spice86/Spice86DependencyInjection.cs index 9113be7b3..38c54b9b0 100644 --- a/src/Spice86/Spice86DependencyInjection.cs +++ b/src/Spice86/Spice86DependencyInjection.cs @@ -160,7 +160,7 @@ public Spice86DependencyInjection(ILoggerService loggerService, Configuration co emulatorStateSerializer); mainWindowViewModel = new MainWindowViewModel( timer, uiThreadDispatcher, hostStorageProvider, textClipboard, configuration, - loggerService, pauseHandler); + loggerService, pauseHandler, performanceViewModel); } VgaCard vgaCard = new(mainWindowViewModel, vgaRenderer, loggerService); diff --git a/src/Spice86/ViewModels/MainWindowViewModel.cs b/src/Spice86/ViewModels/MainWindowViewModel.cs index 6f902f141..faa0abccf 100644 --- a/src/Spice86/ViewModels/MainWindowViewModel.cs +++ b/src/Spice86/ViewModels/MainWindowViewModel.cs @@ -33,6 +33,7 @@ public sealed partial class MainWindowViewModel : ViewModelWithErrorDialog, IGui private readonly AvaloniaKeyScanCodeConverter _avaloniaKeyScanCodeConverter; private readonly IPauseHandler _pauseHandler; private readonly ITimeMultiplier _pit; + private readonly PerformanceViewModel _performanceViewModel; [ObservableProperty] private bool _canUseInternalDebugger; @@ -59,8 +60,9 @@ public sealed partial class MainWindowViewModel : ViewModelWithErrorDialog, IGui public MainWindowViewModel( ITimeMultiplier pit, IUIDispatcher uiDispatcher, IHostStorageProvider hostStorageProvider, ITextClipboard textClipboard, - Configuration configuration, ILoggerService loggerService, IPauseHandler pauseHandler) : base(textClipboard) { + Configuration configuration, ILoggerService loggerService, IPauseHandler pauseHandler, PerformanceViewModel performanceViewModel) : base(textClipboard) { _pit = pit; + _performanceViewModel = performanceViewModel; _avaloniaKeyScanCodeConverter = new AvaloniaKeyScanCodeConverter(); Configuration = configuration; _loggerService = loggerService; @@ -71,8 +73,13 @@ public MainWindowViewModel( _pauseHandler.Resumed += OnResumed; TimeMultiplier = Configuration.TimeMultiplier; CanUseInternalDebugger = configuration.GdbPort is null; + DispatcherTimerStarter.StartNewDispatcherTimer(TimeSpan.FromSeconds(1.0 / 30.0), DispatcherPriority.MaxValue, (_, _) => UpdateCpuInstructionsPerMillisecondsInMainWindowTitle()); } - + + private void UpdateCpuInstructionsPerMillisecondsInMainWindowTitle() { + SetMainTitle(_performanceViewModel.InstructionsPerMillisecond); + } + [RelayCommand] public void SetLogLevelToSilent() => SetLogLevel("Silent"); @@ -228,14 +235,15 @@ public void SetResolution(int width, int height) { [RelayCommand(CanExecute = nameof(IsEmulatorRunning))] private async Task DumpEmulatorStateToFile() { - //TODO: refactor this await _hostStorageProvider.DumpEmulatorStateToFile().ConfigureAwait(false); } [RelayCommand(CanExecute = nameof(CanPause))] public void Pause() => _pauseHandler.RequestPause("Pause button pressed in main window"); - private void SetMainTitle() => MainTitle = $"{nameof(Spice86)} {Configuration.Exe}"; + private void SetMainTitle(double instructionsPerMillisecond) { + MainTitle = $"{nameof(Spice86)} {Configuration.Exe} - {instructionsPerMillisecond:N0} cycles/ms"; + } [ObservableProperty] private string? _mainTitle; @@ -303,7 +311,7 @@ internal void StartEmulator() { _ => "ASM code overrides: none." }; SetLogLevel(Configuration.SilencedLogs ? "Silent" : _loggerService.LogLevelSwitch.MinimumLevel.ToString()); - SetMainTitle(); + SetMainTitle(_performanceViewModel.InstructionsPerMillisecond); StartEmulatorThread(); } diff --git a/src/Spice86/ViewModels/PerformanceViewModel.cs b/src/Spice86/ViewModels/PerformanceViewModel.cs index 9524c8766..5fa54832a 100644 --- a/src/Spice86/ViewModels/PerformanceViewModel.cs +++ b/src/Spice86/ViewModels/PerformanceViewModel.cs @@ -37,8 +37,12 @@ private void UpdatePerformanceInfo(object? sender, EventArgs e) { InstructionsExecuted = _state.Cycles; _performanceMeasurer.UpdateValue(_state.Cycles); AverageInstructionsPerSecond = _performanceMeasurer.AverageValuePerSecond; + InstructionsPerMillisecond = _performanceMeasurer.ValuePerMillisecond; } + [ObservableProperty] + private double _instructionsPerMillisecond; + [ObservableProperty] private double _instructionsExecuted; } From bd8bb94e58d50309792cc4d385059b4ccb8fd14b Mon Sep 17 00:00:00 2001 From: Maximilien Noal Date: Sun, 10 Nov 2024 18:41:40 +0100 Subject: [PATCH 5/7] refactor: Faster IsLastMeasurementExpired Signed-off-by: Maximilien Noal --- src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs index 72107a59a..3b81d83de 100644 --- a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs +++ b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs @@ -58,9 +58,8 @@ private void ResetMetrics(long newTimeInMilliseconds) { AverageValuePerSecond = 0; } - private bool IsLastMeasurementExpired(long newTimeInMilliseconds) { - return (TimeSpan.FromTicks(newTimeInMilliseconds) - TimeSpan.FromTicks(_firstMeasureTimeInMilliseconds)).TotalSeconds >= WindowSizeInSeconds; - } + private bool IsLastMeasurementExpired(long newTimeInMilliseconds) => + newTimeInMilliseconds - _firstMeasureTimeInMilliseconds > WindowSizeInSeconds * 1000; private static long ApproxRollingAverage(long measureAverage, long valuePerSecond, long sampledMetricsCount) { measureAverage -= measureAverage / Math.Max(sampledMetricsCount, 1); From 432ff43dd0902ff1adc368eea4c9e36cdcb102a8 Mon Sep 17 00:00:00 2001 From: Maximilien Noal Date: Sun, 10 Nov 2024 19:57:11 +0100 Subject: [PATCH 6/7] Update src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs Co-authored-by: Joris van Eijden --- src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs index 3b81d83de..548d4291b 100644 --- a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs +++ b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs @@ -44,7 +44,7 @@ public void UpdateValue(long newMeasure) { _lastTimeInMilliseconds = newTimeInMilliseconds; long valueDelta = newMeasure - _measure; _measure = newMeasure; - ValuePerMillisecond = valueDelta / Math.Max(millisecondsDelta, 1); + ValuePerMillisecond = valueDelta / millisecondsDelta; AverageValuePerSecond = ApproxRollingAverage(AverageValuePerSecond, ValuePerSecond, _sampledMetricsCount++); } From 9c90726f9a624209bad332993df0962a61e643f9 Mon Sep 17 00:00:00 2001 From: Maximilien Noal Date: Sun, 10 Nov 2024 19:57:42 +0100 Subject: [PATCH 7/7] Update src/Spice86/ViewModels/MainWindowViewModel.cs Co-authored-by: Joris van Eijden --- src/Spice86/ViewModels/MainWindowViewModel.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Spice86/ViewModels/MainWindowViewModel.cs b/src/Spice86/ViewModels/MainWindowViewModel.cs index faa0abccf..28fc3fe51 100644 --- a/src/Spice86/ViewModels/MainWindowViewModel.cs +++ b/src/Spice86/ViewModels/MainWindowViewModel.cs @@ -242,7 +242,7 @@ private async Task DumpEmulatorStateToFile() { public void Pause() => _pauseHandler.RequestPause("Pause button pressed in main window"); private void SetMainTitle(double instructionsPerMillisecond) { - MainTitle = $"{nameof(Spice86)} {Configuration.Exe} - {instructionsPerMillisecond:N0} cycles/ms"; + MainTitle = $"{nameof(Spice86)} {Configuration.Exe} - cycles/ms: {instructionsPerMillisecond,7:N0}"; } [ObservableProperty]