From b95bb3e21c277f23d3291e7d35c4567ed8b42493 Mon Sep 17 00:00:00 2001 From: Erik Date: Sun, 19 Jul 2026 16:38:49 +0200 Subject: [PATCH] fix(diagnostics): keep UI scripts on game-loop time Preserve sub-millisecond frame deltas with a command-local compensated clock so uncapped diagnostic routes do not outrun materialization and settling. Keep sleep boundaries inclusive, wait timeouts strict, and handle long-duration and invalid-delta cases deterministically. Record the aligned seven-destination connected route with a full turn at every stop. Release build succeeds and all 6,308 tests pass with five intentional skips. Co-authored-by: OpenAI Codex --- docs/ISSUES.md | 53 +++- docs/plans/2026-04-11-roadmap.md | 2 +- .../Testing/RetailUiAutomationScriptRunner.cs | 59 ++++- .../UI/RetailUiAutomationProbeTests.cs | 237 ++++++++++++++++++ 4 files changed, 336 insertions(+), 15 deletions(-) diff --git a/docs/ISSUES.md b/docs/ISSUES.md index 09e7ce07..47006cc8 100644 --- a/docs/ISSUES.md +++ b/docs/ISSUES.md @@ -126,18 +126,51 @@ stable radix, avoiding a second immediate-buffer pack for deferred transparent instances, packing per-instance light sets, caching static picking descriptors, and using checked direct group handles. Historical material groups now retire after one complete unused frame (not after one `Draw`, because landscape slices -and paperdoll share the dispatcher) and release their list capacity. That dense -sample reached roughly 5.3–6.2 ms CPU / 7.1–8.3 ms p95 and 3.2–3.6 ms GPU before -the final group-retirement review correction. +and paperdoll share the dispatcher) and release their list capacity. Before the +final group-retirement review correction, that fixed dense sample reached +5.3–6.2 ms CPU p50, 7.1–8.3 ms CPU p95, and 3.2–3.6 ms GPU p50. The earlier software limiter also used coarse `Thread.Sleep`, whose nominal one-millisecond waits measured about 15.98 ms on this host. A reusable Windows high-resolution waitable timer now paces to the monitor deadline and is reported as `pace` by the frame profiler. Scripted UI automation no longer enables the allocation-heavy GPU-stream dump implicitly, and graceful shutdown now wakes -all persistent mesh workers without resetting their shared wake signal. The -post-review connected stress rerun remains pending because local ACE was not -listening; sparse-scene 239 FPS samples are not substituted for that gate. +all persistent mesh workers without resetting their shared wake signal. The UI +automation clock now uses command-local compensated accumulation, retaining +sub-millisecond frame deltas instead of rounding every uncapped frame up to one +millisecond. Exact sleep and strict timeout boundaries therefore remain stable +across high-refresh frames and long scripts. + +The post-review connected rerun passed on 2026-07-19. It used the complete +Caul → Sawato → Rynthid → Aerlinthe → Sawato → Holtburg → Caul route, waited for +each actual materialization, allowed at least five seconds of destination +streaming, synchronized to the next profiler boundary, and then held the retail +turn-right action through one dedicated interval (4.93–5.07 seconds, more than +one full visibility sweep) at every stop. Each +turn window and its following stationary window were captured on separate +profiler boundaries. The uncapped Release client completed all seven portals +and seven turns and shut down gracefully, with no exception, WER report, or AMD +driver reset observed in the process logs, Windows event logs, or crash-dump +directory. Returned dense Caul contained about 21,024 visible entities and +measured 3.8 ms median / 5.0 ms p95 CPU and 2.6 ms median / 3.2 ms p95 GPU while +stationary (241 FPS in the title sample). Its complete turning window measured +3.0 ms median / 4.9 ms p95 CPU and 2.0 ms median / 3.4 ms p95 GPU. + +Across all stationary destinations, CPU p50/p95 ranged from 1.1–4.0 / +1.6–5.1 ms and GPU p50/p95 from 0.7–2.8 / 1.0–3.4 ms. Across the turn +windows, those ranges were 1.0–3.1 / 1.8–4.9 ms CPU and +0.7–2.0 / 1.2–3.4 ms GPU. Working/private memory was 939.8/1,438.3 MiB on the +first Caul dwell; the highest stationary sample was 1,065.0/1,660.6 MiB in +Holtburg, followed by 1,034.8/1,630.5 MiB on the Caul return. The samples were +non-monotonic, but one circuit is not claimed as a new lifetime plateau proof. +Startup reached a transient 240.2 ms maximum, and the largest later +destination-load window reached 81.9 ms CPU; all isolated turn and stationary +windows recovered to low-millisecond frame times, so this run is not described +as stall-free. + +The run was performed over RDP, but software pacing was explicitly disabled and +`pace` remained zero, so these are engine-throughput measurements rather than +remote-display refresh measurements. The lifestone/particle visual gate remains. **Files:** `src/AcDream.App/Rendering/RetailAlphaQueue.cs`; `src/AcDream.App/Rendering/Wb/WbDrawDispatcher.cs`; @@ -153,7 +186,13 @@ listening; sparse-scene 239 FPS samples are not substituted for that gate. `src/AcDream.Content/BoundedDatObjectCache.cs`; `src/AcDream.Content/DecodedTextureCache.cs`; `src/AcDream.App/Rendering/FramePacingController.cs`; -`src/AcDream.App/Rendering/WindowsHighResolutionFramePacingWaiter.cs`. +`src/AcDream.App/Rendering/WindowsHighResolutionFramePacingWaiter.cs`; +`src/AcDream.App/Diagnostics/FrameProfiler.cs`; +`src/AcDream.App/Rendering/GameWindow.cs`; +`src/AcDream.App/Rendering/Wb/ObjectMeshManager.cs`; +`src/AcDream.App/Rendering/Wb/CachedBatch.cs`; +`src/AcDream.App/Rendering/Wb/EntityClassificationCache.cs`; +`src/AcDream.App/UI/Testing/RetailUiAutomationScriptRunner.cs`. **Research:** `docs/research/2026-07-18-retail-shared-alpha-list-pseudocode.md`; diff --git a/docs/plans/2026-04-11-roadmap.md b/docs/plans/2026-04-11-roadmap.md index c6c2d898..6141d66b 100644 --- a/docs/plans/2026-04-11-roadmap.md +++ b/docs/plans/2026-04-11-roadmap.md @@ -562,7 +562,7 @@ behavior. Estimated 17–26 days focused work, 3–5 weeks calendar. - **Missile/portal VFX campaign Step 9 automated hardening implemented and independently reviewed 2026-07-14; final two-client visual gate pending.** A deterministic 96-owner App fixture drives canonical missiles and effect owners through projectile updates, repeated DAT-effect scheduling, loaded↔pending↔loaded landblock churn, light/particle withdrawal and recovery, accepted deletes, same-GUID generation reuse, never-created F754 queues, and session reset. It asserts balanced logical render registration and zero residual records/bodies/projectiles, spatial buckets/rescues, shadows (including suspended registrations), effect profiles/packets, PhysicsScript FIFOs/anchors/delayed calls, particle bindings/logical IDs/render-pass owners, poses, light-controller/sink/manager owners, and stale record component references. A companion twelve-cycle gate drives exact recall motion `0x10000153` through AnimationSequencer/CallPES, Hidden, deferred remote placement, hydration, and UnHide; a second 96-owner `EntitySpawnAdapter` gate balances actual mesh-adapter reference counts without GL. The pass fixed undrained persistent rescue retention, delayed stale visibility edges, GUID-scoped teardown, create resurrection after a nested delete/reset, non-atomic resource registration, double teardown from a re-entrant session-clear callback, observer failure stranding later visibility edges, and stale outer projection transactions overwriting callback-created replacements. Teardown now removes exact projection references and generation/local-ID owners, uses per-GUID/session lifetime epochs plus per-record projection tokens, drains visibility fan-out before aggregating failures, and finishes or supersedes canonical commits before surfacing observer errors. Core remains GL/backend-free, panels remain on UI abstractions, and projectiles still draw through ordinary `WbDrawDispatcher` live-entity submission rather than a global projectile pass. AP-69 and TS-49 remain; AP-83/AP-91 now explicitly describe only a future mover that enables PerfectClip. - **Portal/resource lifetime correction 2026-07-18; connected stress gate passed, final visual gate pending.** `LiveEntityLivenessController` ports retail's 25-second leave-visibility destruction queue over canonical live records, cancels expiry for spatially resident or owned objects, and uses holtburger's conservative 384-unit envelope where ACE supplies no client-visible PVS leave event. The broader integration balances generation-scoped appearance/live/landblock/effect/UI/portal owners, bounds DAT/decoded/standalone/composite/atlas/mesh residency, performs incremental mesh-arena migration, and defers GL deletion or slot reuse through three frames of GPU fences. Render/UI scratch storage is reused with hysteretic trimming. No visual range or quality setting was reduced. The final seven-destination connected route cut peak working/private memory from 2,954.5/3,502.3 MiB to 1,493.4/1,969.5 MiB, returned Caul to 1,030.6/1,638.2 MiB, held 125–153 FPS locally through the final dwell, and produced no WER/driver reset. AP-69 is narrowed rather than retired because exact ObjCell PVS and explicit preview lifetimes remain. -- **Render-thread CPU and high-refresh pacing correction 2026-07-19; automated/review gates passed, connected rerun pending.** Software pacing now uses one reusable Windows high-resolution waitable timer instead of scheduler-quantized `Thread.Sleep`; the permanent profiler attributes that wait as `pace`. Wb keeps exact stable far-to-near alpha order while using a radix key, avoids immediate SSBO packing for deferred transparent objects, packs each eight-light set, caches immutable selection descriptors, and retires historical material groups only after one complete unused frame across every landscape/dynamics/paperdoll draw scope. A fixed dense-Caul sample improved from roughly 9–12 ms CPU to 5.3–6.2 ms without reducing view distance, particles, textures, streaming radius, or other quality. The prior 141.8 FPS result remains scene-specific; local ACE was offline for the post-review connected rerun. +- **Render-thread CPU and high-refresh pacing correction 2026-07-19; automated/review/connected gates passed, final translucency visual gate pending.** Software pacing now uses one reusable Windows high-resolution waitable timer instead of scheduler-quantized `Thread.Sleep`; the permanent profiler attributes that wait as `pace`. Wb keeps exact stable far-to-near alpha order while using a radix key, avoids immediate SSBO packing for deferred transparent objects, packs each eight-light set, caches immutable selection descriptors, and retires historical material groups only after one complete unused frame across every landscape/dynamics/paperdoll draw scope. A fixed dense-Caul sample improved from roughly 9–12 ms CPU to 5.3–6.2 ms without reducing view distance, particles, textures, streaming radius, or other quality. The corrected post-review uncapped route waited for every materialization and held a full visibility sweep through one dedicated profiler window at all seven destinations. Returned dense Caul (about 21,024 visible entities) measured 3.0/4.9 ms CPU p50/p95 and 2.0/3.4 ms GPU while turning, then 3.8/5.0 ms CPU and 2.6/3.2 ms GPU stationary (241 FPS title sample). First/return Caul memory was 939.8/1,438.3 and 1,034.8/1,630.5 MiB working/private; the highest stationary sample was 1,065.0/1,660.6 MiB in Holtburg, and the client exited gracefully. With pacing disabled (`pace=0`) and title samples reaching 844 FPS, RDP did not refresh-cap engine throughput. UI automation now uses a command-local compensated clock, preserving sub-millisecond frame deltas and exact long-duration sleep/timeout boundaries. **Reference docs:** `docs/research/retail-ui/00-master-synthesis.md` + slices 01-06. Every AC-specific behavior has a decompiled FUN_ / DAT_ citation. diff --git a/src/AcDream.App/UI/Testing/RetailUiAutomationScriptRunner.cs b/src/AcDream.App/UI/Testing/RetailUiAutomationScriptRunner.cs index 65f43ea6..762c257c 100644 --- a/src/AcDream.App/UI/Testing/RetailUiAutomationScriptRunner.cs +++ b/src/AcDream.App/UI/Testing/RetailUiAutomationScriptRunner.cs @@ -22,8 +22,8 @@ public sealed class RetailUiAutomationScriptRunner private readonly string? _loadError; private int _index; private int _activeIndex = -1; - private long _elapsedMs; - private long _commandStartMs; + private double _commandElapsedMs; + private double _commandElapsedCompensationMs; private bool _started; private bool _completed; @@ -65,8 +65,27 @@ public sealed class RetailUiAutomationScriptRunner { if (_completed) return; - long addMs = Math.Max(1, (long)Math.Round(deltaSeconds * 1000.0)); - _elapsedMs += addMs; + // Preserve sub-millisecond frame deltas. Rounding every uncapped frame + // up to one millisecond makes script time run several times faster than + // wall/game-loop time in light scenes and portal space. + if (double.IsFinite(deltaSeconds) && deltaSeconds > 0d) + { + double addMs = deltaSeconds * 1000d; + double adjustedMs = addMs - _commandElapsedCompensationMs; + double nextElapsedMs = _commandElapsedMs + adjustedMs; + double nextCompensationMs = (nextElapsedMs - _commandElapsedMs) - adjustedMs; + if (_activeIndex == _index && + double.IsFinite(addMs) && + double.IsFinite(nextElapsedMs) && + double.IsFinite(nextCompensationMs)) + { + // Kahan summation keeps long fractional-frame waits on their + // exact boundary instead of accumulating cadence-dependent + // drift over tens of minutes. + _commandElapsedMs = nextElapsedMs; + _commandElapsedCompensationMs = nextCompensationMs; + } + } if (!_started) { @@ -96,7 +115,10 @@ public sealed class RetailUiAutomationScriptRunner if (_activeIndex != _index) { _activeIndex = _index; - _commandStartMs = _elapsedMs; + // Command-local time avoids losing precision when a diagnostic + // script has already run for minutes or hours. + _commandElapsedMs = 0d; + _commandElapsedCompensationMs = 0d; } var command = _commands[_index]; @@ -233,7 +255,7 @@ public sealed class RetailUiAutomationScriptRunner : p.Length >= 2 ? p[1] : ""; if (!TryParseInt(value, out int ms) || ms < 0) return Stop(command, "usage: sleep | wait ms "); - return _elapsedMs - _commandStartMs >= ms; + return HasElapsed(ms); } private bool DoAssert(ScriptCommand command) @@ -282,10 +304,33 @@ public sealed class RetailUiAutomationScriptRunner private bool WaitOrTimeout(ScriptCommand command, int timeoutMs, string label) { - if (_elapsedMs - _commandStartMs <= timeoutMs) return false; + if (!HasExceeded(timeoutMs)) return false; return Stop(command, $"timed out waiting for {label}"); } + private bool HasElapsed(int durationMs) + { + double elapsedMs = _commandElapsedMs; + if (!double.IsFinite(elapsedMs)) return false; + if (elapsedMs >= durationMs) return true; + + // Repeated fractional frame deltas can land a few representable + // doubles below an exact integer-millisecond deadline (for example, + // sixty 1/60-second frames). Treat only machine-scale drift as equal; + // this tolerance is far below any observable script or frame interval. + return durationMs - elapsedMs <= TimingToleranceMs(durationMs); + } + + private bool HasExceeded(int durationMs) + { + double elapsedMs = _commandElapsedMs; + if (!double.IsFinite(elapsedMs) || elapsedMs <= durationMs) return false; + return elapsedMs - durationMs > TimingToleranceMs(durationMs); + } + + private static double TimingToleranceMs(int durationMs) + => Math.Max(1e-9d, Math.Abs(durationMs) * 1e-12d); + private bool Stop(ScriptCommand command, string message) { _log($"line {command.LineNumber}: {message}; command: {command.Text}"); diff --git a/tests/AcDream.App.Tests/UI/RetailUiAutomationProbeTests.cs b/tests/AcDream.App.Tests/UI/RetailUiAutomationProbeTests.cs index d3ec1a51..8ec20467 100644 --- a/tests/AcDream.App.Tests/UI/RetailUiAutomationProbeTests.cs +++ b/tests/AcDream.App.Tests/UI/RetailUiAutomationProbeTests.cs @@ -204,4 +204,241 @@ public sealed class RetailUiAutomationProbeTests File.Delete(path); } } + + [Fact] + public void ScriptRunner_sleep_preserves_fractional_uncapped_frame_time() + { + var (root, _, _, _, objects) = RootWithTwoItemLists(); + var probe = new RetailUiAutomationProbe(root, objects); + var submitted = new List(); + string path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".ui-probe.txt"); + File.WriteAllLines(path, ["sleep 10", "command /ls"]); + + try + { + var runner = new RetailUiAutomationScriptRunner( + probe, + path, + dumpOnStart: false, + submitCommand: submitted.Add); + + runner.Tick(0d); // Arm the sleep at script time zero. + for (int i = 0; i < 1_000; i++) + runner.Tick(0.000001); // 1 ms total, not the old artificial 1,000 ms. + + Assert.Empty(submitted); + Assert.False(runner.Completed); + + runner.Tick(0.009); // Exact 10 ms deadline, including the 1 ms above. + + Assert.Equal(["/ls"], submitted); + Assert.True(runner.Completed); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public void ScriptRunner_sleep_releases_on_exact_fractional_frame_deadline() + { + var (root, _, _, _, objects) = RootWithTwoItemLists(); + var probe = new RetailUiAutomationProbe(root, objects); + var submitted = new List(); + string path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".ui-probe.txt"); + File.WriteAllLines(path, ["sleep 1000", "command /ls"]); + + try + { + var runner = new RetailUiAutomationScriptRunner( + probe, + path, + dumpOnStart: false, + submitCommand: submitted.Add); + + runner.Tick(0d); // Arm the sleep at script time zero. + for (int i = 0; i < 60; i++) + runner.Tick(1d / 60d); + + Assert.Equal(["/ls"], submitted); + Assert.True(runner.Completed); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public void ScriptRunner_sleep_rebases_fractional_clock_after_long_prior_command() + { + var (root, _, _, _, objects) = RootWithTwoItemLists(); + var probe = new RetailUiAutomationProbe(root, objects); + var submitted = new List(); + string path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".ui-probe.txt"); + File.WriteAllLines(path, ["sleep 1000000", "sleep 1000", "command /ls"]); + + try + { + var runner = new RetailUiAutomationScriptRunner( + probe, + path, + dumpOnStart: false, + submitCommand: submitted.Add); + + runner.Tick(0d); + runner.Tick(1000d); // Complete the 1,000,000 ms precursor and arm the next sleep. + for (int i = 0; i < 60; i++) + runner.Tick(1d / 60d); + + Assert.Equal(["/ls"], submitted); + Assert.True(runner.Completed); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public void ScriptRunner_sleep_ignores_invalid_or_overflowing_frame_deltas() + { + var (root, _, _, _, objects) = RootWithTwoItemLists(); + var probe = new RetailUiAutomationProbe(root, objects); + var submitted = new List(); + string path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".ui-probe.txt"); + File.WriteAllLines(path, ["sleep 1", "command /ls"]); + + try + { + var runner = new RetailUiAutomationScriptRunner( + probe, + path, + dumpOnStart: false, + submitCommand: submitted.Add); + + runner.Tick(0d); + runner.Tick(double.NaN); + runner.Tick(double.PositiveInfinity); + runner.Tick(double.NegativeInfinity); + runner.Tick(double.MaxValue); // Finite input whose millisecond conversion overflows. + runner.Tick(-1d); + + Assert.Empty(submitted); + Assert.False(runner.Completed); + + runner.Tick(0.001d); + + Assert.Equal(["/ls"], submitted); + Assert.True(runner.Completed); + } + finally + { + File.Delete(path); + } + } + + [Theory] + [InlineData(30)] + [InlineData(120)] + public void ScriptRunner_wait_timeout_does_not_fire_on_exact_fractional_deadline(int framesPerSecond) + { + var (root, _, _, _, objects) = RootWithTwoItemLists(); + var probe = new RetailUiAutomationProbe(root, objects); + var logs = new List(); + string path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".ui-probe.txt"); + File.WriteAllLines(path, ["sleep 1000000", "wait item 0xDEAD inventory 1000"]); + + try + { + var runner = new RetailUiAutomationScriptRunner( + probe, + path, + dumpOnStart: false, + log: logs.Add); + + runner.Tick(0d); + runner.Tick(1000d); // Complete the precursor and arm the wait at a rebased zero. + for (int i = 0; i < framesPerSecond; i++) + runner.Tick(1d / framesPerSecond); + + Assert.False(runner.Completed); + Assert.DoesNotContain(logs, line => line.Contains("timed out", StringComparison.Ordinal)); + + runner.Tick(1d / framesPerSecond); + + Assert.True(runner.Completed); + Assert.Contains(logs, line => line.Contains("timed out", StringComparison.Ordinal)); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public void ScriptRunner_one_hour_sleep_releases_on_exact_60Hz_deadline() + { + var (root, _, _, _, objects) = RootWithTwoItemLists(); + var probe = new RetailUiAutomationProbe(root, objects); + var submitted = new List(); + string path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".ui-probe.txt"); + File.WriteAllLines(path, ["sleep 3600000", "command /ls"]); + + try + { + var runner = new RetailUiAutomationScriptRunner( + probe, + path, + dumpOnStart: false, + submitCommand: submitted.Add); + + runner.Tick(0d); + for (int i = 0; i < 60 * 60 * 60; i++) + runner.Tick(1d / 60d); + + Assert.Equal(["/ls"], submitted); + Assert.True(runner.Completed); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public void ScriptRunner_one_hour_wait_does_not_timeout_on_exact_30Hz_deadline() + { + var (root, _, _, _, objects) = RootWithTwoItemLists(); + var probe = new RetailUiAutomationProbe(root, objects); + var logs = new List(); + string path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".ui-probe.txt"); + File.WriteAllText(path, "wait item 0xDEAD inventory 3600000"); + + try + { + var runner = new RetailUiAutomationScriptRunner( + probe, + path, + dumpOnStart: false, + log: logs.Add); + + runner.Tick(0d); + for (int i = 0; i < 30 * 60 * 60; i++) + runner.Tick(1d / 30d); + + Assert.False(runner.Completed); + Assert.DoesNotContain(logs, line => line.Contains("timed out", StringComparison.Ordinal)); + + runner.Tick(1d / 30d); + + Assert.True(runner.Completed); + Assert.Contains(logs, line => line.Contains("timed out", StringComparison.Ordinal)); + } + finally + { + File.Delete(path); + } + } }