From 39d6a41f0dee6cc1fd585a8c35c332f30babad1b Mon Sep 17 00:00:00 2001 From: freezy Date: Sat, 7 Feb 2026 15:54:12 +0100 Subject: [PATCH 01/17] pinmame: Add better lifecycle handling. --- .../Editor/PinMamePlayModeLifecycle.cs | 163 +++++++ .../Editor/PinMamePlayModeLifecycle.cs.meta | 2 + .../Runtime/PinMameGamelogicEngine.cs | 430 ++++++++++++++---- 3 files changed, 502 insertions(+), 93 deletions(-) create mode 100644 VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs create mode 100644 VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs.meta diff --git a/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs new file mode 100644 index 0000000..ffd9831 --- /dev/null +++ b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs @@ -0,0 +1,163 @@ +// Visual Pinball Engine +// Copyright (C) 2021 freezy and VPE Team +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with this program. If not, see . + +#if UNITY_EDITOR + +using System; +using System.Diagnostics; +using NLog; +using UnityEditor; +using UnityEngine; +using Logger = NLog.Logger; + + +// ReSharper disable CheckNamespace + +namespace VisualPinball.Engine.PinMAME.Editor +{ + [InitializeOnLoad] + public static class PinMamePlayModeLifecycle + { + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + private const string LogPrefix = "[PinMAME-debug]"; + private static bool _stopping; + private static Stopwatch _stopwatch; + private const int StopTimeoutMs = 2000; + private static bool _warnedTimeout; + private static System.Threading.Tasks.Task _stopTask; + + private static bool IsDomainReloadDisabled() + { + // When Enter Play Mode Options are enabled, Unity can skip domain/scene reload. + // If domain reload is enabled (default), we must not run PinMAME stop on a background task + // that can outlive the managed domain during playmode transitions. + try { + if (!EditorSettings.enterPlayModeOptionsEnabled) { + return false; + } + return (EditorSettings.enterPlayModeOptions & EnterPlayModeOptions.DisableDomainReload) != 0; + } catch { + return false; + } + } + // Native stop is potentially blocking; we do it on a background thread. + + static PinMamePlayModeLifecycle() + { + EditorApplication.playModeStateChanged += OnPlayModeStateChanged; + EditorApplication.quitting += OnQuitting; + } + + private static void OnQuitting() + { + RequestStop("Editor quitting"); + } + + private static void OnPlayModeStateChanged(PlayModeStateChange state) + { + if (state == PlayModeStateChange.ExitingPlayMode) { + RequestStop("Exiting play mode"); + } + } + + private static void RequestStop(string reason) + { + try { + if (!PinMame.PinMame.IsRunning) { + return; + } + } catch { + return; + } + + if (_stopping) { + return; + } + + _stopping = true; + _warnedTimeout = false; + _stopwatch = Stopwatch.StartNew(); + Logger.Warn($"{LogPrefix} [PinMAME] Stop requested ({reason})"); + + // Stop sim thread(s) first to avoid starving the PinMAME emulation thread. + try { + var sims = UnityEngine.Object.FindObjectsByType(FindObjectsSortMode.None); + for (var i = 0; i < sims.Length; i++) { + sims[i].StopSimulation(); + } + } catch { } + + // Prefer stopping via the active component(s) so they can unsubscribe callbacks first. + try { + var engines = UnityEngine.Object.FindObjectsByType(FindObjectsSortMode.None); + for (var i = 0; i < engines.Length; i++) { + engines[i].StopForPlayModeExit(); + } + } catch { } + + EditorApplication.update -= Update; + EditorApplication.update += Update; + + // Stop PinMAME now. + // - With Domain Reload enabled: stop synchronously while the domain is still stable. + // - With Domain Reload disabled: stop on a background task to keep the editor responsive. + if (IsDomainReloadDisabled()) { + _stopTask = System.Threading.Tasks.Task.Run(() => { + try { + PinMame.PinMame.StopRunningGame(); + } catch (Exception e) { + Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame failed while exiting play mode."); + } + }); + } else { + try { + PinMame.PinMame.StopRunningGame(); + _stopTask = System.Threading.Tasks.Task.CompletedTask; + } catch (Exception e) { + Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame failed while exiting play mode."); + _stopTask = System.Threading.Tasks.Task.CompletedTask; + } + } + } + + private static void Update() + { + bool running; + try { + running = PinMame.PinMame.IsRunning; + } catch { + running = false; + } + + var stopDone = _stopTask == null || _stopTask.IsCompleted; + if (!running && stopDone) { + EditorApplication.update -= Update; + _stopping = false; + _warnedTimeout = false; + _stopTask = null; + Logger.Warn($"{LogPrefix} [PinMAME] Stopped (editor)"); + return; + } + + if (!_warnedTimeout && _stopwatch != null && _stopwatch.ElapsedMilliseconds > StopTimeoutMs) { + _warnedTimeout = true; + Logger.Warn($"{LogPrefix} [PinMAME] Still running after stop timeout (editor)"); + } + } + } +} + +#endif diff --git a/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs.meta b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs.meta new file mode 100644 index 0000000..fae26a5 --- /dev/null +++ b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs.meta @@ -0,0 +1,2 @@ +fileFormatVersion: 2 +guid: e233609de2ea2164b89f4688b5597e55 \ No newline at end of file diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 6d57986..f286c16 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -18,12 +18,13 @@ // ReSharper disable InconsistentNaming // ReSharper disable PossibleNullReferenceException -using System; -using System.Collections.Generic; -using System.Linq; -using System.Runtime.InteropServices; -using System.Threading; -using System.Threading.Tasks; +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Runtime.InteropServices; +using System.Threading; +using System.Threading.Tasks; using NLog; using PinMame; using UnityEngine; @@ -38,9 +39,10 @@ namespace VisualPinball.Engine.PinMAME [DisallowMultipleComponent] [RequireComponent(typeof(AudioSource))] [AddComponentMenu("Pinball/Gamelogic Engine/PinMAME")] - public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine - { - public string Name { get; } = "PinMAME Gamelogic Engine"; + public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine + { + public string Name { get; } = "PinMAME Gamelogic Engine"; + private const string LogPrefix = "[PinMAME-debug]"; public const string DmdPrefix = "dmd"; public const string SegDispPrefix = "display"; @@ -128,8 +130,8 @@ public GamelogicEngineLamp[] RequestedLamps { private Dictionary _frameBuffer = new(); private Dictionary> _dmdLevels = new(); - private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); - private static readonly Color Tint = new(1, 0.18f, 0); + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + private static readonly Color Tint = new(1, 0.18f, 0); private readonly Queue _dispatchQueue = new(); private readonly Queue _audioQueue = new(); @@ -150,10 +152,19 @@ public GamelogicEngineLamp[] RequestedLamps { private Dictionary _registeredMechs = new(); private HashSet _mechSwitches = new(); - private bool _toggleSpeed = false; - private Keyboard _keyboard; - - #endregion + private bool _toggleSpeed = false; + private Keyboard _keyboard; + + private static readonly SemaphoreSlim PinMameStartStopGate = new SemaphoreSlim(1, 1); + private int _onInitCalled; + private int _stopRequested; + private int _playModeExitHandled; + private int _loggedFirstLampUpdate; + private int _loggedNoLampUpdates; + private long _gameStartedMs; + private const int StopTimeoutMs = 10000; + + #endregion #region Lifecycle @@ -171,11 +182,20 @@ private void Start() _lastAudioFrameOffset = 0; } - private void Update() - { - if (_pinMame == null || !_isRunning) { - return; - } + private void Update() + { + if (_pinMame == null || !_isRunning) { + return; + } + + // Detect cases where the game claims to be started but never produces outputs. + if (Interlocked.CompareExchange(ref _loggedFirstLampUpdate, 0, 0) == 0 && _gameStartedMs != 0) { + var nowMs = DateTimeOffset.Now.ToUnixTimeMilliseconds(); + var elapsedMs = nowMs - _gameStartedMs; + if (elapsedMs > 2000 && Interlocked.Exchange(ref _loggedNoLampUpdates, 1) == 0) { + Logger.Warn($"{LogPrefix} [PinMAME] No lamp deltas after {elapsedMs}ms (NativeIsRunning={PinMame.PinMame.IsRunning}, RunState={PinMame.PinMame.RunState})"); + } + } lock (_dispatchQueue) { while (_dispatchQueue.Count > 0) { @@ -183,14 +203,17 @@ private void Update() } } - // lamps - _pinMame.GetChangedLamps(_changedLamps); - foreach (var changedLamp in _changedLamps) { - if (_pinMameIdToLampIdMapping.ContainsKey(changedLamp.Id)) { - //Logger.Info($"[PinMAME] <= lamp {changedLamp.Id}: {changedLamp.Value}"); - OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedLamp.Id]].Id, changedLamp.Value)); - } - } + // lamps + _pinMame.GetChangedLamps(_changedLamps); + if (_changedLamps.Count > 0 && Interlocked.Exchange(ref _loggedFirstLampUpdate, 1) == 0) { + Logger.Info($"{LogPrefix} [PinMAME] First lamp batch: count={_changedLamps.Count}"); + } + foreach (var changedLamp in _changedLamps) { + if (_pinMameIdToLampIdMapping.ContainsKey(changedLamp.Id)) { + //Logger.Info($"[PinMAME] <= lamp {changedLamp.Id}: {changedLamp.Value}"); + OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedLamp.Id]].Id, changedLamp.Value)); + } + } // gi _pinMame.GetChangedGIs(_changedGIs); @@ -210,14 +233,18 @@ private void Update() // } } - private void OnDestroy() - { - if (_pinMame != null) { - _pinMame.StopGame(); - _pinMame.OnGameStarted -= OnGameStarted; - _pinMame.OnGameEnded -= OnGameEnded; - _pinMame.OnDisplayAvailable -= OnDisplayRequested; - _pinMame.OnDisplayUpdated -= OnDisplayUpdated; + private void OnDestroy() + { + #if UNITY_EDITOR + StopForPlayModeExit(); + #else + RequestStopGame("OnDestroy"); + #endif + if (_pinMame != null) { + _pinMame.OnGameStarted -= OnGameStarted; + _pinMame.OnGameEnded -= OnGameEnded; + _pinMame.OnDisplayAvailable -= OnDisplayRequested; + _pinMame.OnDisplayUpdated -= OnDisplayUpdated; if (!DisableAudio) { @@ -229,16 +256,140 @@ private void OnDestroy() _pinMame.OnMechUpdated -= OnMechUpdated; _pinMame.OnSolenoidUpdated -= OnSolenoidUpdated; _pinMame.IsKeyPressed -= IsKeyPressed; - } - _frameBuffer.Clear(); - _dmdLevels.Clear(); - } + } + _frameBuffer.Clear(); + _dmdLevels.Clear(); + } + + private void OnDisable() + { + // In some Unity playmode/domain-reload configurations, OnDestroy isn't reliably called. + // Best-effort shutdown to avoid leaving a game running across sessions. + #if UNITY_EDITOR + StopForPlayModeExit(); + #else + RequestStopGame("OnDisable"); + #endif + } + + private void OnApplicationQuit() + { + #if UNITY_EDITOR + StopForPlayModeExit(); + #else + RequestStopGame("OnApplicationQuit"); + #endif + } + + public void StopForPlayModeExit() + { + if (Interlocked.Exchange(ref _playModeExitHandled, 1) != 0) { + return; + } + + // Editor-only: called from playmode lifecycle hook. + // Do not call into native Stop() here (it blocks); the editor hook will stop PinMAME + // after we unsubscribe managed callbacks. + Interlocked.Exchange(ref _stopRequested, 1); + // Stop polling outputs immediately to avoid concurrent calls into pinmame.dll + // while a stop is in progress (pinmame APIs are not guaranteed thread-safe). + _isRunning = false; + Logger.Info($"{LogPrefix} [PinMAME] StopForPlayModeExit: unsubscribing callbacks ({name}#{GetInstanceID()})"); + try { + if (_pinMame == null) { + return; + } + + _pinMame.OnGameStarted -= OnGameStarted; + _pinMame.OnGameEnded -= OnGameEnded; + _pinMame.OnDisplayAvailable -= OnDisplayRequested; + _pinMame.OnDisplayUpdated -= OnDisplayUpdated; + _pinMame.OnMechAvailable -= OnMechAvailable; + _pinMame.OnMechUpdated -= OnMechUpdated; + _pinMame.OnSolenoidUpdated -= OnSolenoidUpdated; + _pinMame.IsKeyPressed -= IsKeyPressed; + _pinMame.OnAudioAvailable -= OnAudioAvailable; + _pinMame.OnAudioUpdated -= OnAudioUpdated; + } + catch { } + } + + private void RequestStopGame(string reason) + { + #if UNITY_EDITOR + // In the editor, playmode shutdown is handled by StopForPlayModeExit + editor lifecycle hook. + // Calling native Stop() from here can race and destabilize the editor. + StopForPlayModeExit(); + return; + #endif + + try { + if (Interlocked.Exchange(ref _stopRequested, 1) != 0) { + return; + } + _isRunning = false; + + if (!PinMame.PinMame.IsRunning) { + return; + } + + } catch (Exception e) { + Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame ({reason}) failed."); + return; + } + + // Avoid racing StartGame on re-entering play mode. + if (!PinMameStartStopGate.Wait(0)) { + Logger.Warn($"{LogPrefix} [PinMAME] StopGame ({reason}) skipped: start/stop already in progress."); + return; + } + + // Never block the Unity main thread during playmode exit. + // PinMAME shutdown is best-effort here; OnInit() and the editor lifecycle hook + // will recover/ensure shutdown before starting a new ROM. + Logger.Warn($"{LogPrefix} [PinMAME] StopGame ({reason}) requested. RunningGame={_pinMame?.RunningGame}"); + + try { + if (_pinMame != null) { + // Unsubscribe first to keep the native thread from doing work in managed callbacks during shutdown. + _pinMame.OnGameStarted -= OnGameStarted; + _pinMame.OnGameEnded -= OnGameEnded; + _pinMame.OnDisplayAvailable -= OnDisplayRequested; + _pinMame.OnDisplayUpdated -= OnDisplayUpdated; + _pinMame.OnMechAvailable -= OnMechAvailable; + _pinMame.OnMechUpdated -= OnMechUpdated; + _pinMame.OnSolenoidUpdated -= OnSolenoidUpdated; + _pinMame.IsKeyPressed -= IsKeyPressed; + _pinMame.OnAudioAvailable -= OnAudioAvailable; + _pinMame.OnAudioUpdated -= OnAudioUpdated; + } + } + catch (Exception e) { + Logger.Warn(e, $"[PinMAME] Unsubscribe during shutdown ({reason}) failed."); + } + + // PinmameStop may block (joins the emulation thread). Never do that on the Unity main thread. + System.Threading.Tasks.Task.Run(() => { + try { + _pinMame?.StopGame(); + } catch (Exception e) { + Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame ({reason}) failed."); + } finally { + PinMameStartStopGate.Release(); + } + }); + } - public Task OnInit(Player player, TableApi tableApi, BallManager ballManager, CancellationToken ct) - { - string vpmPath = null; - _ballManager = ballManager; - _playfieldComponent = GetComponentInChildren(); + public async Task OnInit(Player player, TableApi tableApi, BallManager ballManager, CancellationToken ct) + { + if (Interlocked.Exchange(ref _onInitCalled, 1) != 0) { + Logger.Warn($"[PinMAME] OnInit called more than once on {name}, ignoring."); + return; + } + + string vpmPath = null; + _ballManager = ballManager; + _playfieldComponent = GetComponentInChildren(); #if (UNITY_IOS || UNITY_ANDROID) && !UNITY_EDITOR vpmPath = Path.Combine(Application.persistentDataPath, "pinmame"); @@ -262,55 +413,145 @@ public Task OnInit(Player player, TableApi tableApi, BallManager ballManager, Ca File.WriteAllBytes(Path.Combine(vpmPath, "roms", $"{romId}.zip"), data); #endif - Logger.Info($"New PinMAME instance at {(double)AudioSettings.outputSampleRate / 1000}kHz"); - - // ReSharper disable once ExpressionIsAlwaysNull - _pinMame = PinMame.PinMame.Instance(PinMameAudioFormat.AudioFormatFloat, AudioSettings.outputSampleRate, vpmPath); - - _pinMame.SetHandleKeyboard(false); - _pinMame.SetHandleMechanics(DisableMechs ? 0 : 0xFF); - - _pinMame.OnGameStarted += OnGameStarted; - _pinMame.OnGameEnded += OnGameEnded; - _pinMame.OnDisplayAvailable += OnDisplayRequested; - _pinMame.OnDisplayUpdated += OnDisplayUpdated; - - if (!DisableAudio) { - _pinMame.OnAudioAvailable += OnAudioAvailable; - _pinMame.OnAudioUpdated += OnAudioUpdated; - } - - _pinMame.OnMechAvailable += OnMechAvailable; - _pinMame.OnMechUpdated += OnMechUpdated; - _pinMame.OnSolenoidUpdated += OnSolenoidUpdated; - _pinMame.IsKeyPressed += IsKeyPressed; - - _player = player; - - _solenoidsEnabled = SolenoidDelay == 0; - - try { - _pinMame.StartGame(romId); - - } catch (Exception e) { - Logger.Error(e); - } - - return Task.CompletedTask; - } + await PinMameStartStopGate.WaitAsync(ct); + try { + Logger.Info($"{LogPrefix} [PinMAME] OnInit {name}: romId={romId}, sampleRate={AudioSettings.outputSampleRate}"); + + #if UNITY_EDITOR + // With Domain Reload disabled, PinMAME (native + managed singleton) persists across play sessions. + // Even when RunState reports 0, the native game thread might still exist and need joining. + // Calling Stop here is a cheap no-op if nothing is running, and a critical cleanup if something is. + var preStopState = PinMame.PinMame.RunState; + var preStopSw = Stopwatch.StartNew(); + try { + PinMame.PinMame.StopRunningGame(); + } catch (Exception e) { + Logger.Warn(e, $"{LogPrefix} [PinMAME] Pre-start StopRunningGame failed."); + } + // Wait for a clean stopped state before starting a new ROM. + var preStopWaitSw = Stopwatch.StartNew(); + while (PinMame.PinMame.RunState != 0 && preStopWaitSw.ElapsedMilliseconds < StopTimeoutMs) { + await Task.Delay(10, ct); + } + Logger.Info($"{LogPrefix} [PinMAME] Editor pre-stop: initialRunState={preStopState}, stopCallMs={preStopSw.ElapsedMilliseconds}, waitMs={preStopWaitSw.ElapsedMilliseconds}, finalRunState={PinMame.PinMame.RunState}"); + if (PinMame.PinMame.RunState != 0) { + Logger.Error($"{LogPrefix} [PinMAME] Cannot start ROM; PinMAME did not reach stopped state (RunState={PinMame.PinMame.RunState})."); + return; + } + + // Force a fresh managed wrapper each init. This avoids cross-session managed state + // (callbacks, buffers) bleeding into the next play run when the host keeps assemblies loaded. + PinMame.PinMame.ResetInstance(); + #endif + + // If we exited play mode recently, a background stop may still be running. + // Starting a new ROM while the previous stop is cleaning up can lead to a "started" + // state with no progress/output on the next run. + var wasRunning = PinMame.PinMame.IsRunning; + var wasStopping = PinMame.PinMame.IsStopInProgress; + var swStop = Stopwatch.StartNew(); + while ((PinMame.PinMame.IsStopInProgress || PinMame.PinMame.IsRunning) && swStop.ElapsedMilliseconds < StopTimeoutMs) { + await Task.Delay(10, ct); + } + Logger.Info($"{LogPrefix} [PinMAME] Pre-start wait: {swStop.ElapsedMilliseconds}ms (WasRunning={wasRunning}, WasStopping={wasStopping}, IsRunning={PinMame.PinMame.IsRunning}, RunState={PinMame.PinMame.RunState}, StopInProgress={PinMame.PinMame.IsStopInProgress})"); + + // ReSharper disable once ExpressionIsAlwaysNull + _pinMame = PinMame.PinMame.Instance(PinMameAudioFormat.AudioFormatFloat, AudioSettings.outputSampleRate, vpmPath); + // Re-apply config each init (important when Domain Reload is disabled). + _pinMame.ApplyConfig(); + + // Prevent duplicate subscriptions if OnInit is invoked more than once. + _pinMame.OnGameStarted -= OnGameStarted; + _pinMame.OnGameEnded -= OnGameEnded; + _pinMame.OnDisplayAvailable -= OnDisplayRequested; + _pinMame.OnDisplayUpdated -= OnDisplayUpdated; + _pinMame.OnMechAvailable -= OnMechAvailable; + _pinMame.OnMechUpdated -= OnMechUpdated; + _pinMame.OnSolenoidUpdated -= OnSolenoidUpdated; + _pinMame.IsKeyPressed -= IsKeyPressed; + _pinMame.OnAudioAvailable -= OnAudioAvailable; + _pinMame.OnAudioUpdated -= OnAudioUpdated; + + // If domain reload is disabled or a previous table didn't shut down cleanly, + // PinMAME can still be running here. + if (PinMame.PinMame.IsRunning) { + Logger.Warn($"{LogPrefix} [PinMAME] A game is already running (RunningGame={_pinMame.RunningGame}); stopping it before starting a new one."); + try { + _pinMame.StopGame(); + } + catch (Exception e) { + Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame failed while recovering from already running state."); + } + + var sw = Stopwatch.StartNew(); + while (PinMame.PinMame.IsRunning && sw.ElapsedMilliseconds < StopTimeoutMs) { + await Task.Delay(10, ct); + } + if (PinMame.PinMame.IsRunning) { + Logger.Warn($"{LogPrefix} [PinMAME] Failed to stop running game within timeout; attempting StartGame anyway."); + } + } + + _pinMame.SetHandleKeyboard(false); + _pinMame.SetHandleMechanics(DisableMechs ? 0 : 0xFF); + + _pinMame.OnGameStarted += OnGameStarted; + _pinMame.OnGameEnded += OnGameEnded; + _pinMame.OnDisplayAvailable += OnDisplayRequested; + _pinMame.OnDisplayUpdated += OnDisplayUpdated; + + if (!DisableAudio) { + _pinMame.OnAudioAvailable += OnAudioAvailable; + _pinMame.OnAudioUpdated += OnAudioUpdated; + } + + _pinMame.OnMechAvailable += OnMechAvailable; + _pinMame.OnMechUpdated += OnMechUpdated; + _pinMame.OnSolenoidUpdated += OnSolenoidUpdated; + _pinMame.IsKeyPressed += IsKeyPressed; + + _player = player; + _solenoidsEnabled = SolenoidDelay == 0; + + try { + _pinMame.StartGame(romId); + } + catch (InvalidOperationException e) when (e.Message != null && e.Message.Contains("status=GAME_ALREADY_RUNNING")) + { + Logger.Warn(e, $"{LogPrefix} [PinMAME] StartGame reported already running; stopping and retrying once."); + try { + _pinMame.StopGame(); + await Task.Delay(100, ct); + _pinMame.StartGame(romId); + } + catch (Exception retryEx) { + Logger.Error(retryEx); + } + } + catch (Exception e) { + Logger.Error(e); + } + + } finally { + PinMameStartStopGate.Release(); + } + } public void ToggleSpeed() { - Logger.Info($"[PinMAME] Toggle speed."); + Logger.Info($"{LogPrefix} [PinMAME] Toggle speed."); _pinMame.SetHandleKeyboard(true); _toggleSpeed = true; } - private void OnGameStarted() - { - Logger.Info($"[PinMAME] Game started."); - _isRunning = true; + private void OnGameStarted() + { + Logger.Info($"{LogPrefix} [PinMAME] Game started."); + _isRunning = true; + _gameStartedMs = DateTimeOffset.Now.ToUnixTimeMilliseconds(); + _loggedFirstLampUpdate = 0; + _loggedNoLampUpdates = 0; _solenoidDelayStart = DateTimeOffset.Now.ToUnixTimeMilliseconds(); @@ -320,7 +561,7 @@ private void OnGameStarted() } catch(Exception e) { - Logger.Error($"[PinMAME] OnGameStarted: {e.Message}"); + Logger.Error($"{LogPrefix} [PinMAME] OnGameStarted: {e.Message}"); } lock (_dispatchQueue) { @@ -328,11 +569,14 @@ private void OnGameStarted() } } - private void OnGameEnded() - { - Logger.Info($"[PinMAME] Game ended."); - _isRunning = false; - } + private void OnGameEnded() + { + // Native can report ended more than once during teardown; keep it idempotent. + if (_isRunning) { + Logger.Info($"{LogPrefix} [PinMAME] Game ended."); + } + _isRunning = false; + } private void UpdateCaches() { @@ -727,7 +971,7 @@ public LampState GetLamp(string id) public void SendInitialSwitches() { var switches = _player.SwitchStatuses; - Logger.Info("[PinMAME] Sending initial switch statuses..."); + Logger.Info($"{LogPrefix} [PinMAME] Sending initial switch statuses..."); foreach (var id in switches.Keys) { var isClosed = switches[id].IsSwitchClosed; // skip open switches From 233e21c3e295b1d5942138f3fe316363f3edf7b6 Mon Sep 17 00:00:00 2001 From: freezy Date: Sat, 7 Feb 2026 16:17:59 +0100 Subject: [PATCH 02/17] chore: Clean up debug code. --- .../Editor/PinMamePlayModeLifecycle.cs | 3 ++- .../Runtime/PinMameGamelogicEngine.cs | 25 +++---------------- 2 files changed, 6 insertions(+), 22 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs index ffd9831..c413f3d 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs @@ -92,7 +92,8 @@ private static void RequestStop(string reason) _stopwatch = Stopwatch.StartNew(); Logger.Warn($"{LogPrefix} [PinMAME] Stop requested ({reason})"); - // Stop sim thread(s) first to avoid starving the PinMAME emulation thread. + // Stop sim thread(s) first. This reduces the chance of other high-frequency code paths + // continuing to call into PinMAME while we are stopping it. try { var sims = UnityEngine.Object.FindObjectsByType(FindObjectsSortMode.None); for (var i = 0; i < sims.Length; i++) { diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index f286c16..d4ab5a7 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -159,9 +159,7 @@ public GamelogicEngineLamp[] RequestedLamps { private int _onInitCalled; private int _stopRequested; private int _playModeExitHandled; - private int _loggedFirstLampUpdate; - private int _loggedNoLampUpdates; - private long _gameStartedMs; + // (removed) lamp delta debug tracking private const int StopTimeoutMs = 10000; #endregion @@ -188,16 +186,7 @@ private void Update() return; } - // Detect cases where the game claims to be started but never produces outputs. - if (Interlocked.CompareExchange(ref _loggedFirstLampUpdate, 0, 0) == 0 && _gameStartedMs != 0) { - var nowMs = DateTimeOffset.Now.ToUnixTimeMilliseconds(); - var elapsedMs = nowMs - _gameStartedMs; - if (elapsedMs > 2000 && Interlocked.Exchange(ref _loggedNoLampUpdates, 1) == 0) { - Logger.Warn($"{LogPrefix} [PinMAME] No lamp deltas after {elapsedMs}ms (NativeIsRunning={PinMame.PinMame.IsRunning}, RunState={PinMame.PinMame.RunState})"); - } - } - - lock (_dispatchQueue) { + lock (_dispatchQueue) { while (_dispatchQueue.Count > 0) { _dispatchQueue.Dequeue().Invoke(); } @@ -205,9 +194,6 @@ private void Update() // lamps _pinMame.GetChangedLamps(_changedLamps); - if (_changedLamps.Count > 0 && Interlocked.Exchange(ref _loggedFirstLampUpdate, 1) == 0) { - Logger.Info($"{LogPrefix} [PinMAME] First lamp batch: count={_changedLamps.Count}"); - } foreach (var changedLamp in _changedLamps) { if (_pinMameIdToLampIdMapping.ContainsKey(changedLamp.Id)) { //Logger.Info($"[PinMAME] <= lamp {changedLamp.Id}: {changedLamp.Value}"); @@ -549,11 +535,8 @@ private void OnGameStarted() { Logger.Info($"{LogPrefix} [PinMAME] Game started."); _isRunning = true; - _gameStartedMs = DateTimeOffset.Now.ToUnixTimeMilliseconds(); - _loggedFirstLampUpdate = 0; - _loggedNoLampUpdates = 0; - - _solenoidDelayStart = DateTimeOffset.Now.ToUnixTimeMilliseconds(); + + _solenoidDelayStart = DateTimeOffset.Now.ToUnixTimeMilliseconds(); try { SendInitialSwitches(); From 9efbcfa8b2b847cf092e1deda710d35460524267 Mon Sep 17 00:00:00 2001 From: freezy Date: Sat, 7 Feb 2026 16:20:00 +0100 Subject: [PATCH 03/17] deps: Bump pinmame-dotnet to v1.0.1. --- .../VisualPinball.Engine.PinMAME.csproj | 54 +++++++++---------- 1 file changed, 27 insertions(+), 27 deletions(-) diff --git a/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj b/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj index a4da2fd..bdd27f9 100644 --- a/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj +++ b/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj @@ -5,7 +5,7 @@ false true 9.0 - 1.0.0 + 1.0.1 3.7.0-beta1 @@ -23,35 +23,35 @@ ..\..\VisualPinball.Engine\VisualPinball.Engine\.bin\Release\netstandard2.1\VisualPinball.Engine.dll --> - - - - + + + + - - - - - - - - - ..\VisualPinball.Engine.PinMAME.Unity\Plugins\$(RuntimeIdentifier)\pinmame.dll - - - - - - - - - - - - + + + + + + + + + ..\VisualPinball.Engine.PinMAME.Unity\Plugins\$(RuntimeIdentifier)\pinmame.dll + + + + + + + + + + + + From 833870ca6cf904a369097674566254e36b4d43ca Mon Sep 17 00:00:00 2001 From: freezy Date: Mon, 16 Feb 2026 00:13:31 +0100 Subject: [PATCH 04/17] fix: PinMAME threading issue. --- .../Editor/PinMamePlayModeLifecycle.cs | 61 +++------ .../Runtime/PinMameGamelogicEngine.cs | 125 +++++++++--------- 2 files changed, 85 insertions(+), 101 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs index c413f3d..006db23 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Editor/PinMamePlayModeLifecycle.cs @@ -32,28 +32,13 @@ namespace VisualPinball.Engine.PinMAME.Editor public static class PinMamePlayModeLifecycle { private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); - private const string LogPrefix = "[PinMAME-debug]"; private static bool _stopping; private static Stopwatch _stopwatch; private const int StopTimeoutMs = 2000; private static bool _warnedTimeout; private static System.Threading.Tasks.Task _stopTask; - private static bool IsDomainReloadDisabled() - { - // When Enter Play Mode Options are enabled, Unity can skip domain/scene reload. - // If domain reload is enabled (default), we must not run PinMAME stop on a background task - // that can outlive the managed domain during playmode transitions. - try { - if (!EditorSettings.enterPlayModeOptionsEnabled) { - return false; - } - return (EditorSettings.enterPlayModeOptions & EnterPlayModeOptions.DisableDomainReload) != 0; - } catch { - return false; - } - } - // Native stop is potentially blocking; we do it on a background thread. + // (removed) Domain reload branching; stop is synchronous for determinism. static PinMamePlayModeLifecycle() { @@ -75,8 +60,10 @@ private static void OnPlayModeStateChanged(PlayModeStateChange state) private static void RequestStop(string reason) { + int runState; try { - if (!PinMame.PinMame.IsRunning) { + runState = PinMame.PinMame.RunState; + if (runState == 0) { return; } } catch { @@ -90,7 +77,7 @@ private static void RequestStop(string reason) _stopping = true; _warnedTimeout = false; _stopwatch = Stopwatch.StartNew(); - Logger.Warn($"{LogPrefix} [PinMAME] Stop requested ({reason})"); + Logger.Info($"[PinMAME] Stop requested ({reason}), RunState={runState}"); // Stop sim thread(s) first. This reduces the chance of other high-frequency code paths // continuing to call into PinMAME while we are stopping it. @@ -113,35 +100,27 @@ private static void RequestStop(string reason) EditorApplication.update += Update; // Stop PinMAME now. - // - With Domain Reload enabled: stop synchronously while the domain is still stable. - // - With Domain Reload disabled: stop on a background task to keep the editor responsive. - if (IsDomainReloadDisabled()) { - _stopTask = System.Threading.Tasks.Task.Run(() => { - try { - PinMame.PinMame.StopRunningGame(); - } catch (Exception e) { - Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame failed while exiting play mode."); - } - }); - } else { - try { - PinMame.PinMame.StopRunningGame(); - _stopTask = System.Threading.Tasks.Task.CompletedTask; - } catch (Exception e) { - Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame failed while exiting play mode."); - _stopTask = System.Threading.Tasks.Task.CompletedTask; - } + // With Domain Reload disabled, background stop can overlap the next play session. + // Now that other hot loops are tamed, prefer a synchronous stop for determinism. + try { + var sw = Stopwatch.StartNew(); + PinMame.PinMame.StopRunningGame(); + Logger.Info($"[PinMAME] Stop call returned after {sw.ElapsedMilliseconds}ms"); + } catch (Exception e) { + Logger.Warn(e, "[PinMAME] StopGame failed while exiting play mode."); } + _stopTask = System.Threading.Tasks.Task.CompletedTask; } private static void Update() { - bool running; + int runState; try { - running = PinMame.PinMame.IsRunning; + runState = PinMame.PinMame.RunState; } catch { - running = false; + runState = 0; } + var running = runState != 0; var stopDone = _stopTask == null || _stopTask.IsCompleted; if (!running && stopDone) { @@ -149,13 +128,13 @@ private static void Update() _stopping = false; _warnedTimeout = false; _stopTask = null; - Logger.Warn($"{LogPrefix} [PinMAME] Stopped (editor)"); + Logger.Info("[PinMAME] Stopped (editor)"); return; } if (!_warnedTimeout && _stopwatch != null && _stopwatch.ElapsedMilliseconds > StopTimeoutMs) { _warnedTimeout = true; - Logger.Warn($"{LogPrefix} [PinMAME] Still running after stop timeout (editor)"); + Logger.Warn($"[PinMAME] Still running after stop timeout (editor), RunState={runState}"); } } } diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index d4ab5a7..a7e0bf9 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -42,7 +42,6 @@ namespace VisualPinball.Engine.PinMAME public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine { public string Name { get; } = "PinMAME Gamelogic Engine"; - private const string LogPrefix = "[PinMAME-debug]"; public const string DmdPrefix = "dmd"; public const string SegDispPrefix = "display"; @@ -166,11 +165,11 @@ public GamelogicEngineLamp[] RequestedLamps { #region Lifecycle - private void Awake() - { - Logger.Info("Project audio sample rate: " + AudioSettings.outputSampleRate); - _keyboard = Keyboard.current; - } + private void Awake() + { + Logger.Info("Project audio sample rate: " + AudioSettings.outputSampleRate); + _keyboard = Keyboard.current; + } private void Start() { @@ -202,17 +201,17 @@ private void Update() } // gi - _pinMame.GetChangedGIs(_changedGIs); - foreach (var changedGi in _changedGIs) { - if (_pinMameIdToLampIdMapping.ContainsKey(changedGi.Id)) { - //Logger.Info($"[PinMAME] <= gi {changedGi.Id}: {changedGi.Value}"); - OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedGi.Id]].Id, changedGi.Value, LampSource.GI)); - } /*else { + _pinMame.GetChangedGIs(_changedGIs); + foreach (var changedGi in _changedGIs) { + if (_pinMameIdToLampIdMapping.ContainsKey(changedGi.Id)) { + //Logger.Info($"[PinMAME] <= gi {changedGi.Id}: {changedGi.Value}"); + OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedGi.Id]].Id, changedGi.Value, LampSource.GI)); + } /*else { Logger.Info($"No GI {changedGi.Id} found."); }*/ } - // if (_keyboard != null && _keyboard.cKey.wasPressedThisFrame) + // if (_keyboard != null && _keyboard.cKey.wasPressedThisFrame) // { // OnCoilChanged.Invoke(this, new CoilEventArgs("28", true)); // OnCoilChanged.Invoke(this, new CoilEventArgs("28", false)); @@ -280,7 +279,7 @@ public void StopForPlayModeExit() // Stop polling outputs immediately to avoid concurrent calls into pinmame.dll // while a stop is in progress (pinmame APIs are not guaranteed thread-safe). _isRunning = false; - Logger.Info($"{LogPrefix} [PinMAME] StopForPlayModeExit: unsubscribing callbacks ({name}#{GetInstanceID()})"); + Logger.Info($"[PinMAME] StopForPlayModeExit: unsubscribing callbacks ({name}#{GetInstanceID()})"); try { if (_pinMame == null) { return; @@ -320,20 +319,20 @@ private void RequestStopGame(string reason) } } catch (Exception e) { - Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame ({reason}) failed."); + Logger.Warn(e, $"[PinMAME] StopGame ({reason}) failed."); return; } // Avoid racing StartGame on re-entering play mode. if (!PinMameStartStopGate.Wait(0)) { - Logger.Warn($"{LogPrefix} [PinMAME] StopGame ({reason}) skipped: start/stop already in progress."); + Logger.Warn($"[PinMAME] StopGame ({reason}) skipped: start/stop already in progress."); return; } // Never block the Unity main thread during playmode exit. // PinMAME shutdown is best-effort here; OnInit() and the editor lifecycle hook // will recover/ensure shutdown before starting a new ROM. - Logger.Warn($"{LogPrefix} [PinMAME] StopGame ({reason}) requested. RunningGame={_pinMame?.RunningGame}"); + Logger.Warn($"[PinMAME] StopGame ({reason}) requested. RunningGame={_pinMame?.RunningGame}"); try { if (_pinMame != null) { @@ -359,7 +358,7 @@ private void RequestStopGame(string reason) try { _pinMame?.StopGame(); } catch (Exception e) { - Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame ({reason}) failed."); + Logger.Warn(e, $"[PinMAME] StopGame ({reason}) failed."); } finally { PinMameStartStopGate.Release(); } @@ -401,7 +400,7 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag await PinMameStartStopGate.WaitAsync(ct); try { - Logger.Info($"{LogPrefix} [PinMAME] OnInit {name}: romId={romId}, sampleRate={AudioSettings.outputSampleRate}"); + Logger.Info($"[PinMAME] OnInit {name}: romId={romId}, sampleRate={AudioSettings.outputSampleRate}"); #if UNITY_EDITOR // With Domain Reload disabled, PinMAME (native + managed singleton) persists across play sessions. @@ -412,16 +411,16 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag try { PinMame.PinMame.StopRunningGame(); } catch (Exception e) { - Logger.Warn(e, $"{LogPrefix} [PinMAME] Pre-start StopRunningGame failed."); + Logger.Warn(e, "[PinMAME] Pre-start StopRunningGame failed."); } // Wait for a clean stopped state before starting a new ROM. var preStopWaitSw = Stopwatch.StartNew(); while (PinMame.PinMame.RunState != 0 && preStopWaitSw.ElapsedMilliseconds < StopTimeoutMs) { await Task.Delay(10, ct); } - Logger.Info($"{LogPrefix} [PinMAME] Editor pre-stop: initialRunState={preStopState}, stopCallMs={preStopSw.ElapsedMilliseconds}, waitMs={preStopWaitSw.ElapsedMilliseconds}, finalRunState={PinMame.PinMame.RunState}"); + Logger.Debug($"[PinMAME] Editor pre-stop: initialRunState={preStopState}, stopCallMs={preStopSw.ElapsedMilliseconds}, waitMs={preStopWaitSw.ElapsedMilliseconds}, finalRunState={PinMame.PinMame.RunState}"); if (PinMame.PinMame.RunState != 0) { - Logger.Error($"{LogPrefix} [PinMAME] Cannot start ROM; PinMAME did not reach stopped state (RunState={PinMame.PinMame.RunState})."); + Logger.Error($"[PinMAME] Cannot start ROM; PinMAME did not reach stopped state (RunState={PinMame.PinMame.RunState})."); return; } @@ -439,7 +438,7 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag while ((PinMame.PinMame.IsStopInProgress || PinMame.PinMame.IsRunning) && swStop.ElapsedMilliseconds < StopTimeoutMs) { await Task.Delay(10, ct); } - Logger.Info($"{LogPrefix} [PinMAME] Pre-start wait: {swStop.ElapsedMilliseconds}ms (WasRunning={wasRunning}, WasStopping={wasStopping}, IsRunning={PinMame.PinMame.IsRunning}, RunState={PinMame.PinMame.RunState}, StopInProgress={PinMame.PinMame.IsStopInProgress})"); + Logger.Debug($"[PinMAME] Pre-start wait: {swStop.ElapsedMilliseconds}ms (WasRunning={wasRunning}, WasStopping={wasStopping}, IsRunning={PinMame.PinMame.IsRunning}, RunState={PinMame.PinMame.RunState}, StopInProgress={PinMame.PinMame.IsStopInProgress})"); // ReSharper disable once ExpressionIsAlwaysNull _pinMame = PinMame.PinMame.Instance(PinMameAudioFormat.AudioFormatFloat, AudioSettings.outputSampleRate, vpmPath); @@ -461,12 +460,12 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag // If domain reload is disabled or a previous table didn't shut down cleanly, // PinMAME can still be running here. if (PinMame.PinMame.IsRunning) { - Logger.Warn($"{LogPrefix} [PinMAME] A game is already running (RunningGame={_pinMame.RunningGame}); stopping it before starting a new one."); + Logger.Warn($"[PinMAME] A game is already running (RunningGame={_pinMame.RunningGame}); stopping it before starting a new one."); try { _pinMame.StopGame(); } catch (Exception e) { - Logger.Warn(e, $"{LogPrefix} [PinMAME] StopGame failed while recovering from already running state."); + Logger.Warn(e, "[PinMAME] StopGame failed while recovering from already running state."); } var sw = Stopwatch.StartNew(); @@ -474,7 +473,7 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag await Task.Delay(10, ct); } if (PinMame.PinMame.IsRunning) { - Logger.Warn($"{LogPrefix} [PinMAME] Failed to stop running game within timeout; attempting StartGame anyway."); + Logger.Warn("[PinMAME] Failed to stop running game within timeout; attempting StartGame anyway."); } } @@ -501,14 +500,16 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag try { _pinMame.StartGame(romId); + Logger.Debug($"[PinMAME] StartGame returned. RunState={PinMame.PinMame.RunState}"); } catch (InvalidOperationException e) when (e.Message != null && e.Message.Contains("status=GAME_ALREADY_RUNNING")) { - Logger.Warn(e, $"{LogPrefix} [PinMAME] StartGame reported already running; stopping and retrying once."); + Logger.Warn(e, "[PinMAME] StartGame reported already running; stopping and retrying once."); try { _pinMame.StopGame(); await Task.Delay(100, ct); _pinMame.StartGame(romId); + Logger.Debug($"[PinMAME] StartGame retry returned. RunState={PinMame.PinMame.RunState}"); } catch (Exception retryEx) { Logger.Error(retryEx); @@ -525,7 +526,7 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag public void ToggleSpeed() { - Logger.Info($"{LogPrefix} [PinMAME] Toggle speed."); + Logger.Info("[PinMAME] Toggle speed."); _pinMame.SetHandleKeyboard(true); _toggleSpeed = true; @@ -533,7 +534,7 @@ public void ToggleSpeed() private void OnGameStarted() { - Logger.Info($"{LogPrefix} [PinMAME] Game started."); + Logger.Info("[PinMAME] Game started."); _isRunning = true; _solenoidDelayStart = DateTimeOffset.Now.ToUnixTimeMilliseconds(); @@ -544,7 +545,7 @@ private void OnGameStarted() } catch(Exception e) { - Logger.Error($"{LogPrefix} [PinMAME] OnGameStarted: {e.Message}"); + Logger.Error($"[PinMAME] OnGameStarted: {e.Message}"); } lock (_dispatchQueue) { @@ -556,7 +557,7 @@ private void OnGameEnded() { // Native can report ended more than once during teardown; keep it idempotent. if (_isRunning) { - Logger.Info($"{LogPrefix} [PinMAME] Game ended."); + Logger.Info("[PinMAME] Game ended."); } _isRunning = false; } @@ -668,10 +669,14 @@ private void OnDisplayRequested(int index, int displayCount, PinMameDisplayLayou } } - private void OnDisplayUpdated(int index, IntPtr framePtr, PinMameDisplayLayout displayLayout) - { - if (displayLayout.IsDmd) { - UpdateDmd(index, displayLayout, framePtr); + private void OnDisplayUpdated(int index, IntPtr framePtr, PinMameDisplayLayout displayLayout) + { + if (!_frameBuffer.ContainsKey(index)) { + Logger.Warn($"[PinMAME] Dropping display frame for unknown index {index} (layout: {displayLayout})."); + return; + } + if (displayLayout.IsDmd) { + UpdateDmd(index, displayLayout, framePtr); } else { UpdateSegDisp(index, displayLayout, framePtr); @@ -778,11 +783,11 @@ private int OnAudioAvailable(PinMameAudioInfo audioInfo) return _audioInfo.SamplesPerFrame; } - private int OnAudioUpdated(IntPtr framePtr, int frameSize) - { - if (_audioFilterChannels == 0) { - // don't know how many channels yet - return _audioInfo.SamplesPerFrame; + private int OnAudioUpdated(IntPtr framePtr, int frameSize) + { + if (_audioFilterChannels == 0) { + // don't know how many channels yet + return _audioInfo.SamplesPerFrame; } _audioNumSamplesInput += frameSize; @@ -904,9 +909,9 @@ public bool GetCoil(string id) return _player != null && _player.CoilStatuses.ContainsKey(id) && _player.CoilStatuses[id]; } - private void OnSolenoidUpdated(int id, bool isActive) - { - if (_pinMameIdToCoilIdMapping.ContainsKey(id)) { + private void OnSolenoidUpdated(int id, bool isActive) + { + if (_pinMameIdToCoilIdMapping.ContainsKey(id)) { if (!_solenoidsEnabled) { _solenoidsEnabled = DateTimeOffset.Now.ToUnixTimeMilliseconds() - _solenoidDelayStart >= SolenoidDelay; @@ -954,7 +959,7 @@ public LampState GetLamp(string id) public void SendInitialSwitches() { var switches = _player.SwitchStatuses; - Logger.Info($"{LogPrefix} [PinMAME] Sending initial switch statuses..."); + Logger.Info("[PinMAME] Sending initial switch statuses..."); foreach (var id in switches.Keys) { var isClosed = switches[id].IsSwitchClosed; // skip open switches @@ -1047,19 +1052,19 @@ private void SendMechs() #endregion - private int IsKeyPressed(PinMameKeycode keycode) - { - if (keycode == PinMameKeycode.F10) { - if (_toggleSpeed) { - _toggleSpeed = false; - - _pinMame.SetHandleKeyboard(false); - - return 1; - } - } - - return 0; - } - } -} + private int IsKeyPressed(PinMameKeycode keycode) + { + if (keycode == PinMameKeycode.F10) { + if (_toggleSpeed) { + _toggleSpeed = false; + + _pinMame.SetHandleKeyboard(false); + + return 1; + } + } + + return 0; + } + } +} From 8365cfeba441c6ac86b540b603c7ad867a9166ba Mon Sep 17 00:00:00 2001 From: freezy Date: Sun, 15 Feb 2026 15:50:35 +0100 Subject: [PATCH 05/17] fix: Another threading issue. --- .../Runtime/PinMameGamelogicEngine.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index a7e0bf9..4069df1 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -124,7 +124,7 @@ public GamelogicEngineLamp[] RequestedLamps { private Dictionary _lamps = new(); private Dictionary _pinMameIdToLampIdMapping = new(); - private bool _isRunning; + private volatile bool _isRunning; private int _numMechs; private Dictionary _frameBuffer = new(); private Dictionary> _dmdLevels = new(); From c9f1e16a08c9175d690cdff08c3365fd9a547287 Mon Sep 17 00:00:00 2001 From: freezy Date: Tue, 17 Feb 2026 00:41:12 +0100 Subject: [PATCH 06/17] chore: Add debug logs and make callbacks more stable. --- .../Runtime/PinMameGamelogicEngine.cs | 80 +++++++++++-------- .../Runtime/PinMameMechComponent.cs | 22 ++--- 2 files changed, 58 insertions(+), 44 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 4069df1..82825ed 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -39,9 +39,10 @@ namespace VisualPinball.Engine.PinMAME [DisallowMultipleComponent] [RequireComponent(typeof(AudioSource))] [AddComponentMenu("Pinball/Gamelogic Engine/PinMAME")] - public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine + public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading { public string Name { get; } = "PinMAME Gamelogic Engine"; + public GamelogicInputDispatchMode SwitchDispatchMode => GamelogicInputDispatchMode.SimulationThread; public const string DmdPrefix = "dmd"; public const string SegDispPrefix = "display"; @@ -148,8 +149,9 @@ public GamelogicEngineLamp[] RequestedLamps { public bool _solenoidsEnabled; public long _solenoidDelayStart; - private Dictionary _registeredMechs = new(); - private HashSet _mechSwitches = new(); + private Dictionary _registeredMechs = new(); + private Dictionary _registeredMechNames = new(); + private HashSet _mechSwitches = new(); private bool _toggleSpeed = false; private Keyboard _keyboard; @@ -186,10 +188,16 @@ private void Update() } lock (_dispatchQueue) { - while (_dispatchQueue.Count > 0) { - _dispatchQueue.Dequeue().Invoke(); - } - } + while (_dispatchQueue.Count > 0) { + var callback = _dispatchQueue.Dequeue(); + try { + callback.Invoke(); + } + catch (Exception e) { + Logger.Error(e, "[PinMAME] Exception while processing main-thread dispatch callback."); + } + } + } // lamps _pinMame.GetChangedLamps(_changedLamps); @@ -922,13 +930,13 @@ private void OnSolenoidUpdated(int id, bool isActive) var coil = _coils[_pinMameIdToCoilIdMapping[id]]; - if (_solenoidsEnabled) { - Logger.Info($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); - - lock (_dispatchQueue) { - _dispatchQueue.Enqueue(() => OnCoilChanged?.Invoke(this, new CoilEventArgs(coil.Id, isActive))); - } - } + if (_solenoidsEnabled) { + Logger.Info($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); + + lock (_dispatchQueue) { + _dispatchQueue.Enqueue(() => OnCoilChanged?.Invoke(this, new CoilEventArgs(coil.Id, isActive))); + } + } else { Logger.Info($"[PinMAME] <= solenoids disabled, coil {coil.Id} : {isActive} | {coil.Description}"); } @@ -1011,11 +1019,13 @@ public bool GetSwitch(string id) #region Mechs - public void RegisterMech(PinMameMechComponent mechComponent) - { - var id = _numMechs++; - _registeredMechs[id] = mechComponent; - } + public void RegisterMech(PinMameMechComponent mechComponent) + { + // PinMAME mech numbers are 1-based. + var id = ++_numMechs; + _registeredMechs[id] = mechComponent; + _registeredMechNames[id] = mechComponent ? mechComponent.name : ""; + } private void OnMechAvailable(int mechNo, PinMameMechInfo mechInfo) { @@ -1034,21 +1044,23 @@ private void OnMechUpdated(int mechNo, PinMameMechInfo mechInfo) } } - private void SendMechs() - { - var max = _pinMame.GetMaxMechs(); - foreach (var (id, mech) in _registeredMechs) { - if (id > max) { - Logger.Error($"PinMAME only supports up to {max} custom mechs, ignoring {mech.name}."); - return; - } - var mechConfig = mech.Config(_player.SwitchMapping, _player.CoilMapping, _switchIdToPinMameIdMappings, _coilIdToPinMameIdMapping); - _pinMame.SetMech(id, mechConfig); - foreach (var c in mechConfig.SwitchList) { - _mechSwitches.Add(c.SwNo); - } - } - } + private void SendMechs() + { + var max = _pinMame.GetMaxMechs(); + foreach (var (id, mech) in _registeredMechs) { + var mechName = _registeredMechNames.TryGetValue(id, out var name) ? name : $"mech#{id}"; + // GetMaxMechs() returns the count of available slots and valid mech numbers are 1..max. + if (id > max) { + Logger.Error($"PinMAME supports {max} custom mech slot(s). Cannot register mech id={id} ({mechName})."); + continue; + } + var mechConfig = mech.Config(_player.SwitchMapping, _player.CoilMapping, _switchIdToPinMameIdMappings, _coilIdToPinMameIdMapping); + _pinMame.SetMech(id, mechConfig); + foreach (var c in mechConfig.SwitchList) { + _mechSwitches.Add(c.SwNo); + } + } + } #endregion diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameMechComponent.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameMechComponent.cs index 5f5ef77..0dff722 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameMechComponent.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameMechComponent.cs @@ -134,10 +134,10 @@ public PinMameMechConfig Config(List switchMappings, List ReferenceEquals(sm.Device, this) && sm.DeviceItem == mark.SwitchId); - if (switchMapping == null) { - Logger.Error($"Switch \"{mark.Name}\" for mech {name} is not mapped in the switch manager, ignoring."); - continue; - } + if (switchMapping == null) { + Logger.Error($"Switch \"{mark.Name}\" for mech {_cachedName} is not mapped in the switch manager, ignoring."); + continue; + } switch (mark.Type) { case MechMarkSwitchType.EnableBetween: @@ -159,7 +159,8 @@ public PinMameMechConfig Config(List switchMappings, List AvailableCoils { private PinMameGamelogicEngine _gle; - private void Awake() - { - _gle = GetComponentInParent(); - if (_gle && enabled) { - _gle.RegisterMech(this); + private void Awake() + { + _cachedName = gameObject.name; + _gle = GetComponentInParent(); + if (_gle && enabled) { + _gle.RegisterMech(this); } } From 4308a16f246ca11b0ffaae89cd7287d8e6602757 Mon Sep 17 00:00:00 2001 From: freezy Date: Tue, 17 Feb 2026 23:57:38 +0100 Subject: [PATCH 07/17] api: Add SetTimeFence() --- .../Runtime/PinMameGamelogicEngine.cs | 31 ++++++++++++++----- 1 file changed, 24 insertions(+), 7 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 82825ed..4dd8b44 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -39,7 +39,7 @@ namespace VisualPinball.Engine.PinMAME [DisallowMultipleComponent] [RequireComponent(typeof(AudioSource))] [AddComponentMenu("Pinball/Gamelogic Engine/PinMAME")] - public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading + public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, IGamelogicTimeFence { public string Name { get; } = "PinMAME Gamelogic Engine"; public GamelogicInputDispatchMode SwitchDispatchMode => GamelogicInputDispatchMode.SimulationThread; @@ -97,10 +97,24 @@ public GamelogicEngineLamp[] RequestedLamps { public event EventHandler OnLampsChanged; public event EventHandler OnDisplaysRequested; public event EventHandler OnDisplayClear; - public event EventHandler OnDisplayUpdateFrame; - public event EventHandler OnStarted; - - #endregion + public event EventHandler OnDisplayUpdateFrame; + public event EventHandler OnStarted; + + public void SetTimeFence(double timeInSeconds) + { + if (!_isRunning || _pinMame == null) { + return; + } + + try { + PinMame.PinMame.SetTimeFence(timeInSeconds); + } + catch (Exception e) { + Logger.Warn(e, "[PinMAME] SetTimeFence call failed."); + } + } + + #endregion #region Internals @@ -284,6 +298,7 @@ public void StopForPlayModeExit() // Do not call into native Stop() here (it blocks); the editor hook will stop PinMAME // after we unsubscribe managed callbacks. Interlocked.Exchange(ref _stopRequested, 1); + SetTimeFence(0.0); // Stop polling outputs immediately to avoid concurrent calls into pinmame.dll // while a stop is in progress (pinmame APIs are not guaranteed thread-safe). _isRunning = false; @@ -317,6 +332,8 @@ private void RequestStopGame(string reason) #endif try { + SetTimeFence(0.0); + if (Interlocked.Exchange(ref _stopRequested, 1) != 0) { return; } @@ -1062,8 +1079,8 @@ private void SendMechs() } } - #endregion - + #endregion + private int IsKeyPressed(PinMameKeycode keycode) { if (keycode == PinMameKeycode.F10) { From 1edf98c3b0c01b5d90f332eeb0109c17ccc48b61 Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 09:24:59 +0100 Subject: [PATCH 08/17] perf: Add handlers for perf stats. --- .../Runtime/PinMameGamelogicEngine.cs | 87 +++++++++++++++++-- 1 file changed, 82 insertions(+), 5 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 4dd8b44..0969b6b 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -19,6 +19,7 @@ // ReSharper disable PossibleNullReferenceException using System; +using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.Linq; @@ -39,7 +40,7 @@ namespace VisualPinball.Engine.PinMAME [DisallowMultipleComponent] [RequireComponent(typeof(AudioSource))] [AddComponentMenu("Pinball/Gamelogic Engine/PinMAME")] - public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, IGamelogicTimeFence + public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, IGamelogicTimeFence, IGamelogicCoilOutputFeed, IGamelogicPerformanceStats { public string Name { get; } = "PinMAME Gamelogic Engine"; public GamelogicInputDispatchMode SwitchDispatchMode => GamelogicInputDispatchMode.SimulationThread; @@ -102,7 +103,7 @@ public GamelogicEngineLamp[] RequestedLamps { public void SetTimeFence(double timeInSeconds) { - if (!_isRunning || _pinMame == null) { + if (_pinMame == null) { return; } @@ -114,6 +115,29 @@ public void SetTimeFence(double timeInSeconds) } } + public bool TryDequeueCoilEvent(out CoilEventArgs coilEvent) + { + if (_simulationCoilDispatchQueue.TryDequeue(out coilEvent)) { + if (Interlocked.Decrement(ref _simulationCoilDispatchQueueSize) < 0) { + Interlocked.Exchange(ref _simulationCoilDispatchQueueSize, 0); + } + return true; + } + + return false; + } + + public bool TryGetPerformanceStats(out GamelogicPerformanceStats stats) + { + if (_pinMame == null) { + stats = default; + return false; + } + + stats = new GamelogicPerformanceStats(_isRunning, Volatile.Read(ref _pinMameCallbackRateHz), PinMame.PinMame.RunState); + return true; + } + #endregion #region Internals @@ -146,9 +170,16 @@ public void SetTimeFence(double timeInSeconds) private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); private static readonly Color Tint = new(1, 0.18f, 0); - - private readonly Queue _dispatchQueue = new(); - private readonly Queue _audioQueue = new(); + + private readonly Queue _dispatchQueue = new(); + private readonly ConcurrentQueue _simulationCoilDispatchQueue = new(); + private int _simulationCoilDispatchQueueSize; + private const int MaxSimulationCoilDispatchQueueSize = 8192; + private const double PerfSampleWindowSeconds = 0.25; + private long _pinMamePerfWindowStartTicks = Stopwatch.GetTimestamp(); + private int _pinMameCallbacksInWindow; + private float _pinMameCallbackRateHz; + private readonly Queue _audioQueue = new(); private int _audioFilterChannels; private PinMameAudioInfo _audioInfo; @@ -504,6 +535,7 @@ public async Task OnInit(Player player, TableApi tableApi, BallManager ballManag _pinMame.SetHandleKeyboard(false); _pinMame.SetHandleMechanics(DisableMechs ? 0 : 0xFF); + SetTimeFence(0.01); _pinMame.OnGameStarted += OnGameStarted; _pinMame.OnGameEnded += OnGameEnded; @@ -585,6 +617,11 @@ private void OnGameEnded() Logger.Info("[PinMAME] Game ended."); } _isRunning = false; + while (_simulationCoilDispatchQueue.TryDequeue(out _)) { + if (Interlocked.Decrement(ref _simulationCoilDispatchQueueSize) < 0) { + Interlocked.Exchange(ref _simulationCoilDispatchQueueSize, 0); + } + } } private void UpdateCaches() @@ -696,6 +733,8 @@ private void OnDisplayRequested(int index, int displayCount, PinMameDisplayLayou private void OnDisplayUpdated(int index, IntPtr framePtr, PinMameDisplayLayout displayLayout) { + MarkPinMameCallbackActivity(); + if (!_frameBuffer.ContainsKey(index)) { Logger.Warn($"[PinMAME] Dropping display frame for unknown index {index} (layout: {displayLayout})."); return; @@ -936,6 +975,8 @@ public bool GetCoil(string id) private void OnSolenoidUpdated(int id, bool isActive) { + MarkPinMameCallbackActivity(); + if (_pinMameIdToCoilIdMapping.ContainsKey(id)) { if (!_solenoidsEnabled) { _solenoidsEnabled = DateTimeOffset.Now.ToUnixTimeMilliseconds() - _solenoidDelayStart >= SolenoidDelay; @@ -949,6 +990,16 @@ private void OnSolenoidUpdated(int id, bool isActive) if (_solenoidsEnabled) { Logger.Info($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); + if (IsLowLatencySimulationCoil(coil.Id)) { + _simulationCoilDispatchQueue.Enqueue(new CoilEventArgs(coil.Id, isActive)); + if (Interlocked.Increment(ref _simulationCoilDispatchQueueSize) > MaxSimulationCoilDispatchQueueSize) { + if (_simulationCoilDispatchQueue.TryDequeue(out _)) { + if (Interlocked.Decrement(ref _simulationCoilDispatchQueueSize) < 0) { + Interlocked.Exchange(ref _simulationCoilDispatchQueueSize, 0); + } + } + } + } lock (_dispatchQueue) { _dispatchQueue.Enqueue(() => OnCoilChanged?.Invoke(this, new CoilEventArgs(coil.Id, isActive))); @@ -1095,5 +1146,31 @@ private int IsKeyPressed(PinMameKeycode keycode) return 0; } + + private static bool IsLowLatencySimulationCoil(string coilId) + { + return !string.IsNullOrEmpty(coilId) + && coilId.StartsWith("c_flipper", StringComparison.OrdinalIgnoreCase); + } + + private void MarkPinMameCallbackActivity() + { + Interlocked.Increment(ref _pinMameCallbacksInWindow); + + var nowTicks = Stopwatch.GetTimestamp(); + var startTicks = Volatile.Read(ref _pinMamePerfWindowStartTicks); + var elapsedSeconds = (double)(nowTicks - startTicks) / Stopwatch.Frequency; + if (elapsedSeconds < PerfSampleWindowSeconds) { + return; + } + + if (Interlocked.CompareExchange(ref _pinMamePerfWindowStartTicks, nowTicks, startTicks) != startTicks) { + return; + } + + var callbacks = Interlocked.Exchange(ref _pinMameCallbacksInWindow, 0); + var rate = elapsedSeconds > 0.0 ? callbacks / elapsedSeconds : 0.0; + Volatile.Write(ref _pinMameCallbackRateHz, (float)rate); + } } } From 70235f111796ea037589812aaa89fa4400374027 Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 10:48:25 +0100 Subject: [PATCH 09/17] threading: Fix the PinMAME dispatch queue drain pattern. `PinMameGamelogicEngine.Update()` now copies `_dispatchQueue` callbacks into a reusable local list under the queue lock, then releases the lock before invoking them. This removes callback execution time from the producer-contention window while preserving callback order and exception handling. --- .../Runtime/PinMameGamelogicEngine.cs | 22 ++++++++++++------- 1 file changed, 14 insertions(+), 8 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 0969b6b..189b477 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -172,6 +172,7 @@ public bool TryGetPerformanceStats(out GamelogicPerformanceStats stats) private static readonly Color Tint = new(1, 0.18f, 0); private readonly Queue _dispatchQueue = new(); + private readonly List _pendingDispatchCallbacks = new(); private readonly ConcurrentQueue _simulationCoilDispatchQueue = new(); private int _simulationCoilDispatchQueueSize; private const int MaxSimulationCoilDispatchQueueSize = 8192; @@ -232,18 +233,23 @@ private void Update() return; } + _pendingDispatchCallbacks.Clear(); + lock (_dispatchQueue) { while (_dispatchQueue.Count > 0) { - var callback = _dispatchQueue.Dequeue(); - try { - callback.Invoke(); - } - catch (Exception e) { - Logger.Error(e, "[PinMAME] Exception while processing main-thread dispatch callback."); - } + _pendingDispatchCallbacks.Add(_dispatchQueue.Dequeue()); } } - + + foreach (var callback in _pendingDispatchCallbacks) { + try { + callback.Invoke(); + } + catch (Exception e) { + Logger.Error(e, "[PinMAME] Exception while processing main-thread dispatch callback."); + } + } + // lamps _pinMame.GetChangedLamps(_changedLamps); foreach (var changedLamp in _changedLamps) { From 9e6e1c7cb84c51cc95f9a9a6aa3d8f30166bad16 Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 10:57:38 +0100 Subject: [PATCH 10/17] threading: Bound or instrument all cross-thread queues. `PinMameGamelogicEngine` warns on main-thread dispatch queue growth and simulation-coil queue overflow. --- .../Runtime/PinMameGamelogicEngine.cs | 76 +++++++++++-------- 1 file changed, 43 insertions(+), 33 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 189b477..fe1d8dd 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -175,7 +175,11 @@ public bool TryGetPerformanceStats(out GamelogicPerformanceStats stats) private readonly List _pendingDispatchCallbacks = new(); private readonly ConcurrentQueue _simulationCoilDispatchQueue = new(); private int _simulationCoilDispatchQueueSize; + private bool _dispatchQueueWarningIssued; + private bool _simulationCoilQueueWarningIssued; + private bool _simulationCoilQueueDropWarningIssued; private const int MaxSimulationCoilDispatchQueueSize = 8192; + private const int DispatchQueueWarningThreshold = 512; private const double PerfSampleWindowSeconds = 0.25; private long _pinMamePerfWindowStartTicks = Stopwatch.GetTimestamp(); private int _pinMameCallbacksInWindow; @@ -274,9 +278,20 @@ private void Update() // { // OnCoilChanged.Invoke(this, new CoilEventArgs("28", true)); // OnCoilChanged.Invoke(this, new CoilEventArgs("28", false)); - // } - } - + // } + } + + private void EnqueueMainThreadDispatch(Action callback) + { + lock (_dispatchQueue) { + _dispatchQueue.Enqueue(callback); + if (!_dispatchQueueWarningIssued && _dispatchQueue.Count >= DispatchQueueWarningThreshold) { + _dispatchQueueWarningIssued = true; + Logger.Warn($"[PinMAME] Main-thread dispatch queue backlog reached {_dispatchQueue.Count} items."); + } + } + } + private void OnDestroy() { #if UNITY_EDITOR @@ -611,9 +626,7 @@ private void OnGameStarted() Logger.Error($"[PinMAME] OnGameStarted: {e.Message}"); } - lock (_dispatchQueue) { - _dispatchQueue.Enqueue(() => OnStarted?.Invoke(this, EventArgs.Empty)); - } + EnqueueMainThreadDispatch(() => OnStarted?.Invoke(this, EventArgs.Empty)); } private void OnGameEnded() @@ -716,21 +729,17 @@ private void UpdateCaches() private void OnDisplayRequested(int index, int displayCount, PinMameDisplayLayout displayLayout) { if (displayLayout.IsDmd) { - lock (_dispatchQueue) { - _dispatchQueue.Enqueue(() => - OnDisplaysRequested?.Invoke(this, new RequestedDisplays( - new DisplayConfig($"{DmdPrefix}{index}", displayLayout.Width, displayLayout.Height)))); - } + EnqueueMainThreadDispatch(() => + OnDisplaysRequested?.Invoke(this, new RequestedDisplays( + new DisplayConfig($"{DmdPrefix}{index}", displayLayout.Width, displayLayout.Height)))); _frameBuffer[index] = new byte[displayLayout.Width * displayLayout.Height]; _dmdLevels[index] = displayLayout.Levels; } else { - lock (_dispatchQueue) { - _dispatchQueue.Enqueue(() => - OnDisplaysRequested?.Invoke(this, new RequestedDisplays( - new DisplayConfig($"{SegDispPrefix}{index}", displayLayout.Length, 1)))); - } + EnqueueMainThreadDispatch(() => + OnDisplaysRequested?.Invoke(this, new RequestedDisplays( + new DisplayConfig($"{SegDispPrefix}{index}", displayLayout.Length, 1)))); _frameBuffer[index] = new byte[displayLayout.Length * 2]; Logger.Info($"[PinMAME] Display {SegDispPrefix}{index} is of type {displayLayout.Type} at {displayLayout.Length} wide."); @@ -769,21 +778,17 @@ private void UpdateDmd(int index, PinMameDisplayLayout displayLayout, IntPtr fra } } - lock (_dispatchQueue) { - _dispatchQueue.Enqueue(() => OnDisplayUpdateFrame?.Invoke(this, - new DisplayFrameData($"{DmdPrefix}{index}", GetDisplayFrameFormat(displayLayout), _frameBuffer[index]))); - } + EnqueueMainThreadDispatch(() => OnDisplayUpdateFrame?.Invoke(this, + new DisplayFrameData($"{DmdPrefix}{index}", GetDisplayFrameFormat(displayLayout), _frameBuffer[index]))); } private void UpdateSegDisp(int index, PinMameDisplayLayout displayLayout, IntPtr framePtr) { Marshal.Copy(framePtr, _frameBuffer[index], 0, displayLayout.Length * 2); - lock (_dispatchQueue) { - //Logger.Info($"[PinMAME] Seg data ({index}): {BitConverter.ToString(_frameBuffer[index])}" ); - _dispatchQueue.Enqueue(() => OnDisplayUpdateFrame?.Invoke(this, - new DisplayFrameData($"{SegDispPrefix}{index}", GetDisplayFrameFormat(displayLayout), _frameBuffer[index]))); - } + //Logger.Info($"[PinMAME] Seg data ({index}): {BitConverter.ToString(_frameBuffer[index])}" ); + EnqueueMainThreadDispatch(() => OnDisplayUpdateFrame?.Invoke(this, + new DisplayFrameData($"{SegDispPrefix}{index}", GetDisplayFrameFormat(displayLayout), _frameBuffer[index]))); } public static DisplayFrameFormat GetDisplayFrameFormat(PinMameDisplayLayout layout) @@ -998,18 +1003,25 @@ private void OnSolenoidUpdated(int id, bool isActive) Logger.Info($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); if (IsLowLatencySimulationCoil(coil.Id)) { _simulationCoilDispatchQueue.Enqueue(new CoilEventArgs(coil.Id, isActive)); - if (Interlocked.Increment(ref _simulationCoilDispatchQueueSize) > MaxSimulationCoilDispatchQueueSize) { + var simulationCoilQueueSize = Interlocked.Increment(ref _simulationCoilDispatchQueueSize); + if (!_simulationCoilQueueWarningIssued && simulationCoilQueueSize >= MaxSimulationCoilDispatchQueueSize / 2) { + _simulationCoilQueueWarningIssued = true; + Logger.Warn($"[PinMAME] Simulation coil dispatch backlog reached {simulationCoilQueueSize} items."); + } + if (simulationCoilQueueSize > MaxSimulationCoilDispatchQueueSize) { if (_simulationCoilDispatchQueue.TryDequeue(out _)) { if (Interlocked.Decrement(ref _simulationCoilDispatchQueueSize) < 0) { Interlocked.Exchange(ref _simulationCoilDispatchQueueSize, 0); } + if (!_simulationCoilQueueDropWarningIssued) { + _simulationCoilQueueDropWarningIssued = true; + Logger.Warn($"[PinMAME] Simulation coil dispatch queue exceeded {MaxSimulationCoilDispatchQueueSize} items. Dropping oldest coil callbacks."); + } } } } - lock (_dispatchQueue) { - _dispatchQueue.Enqueue(() => OnCoilChanged?.Invoke(this, new CoilEventArgs(coil.Id, isActive))); - } + EnqueueMainThreadDispatch(() => OnCoilChanged?.Invoke(this, new CoilEventArgs(coil.Id, isActive))); } else { Logger.Info($"[PinMAME] <= solenoids disabled, coil {coil.Id} : {isActive} | {coil.Description}"); @@ -1108,10 +1120,8 @@ private void OnMechAvailable(int mechNo, PinMameMechInfo mechInfo) private void OnMechUpdated(int mechNo, PinMameMechInfo mechInfo) { - if (_registeredMechs.ContainsKey(mechNo)) { - lock (_dispatchQueue) { - _dispatchQueue.Enqueue(() => _registeredMechs[mechNo].UpdateMech(mechInfo)); - } + if (_registeredMechs.ContainsKey(mechNo)) { + EnqueueMainThreadDispatch(() => _registeredMechs[mechNo].UpdateMech(mechInfo)); } else { Logger.Info($"[PinMAME] <= mech updated: mechNo={mechNo}, mechInfo={mechInfo}"); From 3912b7aab939834c29707c7e48f79799a248e3fe Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 11:20:59 +0100 Subject: [PATCH 11/17] dmd: Improve frame buffer copying. --- .../Runtime/PinMameGamelogicEngine.cs | 110 +++++++++++------- 1 file changed, 66 insertions(+), 44 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index fe1d8dd..043cabf 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -173,6 +173,7 @@ public bool TryGetPerformanceStats(out GamelogicPerformanceStats stats) private readonly Queue _dispatchQueue = new(); private readonly List _pendingDispatchCallbacks = new(); + private readonly object _displayStateLock = new(); private readonly ConcurrentQueue _simulationCoilDispatchQueue = new(); private int _simulationCoilDispatchQueueSize; private bool _dispatchQueueWarningIssued; @@ -726,70 +727,91 @@ private void UpdateCaches() #region Displays - private void OnDisplayRequested(int index, int displayCount, PinMameDisplayLayout displayLayout) - { - if (displayLayout.IsDmd) { + private void OnDisplayRequested(int index, int displayCount, PinMameDisplayLayout displayLayout) + { + if (displayLayout.IsDmd) { EnqueueMainThreadDispatch(() => OnDisplaysRequested?.Invoke(this, new RequestedDisplays( new DisplayConfig($"{DmdPrefix}{index}", displayLayout.Width, displayLayout.Height)))); - - _frameBuffer[index] = new byte[displayLayout.Width * displayLayout.Height]; - _dmdLevels[index] = displayLayout.Levels; - - } else { + + lock (_displayStateLock) { + _frameBuffer[index] = new byte[displayLayout.Width * displayLayout.Height]; + _dmdLevels[index] = displayLayout.Levels; + } + + } else { EnqueueMainThreadDispatch(() => OnDisplaysRequested?.Invoke(this, new RequestedDisplays( new DisplayConfig($"{SegDispPrefix}{index}", displayLayout.Length, 1)))); - - _frameBuffer[index] = new byte[displayLayout.Length * 2]; - Logger.Info($"[PinMAME] Display {SegDispPrefix}{index} is of type {displayLayout.Type} at {displayLayout.Length} wide."); - } - } + + lock (_displayStateLock) { + _frameBuffer[index] = new byte[displayLayout.Length * 2]; + } + Logger.Info($"[PinMAME] Display {SegDispPrefix}{index} is of type {displayLayout.Type} at {displayLayout.Length} wide."); + } + } private void OnDisplayUpdated(int index, IntPtr framePtr, PinMameDisplayLayout displayLayout) { MarkPinMameCallbackActivity(); - if (!_frameBuffer.ContainsKey(index)) { - Logger.Warn($"[PinMAME] Dropping display frame for unknown index {index} (layout: {displayLayout})."); - return; - } if (displayLayout.IsDmd) { UpdateDmd(index, displayLayout, framePtr); - - } else { + + } else { UpdateSegDisp(index, displayLayout, framePtr); } } - private void UpdateDmd(int index, PinMameDisplayLayout displayLayout, IntPtr framePtr) - { - unsafe { - var ptr = (byte*) framePtr; - for (var y = 0; y < displayLayout.Height; y++) { - for (var x = 0; x < displayLayout.Width; x++) { - var pos = y * displayLayout.Width + x; - if (!_dmdLevels[index].ContainsKey(ptr[pos])) { - Logger.Error($"Display {index}: Provided levels ({BitConverter.ToString(_dmdLevels[index].Keys.ToArray())}) don't contain level {BitConverter.ToString(new[] {ptr[pos]})}."); - _dmdLevels[index][ptr[pos]] = 0x4; - } - _frameBuffer[index][pos] = _dmdLevels[index][ptr[pos]]; - } - } - } - + private void UpdateDmd(int index, PinMameDisplayLayout displayLayout, IntPtr framePtr) + { + byte[] frameBuffer; + Dictionary levels; + lock (_displayStateLock) { + if (!_frameBuffer.TryGetValue(index, out frameBuffer)) { + Logger.Warn($"[PinMAME] Dropping DMD frame for unknown index {index} (layout: {displayLayout})."); + return; + } + if (!_dmdLevels.TryGetValue(index, out levels) || levels == null) { + Logger.Warn($"[PinMAME] Dropping DMD frame for index {index} because display levels are not initialized yet."); + return; + } + } + + unsafe { + var ptr = (byte*) framePtr; + for (var y = 0; y < displayLayout.Height; y++) { + for (var x = 0; x < displayLayout.Width; x++) { + var pos = y * displayLayout.Width + x; + if (!levels.ContainsKey(ptr[pos])) { + Logger.Error($"Display {index}: Provided levels ({BitConverter.ToString(levels.Keys.ToArray())}) don't contain level {BitConverter.ToString(new[] {ptr[pos]})}."); + levels[ptr[pos]] = 0x4; + } + frameBuffer[pos] = levels[ptr[pos]]; + } + } + } + EnqueueMainThreadDispatch(() => OnDisplayUpdateFrame?.Invoke(this, - new DisplayFrameData($"{DmdPrefix}{index}", GetDisplayFrameFormat(displayLayout), _frameBuffer[index]))); - } - - private void UpdateSegDisp(int index, PinMameDisplayLayout displayLayout, IntPtr framePtr) - { - Marshal.Copy(framePtr, _frameBuffer[index], 0, displayLayout.Length * 2); - + new DisplayFrameData($"{DmdPrefix}{index}", GetDisplayFrameFormat(displayLayout), frameBuffer))); + } + + private void UpdateSegDisp(int index, PinMameDisplayLayout displayLayout, IntPtr framePtr) + { + byte[] frameBuffer; + lock (_displayStateLock) { + if (!_frameBuffer.TryGetValue(index, out frameBuffer)) { + Logger.Warn($"[PinMAME] Dropping segmented display frame for unknown index {index} (layout: {displayLayout})."); + return; + } + } + + Marshal.Copy(framePtr, frameBuffer, 0, displayLayout.Length * 2); + //Logger.Info($"[PinMAME] Seg data ({index}): {BitConverter.ToString(_frameBuffer[index])}" ); EnqueueMainThreadDispatch(() => OnDisplayUpdateFrame?.Invoke(this, - new DisplayFrameData($"{SegDispPrefix}{index}", GetDisplayFrameFormat(displayLayout), _frameBuffer[index]))); - } + new DisplayFrameData($"{SegDispPrefix}{index}", GetDisplayFrameFormat(displayLayout), frameBuffer))); + } public static DisplayFrameFormat GetDisplayFrameFormat(PinMameDisplayLayout layout) { From b9bfc4ef3f580067732d2332951644a973eeece8 Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 11:50:08 +0100 Subject: [PATCH 12/17] threading: Generalize low-latency coil handling. --- .../Runtime/PinMameGamelogicEngine.cs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 043cabf..8bd6485 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -1023,7 +1023,7 @@ private void OnSolenoidUpdated(int id, bool isActive) if (_solenoidsEnabled) { Logger.Info($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); - if (IsLowLatencySimulationCoil(coil.Id)) { + if (ShouldDispatchSimulationCoil(coil.Id)) { _simulationCoilDispatchQueue.Enqueue(new CoilEventArgs(coil.Id, isActive)); var simulationCoilQueueSize = Interlocked.Increment(ref _simulationCoilDispatchQueueSize); if (!_simulationCoilQueueWarningIssued && simulationCoilQueueSize >= MaxSimulationCoilDispatchQueueSize / 2) { @@ -1185,10 +1185,11 @@ private int IsKeyPressed(PinMameKeycode keycode) return 0; } - private static bool IsLowLatencySimulationCoil(string coilId) + private bool ShouldDispatchSimulationCoil(string coilId) { return !string.IsNullOrEmpty(coilId) - && coilId.StartsWith("c_flipper", StringComparison.OrdinalIgnoreCase); + && _player != null + && _player.SupportsSimulationThreadCoilDispatch(coilId); } private void MarkPinMameCallbackActivity() From 47c2a9548b467908eae367e2b19a711a3fc65acb Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 12:41:01 +0100 Subject: [PATCH 13/17] gle: Finish shared-state publication for PinMAME outputs. --- .../Runtime/PinMameGamelogicEngine.cs | 131 +++++++++++++++--- 1 file changed, 115 insertions(+), 16 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 8bd6485..8686747 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -28,11 +28,12 @@ using System.Threading.Tasks; using NLog; using PinMame; -using UnityEngine; -using UnityEngine.InputSystem; -using VisualPinball.Engine.Game.Engines; -using VisualPinball.Unity; -using Logger = NLog.Logger; +using UnityEngine; +using UnityEngine.InputSystem; +using VisualPinball.Engine.Game.Engines; +using VisualPinball.Unity; +using VisualPinball.Unity.Simulation; +using Logger = NLog.Logger; namespace VisualPinball.Engine.PinMAME { @@ -40,7 +41,7 @@ namespace VisualPinball.Engine.PinMAME [DisallowMultipleComponent] [RequireComponent(typeof(AudioSource))] [AddComponentMenu("Pinball/Gamelogic Engine/PinMAME")] - public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, IGamelogicTimeFence, IGamelogicCoilOutputFeed, IGamelogicPerformanceStats + public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, IGamelogicTimeFence, IGamelogicCoilOutputFeed, IGamelogicSharedStateWriter, IGamelogicPerformanceStats { public string Name { get; } = "PinMAME Gamelogic Engine"; public GamelogicInputDispatchMode SwitchDispatchMode => GamelogicInputDispatchMode.SimulationThread; @@ -138,6 +139,15 @@ public bool TryGetPerformanceStats(out GamelogicPerformanceStats stats) return true; } + public void WriteSharedState(ref SimulationState.Snapshot snapshot) + { + lock (_outputStateLock) { + snapshot.CoilCount = CopyCoilStates(ref snapshot); + snapshot.LampCount = CopyLampStates(ref snapshot); + snapshot.GICount = CopyGiStates(ref snapshot); + } + } + #endregion #region Internals @@ -174,6 +184,7 @@ public bool TryGetPerformanceStats(out GamelogicPerformanceStats stats) private readonly Queue _dispatchQueue = new(); private readonly List _pendingDispatchCallbacks = new(); private readonly object _displayStateLock = new(); + private readonly object _outputStateLock = new(); private readonly ConcurrentQueue _simulationCoilDispatchQueue = new(); private int _simulationCoilDispatchQueueSize; private bool _dispatchQueueWarningIssued; @@ -185,6 +196,9 @@ public bool TryGetPerformanceStats(out GamelogicPerformanceStats stats) private long _pinMamePerfWindowStartTicks = Stopwatch.GetTimestamp(); private int _pinMameCallbacksInWindow; private float _pinMameCallbackRateHz; + private readonly Dictionary _sharedCoilStates = new(); + private readonly Dictionary _sharedLampStates = new(); + private readonly Dictionary _sharedGiStates = new(); private readonly Queue _audioQueue = new(); private int _audioFilterChannels; @@ -258,6 +272,9 @@ private void Update() // lamps _pinMame.GetChangedLamps(_changedLamps); foreach (var changedLamp in _changedLamps) { + lock (_outputStateLock) { + _sharedLampStates[changedLamp.Id] = changedLamp.Value; + } if (_pinMameIdToLampIdMapping.ContainsKey(changedLamp.Id)) { //Logger.Info($"[PinMAME] <= lamp {changedLamp.Id}: {changedLamp.Value}"); OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedLamp.Id]].Id, changedLamp.Value)); @@ -267,6 +284,9 @@ private void Update() // gi _pinMame.GetChangedGIs(_changedGIs); foreach (var changedGi in _changedGIs) { + lock (_outputStateLock) { + _sharedGiStates[changedGi.Id] = changedGi.Value; + } if (_pinMameIdToLampIdMapping.ContainsKey(changedGi.Id)) { //Logger.Info($"[PinMAME] <= gi {changedGi.Id}: {changedGi.Value}"); OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedGi.Id]].Id, changedGi.Value, LampSource.GI)); @@ -293,6 +313,57 @@ private void EnqueueMainThreadDispatch(Action callback) } } + private int CopyCoilStates(ref SimulationState.Snapshot snapshot) + { + var index = 0; + foreach (var entry in _sharedCoilStates) { + if (index >= snapshot.CoilStates.Length) { + break; + } + + snapshot.CoilStates[index++] = new SimulationState.CoilState { + Id = entry.Key, + IsActive = entry.Value ? (byte)1 : (byte)0, + }; + } + + return index; + } + + private int CopyLampStates(ref SimulationState.Snapshot snapshot) + { + var index = 0; + foreach (var entry in _sharedLampStates) { + if (index >= snapshot.LampStates.Length) { + break; + } + + snapshot.LampStates[index++] = new SimulationState.LampState { + Id = entry.Key, + Value = entry.Value, + }; + } + + return index; + } + + private int CopyGiStates(ref SimulationState.Snapshot snapshot) + { + var index = 0; + foreach (var entry in _sharedGiStates) { + if (index >= snapshot.GIStates.Length) { + break; + } + + snapshot.GIStates[index++] = new SimulationState.GIState { + Id = entry.Key, + Value = entry.Value, + }; + } + + return index; + } + private void OnDestroy() { #if UNITY_EDITOR @@ -319,6 +390,11 @@ private void OnDestroy() } _frameBuffer.Clear(); _dmdLevels.Clear(); + lock (_outputStateLock) { + _sharedCoilStates.Clear(); + _sharedLampStates.Clear(); + _sharedGiStates.Clear(); + } } private void OnDisable() @@ -642,6 +718,11 @@ private void OnGameEnded() Interlocked.Exchange(ref _simulationCoilDispatchQueueSize, 0); } } + lock (_outputStateLock) { + _sharedCoilStates.Clear(); + _sharedLampStates.Clear(); + _sharedGiStates.Clear(); + } } private void UpdateCaches() @@ -996,10 +1077,15 @@ private void OnAudioFilterRead(float[] data, int channels) #region Coils - public void SetCoil(string n, bool value) - { - OnCoilChanged?.Invoke(this, new CoilEventArgs(n, value)); - } + public void SetCoil(string n, bool value) + { + if (int.TryParse(n, out var coilId)) { + lock (_outputStateLock) { + _sharedCoilStates[coilId] = value; + } + } + OnCoilChanged?.Invoke(this, new CoilEventArgs(n, value)); + } public bool GetCoil(string id) { @@ -1019,9 +1105,13 @@ private void OnSolenoidUpdated(int id, bool isActive) } } - var coil = _coils[_pinMameIdToCoilIdMapping[id]]; - + var coil = _coils[_pinMameIdToCoilIdMapping[id]]; + if (_solenoidsEnabled) { + lock (_outputStateLock) { + _sharedCoilStates[id] = isActive; + } + Logger.Info($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); if (ShouldDispatchSimulationCoil(coil.Id)) { _simulationCoilDispatchQueue.Enqueue(new CoilEventArgs(coil.Id, isActive)); @@ -1058,10 +1148,19 @@ private void OnSolenoidUpdated(int id, bool isActive) #region Lamps - public void SetLamp(string id, float value, bool isCoil = false, LampSource source = LampSource.Lamp) - { - OnLampChanged?.Invoke(this, new LampEventArgs(id, value, isCoil, source)); - } + public void SetLamp(string id, float value, bool isCoil = false, LampSource source = LampSource.Lamp) + { + if (int.TryParse(id, out var lampId)) { + lock (_outputStateLock) { + if (source == LampSource.GI) { + _sharedGiStates[lampId] = value; + } else { + _sharedLampStates[lampId] = value; + } + } + } + OnLampChanged?.Invoke(this, new LampEventArgs(id, value, isCoil, source)); + } public LampState GetLamp(string id) { From 863cd99275d1435cc5ca88a19c8148b4a8ac524b Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 12:50:41 +0100 Subject: [PATCH 14/17] gle: Reevaluate lamp/GI polling strategy. --- .../Runtime/PinMameGamelogicEngine.cs | 50 +++++++++++++++++-- 1 file changed, 47 insertions(+), 3 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 8686747..8ed9498 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -41,7 +41,7 @@ namespace VisualPinball.Engine.PinMAME [DisallowMultipleComponent] [RequireComponent(typeof(AudioSource))] [AddComponentMenu("Pinball/Gamelogic Engine/PinMAME")] - public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, IGamelogicTimeFence, IGamelogicCoilOutputFeed, IGamelogicSharedStateWriter, IGamelogicPerformanceStats + public class PinMameGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, IGamelogicTimeFence, IGamelogicCoilOutputFeed, IGamelogicSharedStateWriter, IGamelogicSharedStateApplier, IGamelogicPerformanceStats { public string Name { get; } = "PinMAME Gamelogic Engine"; public GamelogicInputDispatchMode SwitchDispatchMode => GamelogicInputDispatchMode.SimulationThread; @@ -148,6 +148,41 @@ public void WriteSharedState(ref SimulationState.Snapshot snapshot) } } + public void ApplySharedState(in SimulationState.Snapshot snapshot) + { + if (_player == null) { + return; + } + + _sharedLampPlaybackActive = true; + + for (var i = 0; i < snapshot.LampCount; i++) { + var lamp = snapshot.LampStates[i]; + if (!_pinMameIdToLampIdMapping.TryGetValue(lamp.Id, out var lampId)) { + continue; + } + if (_lastAppliedLampStates.TryGetValue(lamp.Id, out var currentValue) && currentValue == lamp.Value) { + continue; + } + + _lastAppliedLampStates[lamp.Id] = lamp.Value; + _player.SetLamp(lampId, lamp.Value, LampSource.Lamp); + } + + for (var i = 0; i < snapshot.GICount; i++) { + var gi = snapshot.GIStates[i]; + if (!_pinMameIdToLampIdMapping.TryGetValue(gi.Id, out var giId)) { + continue; + } + if (_lastAppliedGiStates.TryGetValue(gi.Id, out var currentValue) && currentValue == gi.Value) { + continue; + } + + _lastAppliedGiStates[gi.Id] = gi.Value; + _player.SetLamp(giId, gi.Value, LampSource.GI); + } + } + #endregion #region Internals @@ -199,6 +234,9 @@ public void WriteSharedState(ref SimulationState.Snapshot snapshot) private readonly Dictionary _sharedCoilStates = new(); private readonly Dictionary _sharedLampStates = new(); private readonly Dictionary _sharedGiStates = new(); + private readonly Dictionary _lastAppliedLampStates = new(); + private readonly Dictionary _lastAppliedGiStates = new(); + private bool _sharedLampPlaybackActive; private readonly Queue _audioQueue = new(); private int _audioFilterChannels; @@ -275,7 +313,7 @@ private void Update() lock (_outputStateLock) { _sharedLampStates[changedLamp.Id] = changedLamp.Value; } - if (_pinMameIdToLampIdMapping.ContainsKey(changedLamp.Id)) { + if (!_sharedLampPlaybackActive && _pinMameIdToLampIdMapping.ContainsKey(changedLamp.Id)) { //Logger.Info($"[PinMAME] <= lamp {changedLamp.Id}: {changedLamp.Value}"); OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedLamp.Id]].Id, changedLamp.Value)); } @@ -287,7 +325,7 @@ private void Update() lock (_outputStateLock) { _sharedGiStates[changedGi.Id] = changedGi.Value; } - if (_pinMameIdToLampIdMapping.ContainsKey(changedGi.Id)) { + if (!_sharedLampPlaybackActive && _pinMameIdToLampIdMapping.ContainsKey(changedGi.Id)) { //Logger.Info($"[PinMAME] <= gi {changedGi.Id}: {changedGi.Value}"); OnLampChanged?.Invoke(this, new LampEventArgs(_lamps[_pinMameIdToLampIdMapping[changedGi.Id]].Id, changedGi.Value, LampSource.GI)); } /*else { @@ -395,6 +433,9 @@ private void OnDestroy() _sharedLampStates.Clear(); _sharedGiStates.Clear(); } + _lastAppliedLampStates.Clear(); + _lastAppliedGiStates.Clear(); + _sharedLampPlaybackActive = false; } private void OnDisable() @@ -723,6 +764,9 @@ private void OnGameEnded() _sharedLampStates.Clear(); _sharedGiStates.Clear(); } + _lastAppliedLampStates.Clear(); + _lastAppliedGiStates.Clear(); + _sharedLampPlaybackActive = false; } private void UpdateCaches() From 110aed3a1901f3fa7a4ab5fde230f3124c9effbc Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 12:55:44 +0100 Subject: [PATCH 15/17] fix: Remove hot-path logging and wall-clock calls from PinMAME callbacks. The solenoid-delay timing check now uses a monotonic `Stopwatch`-based timestamp instead of `DateTimeOffset.Now`, and high-frequency coil callback logs were downgraded behind `Logger.IsDebugEnabled` so normal runtime no longer pays string-format/logging cost on every coil edge. --- .../Runtime/PinMameGamelogicEngine.cs | 34 ++++++++++++------- 1 file changed, 21 insertions(+), 13 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 8ed9498..2911d57 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -225,6 +225,7 @@ public void ApplySharedState(in SimulationState.Snapshot snapshot) private bool _dispatchQueueWarningIssued; private bool _simulationCoilQueueWarningIssued; private bool _simulationCoilQueueDropWarningIssued; + private long _solenoidDelayStartTimestampUsec; private const int MaxSimulationCoilDispatchQueueSize = 8192; private const int DispatchQueueWarningThreshold = 512; private const double PerfSampleWindowSeconds = 0.25; @@ -239,7 +240,7 @@ public void ApplySharedState(in SimulationState.Snapshot snapshot) private bool _sharedLampPlaybackActive; private readonly Queue _audioQueue = new(); - private int _audioFilterChannels; + private int _audioFilterChannels; private PinMameAudioInfo _audioInfo; private float[] _lastAudioFrame = {}; private int _lastAudioFrameOffset; @@ -259,6 +260,8 @@ public void ApplySharedState(in SimulationState.Snapshot snapshot) private bool _toggleSpeed = false; private Keyboard _keyboard; + private static long TimestampUsec => (Stopwatch.GetTimestamp() * 1_000_000) / Stopwatch.Frequency; + private static readonly SemaphoreSlim PinMameStartStopGate = new SemaphoreSlim(1, 1); private int _onInitCalled; private int _stopRequested; @@ -733,7 +736,8 @@ private void OnGameStarted() Logger.Info("[PinMAME] Game started."); _isRunning = true; - _solenoidDelayStart = DateTimeOffset.Now.ToUnixTimeMilliseconds(); + _solenoidDelayStartTimestampUsec = TimestampUsec; + _solenoidDelayStart = _solenoidDelayStartTimestampUsec / 1000; try { SendInitialSwitches(); @@ -1141,13 +1145,13 @@ private void OnSolenoidUpdated(int id, bool isActive) MarkPinMameCallbackActivity(); if (_pinMameIdToCoilIdMapping.ContainsKey(id)) { - if (!_solenoidsEnabled) { - _solenoidsEnabled = DateTimeOffset.Now.ToUnixTimeMilliseconds() - _solenoidDelayStart >= SolenoidDelay; - - if (_solenoidsEnabled) { - Logger.Info($"Solenoids enabled, {SolenoidDelay}ms passed"); - } - } + if (!_solenoidsEnabled) { + _solenoidsEnabled = TimestampUsec - _solenoidDelayStartTimestampUsec >= (long)(SolenoidDelay * 1000f); + + if (_solenoidsEnabled) { + Logger.Info($"Solenoids enabled, {SolenoidDelay}ms passed"); + } + } var coil = _coils[_pinMameIdToCoilIdMapping[id]]; @@ -1156,7 +1160,9 @@ private void OnSolenoidUpdated(int id, bool isActive) _sharedCoilStates[id] = isActive; } - Logger.Info($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); + if (Logger.IsDebugEnabled) { + Logger.Debug($"[PinMAME] <= coil {coil.Id} : {isActive} | {coil.Description}"); + } if (ShouldDispatchSimulationCoil(coil.Id)) { _simulationCoilDispatchQueue.Enqueue(new CoilEventArgs(coil.Id, isActive)); var simulationCoilQueueSize = Interlocked.Increment(ref _simulationCoilDispatchQueueSize); @@ -1179,9 +1185,11 @@ private void OnSolenoidUpdated(int id, bool isActive) EnqueueMainThreadDispatch(() => OnCoilChanged?.Invoke(this, new CoilEventArgs(coil.Id, isActive))); } - else { - Logger.Info($"[PinMAME] <= solenoids disabled, coil {coil.Id} : {isActive} | {coil.Description}"); - } + else { + if (Logger.IsDebugEnabled) { + Logger.Debug($"[PinMAME] <= solenoids disabled, coil {coil.Id} : {isActive} | {coil.Description}"); + } + } } else { Logger.Warn($"[PinMAME] <= coil UNMAPPED {id}: {isActive}"); From 1f3d3080cb3cc92cdd66cc883e55fb5457c13aaf Mon Sep 17 00:00:00 2001 From: freezy Date: Fri, 6 Mar 2026 23:56:22 +0100 Subject: [PATCH 16/17] dmd: Switch to 8-bit pixels. --- .../Runtime/PinMameGamelogicEngine.cs | 39 +++++-------------- 1 file changed, 10 insertions(+), 29 deletions(-) diff --git a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs index 2911d57..96d1ba0 100644 --- a/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs +++ b/VisualPinball.Engine.PinMAME.Unity/Runtime/PinMameGamelogicEngine.cs @@ -210,11 +210,11 @@ public void ApplySharedState(in SimulationState.Snapshot snapshot) private volatile bool _isRunning; private int _numMechs; - private Dictionary _frameBuffer = new(); - private Dictionary> _dmdLevels = new(); - + private Dictionary _frameBuffer = new(); + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); private static readonly Color Tint = new(1, 0.18f, 0); + private static readonly Color UnlitTint = new(Tint.r * 0.18f, Tint.g * 0.18f, Tint.b * 0.18f, 1f); private readonly Queue _dispatchQueue = new(); private readonly List _pendingDispatchCallbacks = new(); @@ -430,7 +430,6 @@ private void OnDestroy() _pinMame.IsKeyPressed -= IsKeyPressed; } _frameBuffer.Clear(); - _dmdLevels.Clear(); lock (_outputStateLock) { _sharedCoilStates.Clear(); _sharedLampStates.Clear(); @@ -861,11 +860,10 @@ private void OnDisplayRequested(int index, int displayCount, PinMameDisplayLayou if (displayLayout.IsDmd) { EnqueueMainThreadDispatch(() => OnDisplaysRequested?.Invoke(this, new RequestedDisplays( - new DisplayConfig($"{DmdPrefix}{index}", displayLayout.Width, displayLayout.Height)))); + new DisplayConfig($"{DmdPrefix}{index}", displayLayout.Width, displayLayout.Height, false, Tint, UnlitTint)))); lock (_displayStateLock) { _frameBuffer[index] = new byte[displayLayout.Width * displayLayout.Height]; - _dmdLevels[index] = displayLayout.Levels; } } else { @@ -895,31 +893,14 @@ private void OnDisplayUpdated(int index, IntPtr framePtr, PinMameDisplayLayout d private void UpdateDmd(int index, PinMameDisplayLayout displayLayout, IntPtr framePtr) { byte[] frameBuffer; - Dictionary levels; lock (_displayStateLock) { if (!_frameBuffer.TryGetValue(index, out frameBuffer)) { Logger.Warn($"[PinMAME] Dropping DMD frame for unknown index {index} (layout: {displayLayout})."); return; } - if (!_dmdLevels.TryGetValue(index, out levels) || levels == null) { - Logger.Warn($"[PinMAME] Dropping DMD frame for index {index} because display levels are not initialized yet."); - return; - } } - unsafe { - var ptr = (byte*) framePtr; - for (var y = 0; y < displayLayout.Height; y++) { - for (var x = 0; x < displayLayout.Width; x++) { - var pos = y * displayLayout.Width + x; - if (!levels.ContainsKey(ptr[pos])) { - Logger.Error($"Display {index}: Provided levels ({BitConverter.ToString(levels.Keys.ToArray())}) don't contain level {BitConverter.ToString(new[] {ptr[pos]})}."); - levels[ptr[pos]] = 0x4; - } - frameBuffer[pos] = levels[ptr[pos]]; - } - } - } + Marshal.Copy(framePtr, frameBuffer, 0, frameBuffer.Length); EnqueueMainThreadDispatch(() => OnDisplayUpdateFrame?.Invoke(this, new DisplayFrameData($"{DmdPrefix}{index}", GetDisplayFrameFormat(displayLayout), frameBuffer))); @@ -942,11 +923,11 @@ private void UpdateSegDisp(int index, PinMameDisplayLayout displayLayout, IntPtr new DisplayFrameData($"{SegDispPrefix}{index}", GetDisplayFrameFormat(displayLayout), frameBuffer))); } - public static DisplayFrameFormat GetDisplayFrameFormat(PinMameDisplayLayout layout) - { - if (layout.IsDmd) { - return layout.Depth == 4 ? DisplayFrameFormat.Dmd4 : DisplayFrameFormat.Dmd2; - } + public static DisplayFrameFormat GetDisplayFrameFormat(PinMameDisplayLayout layout) + { + if (layout.IsDmd) { + return DisplayFrameFormat.Dmd8; + } switch (layout.Type) { case PinMameDisplayType.Seg8: // 7 segments and comma From 4908f942f2542a6987e5696a4eccfd108e172953 Mon Sep 17 00:00:00 2001 From: freezy Date: Sun, 29 Mar 2026 18:52:39 +0200 Subject: [PATCH 17/17] dep: Bump pinmame-dotnet to 1.0.2. --- .../VisualPinball.Engine.PinMAME.csproj | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj b/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj index bdd27f9..041653a 100644 --- a/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj +++ b/VisualPinball.Engine.PinMAME/VisualPinball.Engine.PinMAME.csproj @@ -5,7 +5,7 @@ false true 9.0 - 1.0.1 + 1.0.2 3.7.0-beta1