Fix/performance measurer high samples (#926)

* fix: <1ms performance measurement support Signed-off-by: Maximilien Noal <noal.maximilien@gmail.com> * refactor: OutputPerfStats uses PerformanceMeasurer Signed-off-by: Maximilien Noal <noal.maximilien@gmail.com> * chore: Rename variable for code coherence Signed-off-by: Maximilien Noal <noal.maximilien@gmail.com> * feat: Instructions Per Ms in Main Window Title Signed-off-by: Maximilien Noal <noal.maximilien@gmail.com> * refactor: Faster IsLastMeasurementExpired Signed-off-by: Maximilien Noal <noal.maximilien@gmail.com> * Update src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs Co-authored-by: Joris van Eijden <joris.vaneijden@gmail.com> * Update src/Spice86/ViewModels/MainWindowViewModel.cs Co-authored-by: Joris van Eijden <joris.vaneijden@gmail.com> --------- Signed-off-by: Maximilien Noal <noal.maximilien@gmail.com> Co-authored-by: Joris van Eijden <joris.vaneijden@gmail.com>
OpenRakis · Nov 10, 2024 · a5a6dae · a5a6dae
1 parent 0c489b2
commit a5a6dae
Show file tree

Hide file tree

Showing 5 changed files with 55 additions and 30 deletions.
diff --git 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;
 
 /// <summary>
 /// Runs the emulation loop in a dedicated thread. <br/>
@@ -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;
 
     /// <summary>
     /// 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);
         }
     }
 }
diff --git a/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs b/src/Spice86.Shared/Diagnostics/PerformanceMeasurer.cs
@@ -22,7 +22,7 @@ public class PerformanceMeasurer : IPerformanceMeasurer {
     /// </summary>
     public PerformanceMeasurer() => _lastTimeInMilliseconds = GetCurrentTime();
 
-    private long _firstMeasureTimeInTicks = 0;
+    private long _firstMeasureTimeInMilliseconds = 0;
 
     private const int WindowSizeInSeconds = 30;
 
@@ -31,21 +31,36 @@ public class PerformanceMeasurer : IPerformanceMeasurer {
     /// <inheritdoc />
     public void UpdateValue(long newMeasure) {
         long newTimeInMilliseconds = GetCurrentTime();
-        if (_firstMeasureTimeInTicks == 0) {
-            _firstMeasureTimeInTicks = newTimeInMilliseconds;
-        } else if((TimeSpan.FromTicks(newTimeInMilliseconds) - TimeSpan.FromTicks(_firstMeasureTimeInTicks)).TotalSeconds >= WindowSizeInSeconds) {
-            _firstMeasureTimeInTicks = newTimeInMilliseconds;
-            _sampledMetricsCount = 0;
-            AverageValuePerSecond = 0;
+        if (IsFirstMeasurement()) {
+            _firstMeasureTimeInMilliseconds = newTimeInMilliseconds;
+        } else if (IsLastMeasurementExpired(newTimeInMilliseconds)) {
+            ResetMetrics(newTimeInMilliseconds);
         }
+
         long millisecondsDelta = newTimeInMilliseconds - _lastTimeInMilliseconds;
+        if (millisecondsDelta == 0) {
+            return;
+        }
         _lastTimeInMilliseconds = newTimeInMilliseconds;
         long valueDelta = newMeasure - _measure;
         _measure = newMeasure;
-        ValuePerMillisecond = valueDelta / Math.Max(millisecondsDelta, 1);
+        ValuePerMillisecond = valueDelta / millisecondsDelta;
         AverageValuePerSecond = ApproxRollingAverage(AverageValuePerSecond, ValuePerSecond, _sampledMetricsCount++);
     }
 
+    private bool IsFirstMeasurement() {
+        return _firstMeasureTimeInMilliseconds == 0;
+    }
+
+    private void ResetMetrics(long newTimeInMilliseconds) {
+        _firstMeasureTimeInMilliseconds = newTimeInMilliseconds;
+        _sampledMetricsCount = 0;
+        AverageValuePerSecond = 0;
+    }
+
+    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);
         measureAverage += valuePerSecond / Math.Max(sampledMetricsCount, 1);

diff --git 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
@@ -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} - cycles/ms: {instructionsPerMillisecond,7:N0}";
+    }
 
     [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
@@ -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;
 }