erik/acdream
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions 1

fix(diagnostics): keep UI scripts on game-loop time

Browse source 
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 <codex@openai.com>
This commit is contained in:
Erik 2026-07-19 16:38:49 +02:00
parent 3718e341be
commit b95bb3e21c
4 changed files with 336 additions and 15 deletions
Download patch file Download diff file Expand all files Collapse all files

53
docs/ISSUES.md
View file

@ -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`;

2
docs/plans/2026-04-11-roadmap.md
View file

@ -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.

59
src/AcDream.App/UI/Testing/RetailUiAutomationScriptRunner.cs
View file

@ -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 <milliseconds> | wait ms <milliseconds>");
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}");

237
tests/AcDream.App.Tests/UI/RetailUiAutomationProbeTests.cs
View file

@ -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>();
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>();
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>();
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>();
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>();
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>();
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>();
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);
}
}
}