diff --git a/docs/ISSUES.md b/docs/ISSUES.md index 34a46c70..2907c777 100644 --- a/docs/ISSUES.md +++ b/docs/ISSUES.md @@ -72,6 +72,52 @@ off-threading the per-landblock publication cost — NOT raising budgets line) is a profile SCALE of the same env-tunable options, so it is also already exonerated. Verify (a) first next session. +**2026-08-17 (later): 31 ms-per-admission hypothesis REFUTED by +measurement; the REAL limiter found and FIXED (this commit).** The probe +extension (`[publish-timing]` per-landblock per-stage attribution + +`[stream-tick]` per-second meter/yield/backlog rollups, same +`ACDREAM_PROBE_REVEAL_TIMING=1` env) measured: hold frame rate ~64 fps +(NOT ~32 — prediction (a) false), streaming tick at ~32 Hz (every other +render frame), per-landblock publication cost TINY (whole 625-block +window ≈ 500 ms CPU total; far blocks ~0.17 ms, near blocks 2–43 ms), +and steady state showed ZERO meter yields with ~0.22 ms of the 2.0 ms +budget used per tick — yet exactly one block published per tick with +~400 completions queued. **Root cause:** Runtime's collision-generation +activation is a deliberate TWO-POLL transaction +(`TryAcquireCollisionPrefixMutationPermission` parks residents and +refuses its first poll by design), and +`LandblockPresentationPipeline.Advance`'s metered arm returned +`Completed=false` on ANY nonterminal commit (`meter is not null || …`), +which `DrainAndApply` treats as "stop draining this frame" — one +landblock per 32 Hz tick = the flat 32/s, with the budget ~90% idle. +**Fix:** the metered arm now uses the same Runtime-owned gate the +unmetered arm and the synchronous `CompletePublication` API always used +(`CanContinueMutationSynchronously` — no pending prefix projections, +collision reports, or dispatch debt): the second poll runs in the same +frame under the same meter, so the authored 2 ms elapsed-time ceiling +(unchanged) is now genuinely the authoritative bound. With real debt +(live residents parked mid-game, pending withdrawals) Runtime keeps +reporting nonterminal-with-debt and publication defers to the next +frame exactly as before; regression test +`MeteredLoaded_NonterminalCommitWithoutDebt_CompletesInOneMeteredAdvance` +pins the debt-free single-advance completion. **Measured (this +binary):** loaded slope 32/s → bursts of 100–360/s (625/625 at ~6.1–7.1 +s vs ~22.9 s); `[stream-tick]` yields are now Time-limit yields at the +2 ms ceiling. A/B totals: **12689 / 12734 ms** (baseline +26728/27395/27503) — a 2.2x cut, but ABOVE the 12000 acceptance, and +the remainder is fully attributed: gate-ready at 8136/7617 ms (≈1 s +session+build start, ≈5 s drip at the authored 2 ms/tick destination +budget over ≈500 ms of real publication CPU at a 32 Hz tick, ≈0.4–1.2 s +destination-priority mesh uploads, ≈0.6 s composites), then retail's +AUTHORED tunnel exit (TunnelContinue min 2.0 s / max 5.0 s + two 1.0 s +view-plane fades, golden constants @0x007BD268/70/78 in +`TeleportAnimSequencer`) adds a tunnel-phase-dependent 3.1–6 s +(measured 4523 / 5086 ms) before `WorldViewportObserved`. Reaching +<12 s therefore requires either accepting ~12.7 s, or a LEAD decision +to widen the destination-lane time budget during the hold (a budget +change, out of scope per this round's constraints) — no artifact-shaped +limiter remains. + ## #417 — World ambience keeps playing (and re-firing) on the character-select screen after the in-world logoff **Status:** ✅ FIXED 2026-08-17 (logout-audio round; fix + tests in the same diff --git a/src/AcDream.App/Streaming/LandblockPresentationPipeline.cs b/src/AcDream.App/Streaming/LandblockPresentationPipeline.cs index 93c019ec..ab09145f 100644 --- a/src/AcDream.App/Streaming/LandblockPresentationPipeline.cs +++ b/src/AcDream.App/Streaming/LandblockPresentationPipeline.cs @@ -64,6 +64,13 @@ public sealed class LandblockPresentationPipeline public bool SpatialPresentationCommitted; public bool EnvCellReplayCommitted; public bool LiveRecoveryCommitted; + + /// + /// #418 measurement only (ACDREAM_PROBE_REVEAL_TIMING=1): the + /// per-stage wall-clock attribution of this one publication. Null + /// whenever the probe env is unset. + /// + public PublicationStageTimings? Timing; } private readonly Action? @@ -460,6 +467,7 @@ public sealed class LandblockPresentationPipeline Origin: completedBuild.Origin), meshData), Tier = LandblockStreamTier.Far, + Timing = PublicationTimingProbe.CreateTimings(), }; _publications.Add(acceptedResult, transaction); } @@ -509,6 +517,7 @@ public sealed class LandblockPresentationPipeline LandblockId = farLandblock.LandblockId, Cost = LandblockStreamResultCost.Estimate(farBuild, meshData), Tier = LandblockStreamTier.Far, + Timing = PublicationTimingProbe.CreateTimings(), }; _publications.Add(acceptedResult, transaction); } @@ -553,6 +562,7 @@ public sealed class LandblockPresentationPipeline Cost = estimate ?? LandblockStreamResultCost.Estimate(build, meshData), Tier = tier, + Timing = PublicationTimingProbe.CreateTimings(), }; _publications.Add(result, created); return created; @@ -565,6 +575,26 @@ public sealed class LandblockPresentationPipeline bool ensureProgress) { bool progressed = false; + void RunTimed(string stage, Action operation) + { + if (transaction.Timing is not { } timing) + { + operation(); + return; + } + + long start = System.Diagnostics.Stopwatch.GetTimestamp(); + try + { + operation(); + } + finally + { + timing.Add( + stage, + System.Diagnostics.Stopwatch.GetTimestamp() - start); + } + } bool TryRun( StreamingWorkCost cost, string stage, @@ -572,7 +602,7 @@ public sealed class LandblockPresentationPipeline { if (meter is null) { - operation(); + RunTimed(stage, operation); progressed = true; return true; } @@ -585,7 +615,7 @@ public sealed class LandblockPresentationPipeline return false; try { - operation(); + RunTimed(stage, operation); meter.Complete(); progressed = true; return true; @@ -810,8 +840,33 @@ public sealed class LandblockPresentationPipeline } if (transaction.PhysicsPublication.RuntimeMutationPending) { - if (meter is not null - || !_physicsPublisher + // #418: Runtime's collision-generation activation is a + // deliberate two-poll transaction — the first + // CommitCollisionGeneration poll closes the prefix + // quiescence boundary (parking any affected residents) + // and returns nonterminal; only a later poll may + // consume mutation permission. The metered path used + // to defer that later poll to the NEXT frame + // unconditionally, which serialized the whole + // completion drain to ONE landblock per streaming tick + // (DrainAndApply breaks on an incomplete publication): + // the measured login hold published exactly 32 + // blocks/s at a 32 Hz tick rate with ZERO meter + // yields and ~0.2 ms of its 2 ms budget used. Runtime + // explicitly supports consuming that finite suffix + // synchronously when it reports no cross-cutting debt + // (CanContinueMutationSynchronously — the same gate + // the unmetered path and the synchronous + // CompletePublication API already use), so the + // metered path now polls again within the same frame + // under the SAME meter: every extra poll still passes + // TryRun/TryReserve, so the elapsed-time budget + // remains the authoritative per-frame bound. With any + // real debt (live residents parked mid-game, pending + // withdrawals, dispatch backlog) Runtime keeps + // reporting nonterminal-with-debt and this defers to + // the next frame exactly as before. + if (!_physicsPublisher .CanContinueMutationSynchronously()) { return new LandblockPublicationAdvance( @@ -976,6 +1031,13 @@ public sealed class LandblockPresentationPipeline } _publications.Remove(result); + if (transaction.Timing is { } completedTiming) + { + PublicationTimingProbe.EmitPublication( + transaction.LandblockId, + transaction.Kind.ToString(), + completedTiming); + } return new LandblockPublicationAdvance(true, progressed); } } diff --git a/src/AcDream.App/Streaming/PublicationTimingProbe.cs b/src/AcDream.App/Streaming/PublicationTimingProbe.cs new file mode 100644 index 00000000..3183bbdd --- /dev/null +++ b/src/AcDream.App/Streaming/PublicationTimingProbe.cs @@ -0,0 +1,227 @@ +using System.Diagnostics; +using System.Text; + +namespace AcDream.App.Streaming; + +/// +/// Per-stage wall-clock accumulator for ONE landblock publication transaction +/// (#418 measurement). Created only when +/// is set; a null +/// instance on the transaction means the probe is off and costs one null +/// check per stage operation. +/// +internal sealed class PublicationStageTimings +{ + private readonly Dictionary _stages = new(); + private long _totalTicks; + + public long TotalTicks => _totalTicks; + + public void Add(string stage, long ticks) + { + if (ticks < 0) + ticks = 0; + _totalTicks += ticks; + _stages[stage] = _stages.TryGetValue(stage, out (long Ticks, int Count) prior) + ? (prior.Ticks + ticks, prior.Count + 1) + : (ticks, 1); + } + + public IReadOnlyDictionary Stages => _stages; +} + +/// +/// ACDREAM_PROBE_REVEAL_TIMING=1 sibling surface for issue #418: +/// attributes ONE admitted landblock's update-thread publication cost per +/// stage. Emits: +/// +/// +/// [publish-timing] lb=… — one line per completed landblock +/// publication with the total milliseconds and a per-stage +/// name:ms/count breakdown (stages sorted by cost). +/// [publish-timing] CUMULATIVE … — every 64 publications, the +/// running per-stage totals across all completed publications. +/// +/// +/// It also accumulates the per-frame streaming-tick elapsed time so +/// 's 1 Hz progress line can report how much +/// of each wall-clock second the streaming tick consumed (with the observed +/// render-frame count, this verifies or refutes the ~31 ms/frame +/// prediction). Diagnostic-only: no behavior change, never active unless the +/// probe env is set. All access happens on the window thread (the streaming +/// controller and render frame graph share it). +/// +internal static class PublicationTimingProbe +{ + private const int CumulativeEmitInterval = 64; + + private static readonly Dictionary + s_cumulativeStages = new(); + private static readonly Dictionary s_tickWindowYieldReasons = + new(); + private static long s_cumulativeTicks; + private static int s_publications; + private static double s_tickWindowSumMs; + private static double s_tickWindowMaxMs; + private static int s_tickWindowCount; + private static int s_tickWindowYields; + private static int s_tickWindowOperations; + private static int s_tickWindowAdmissions; + private static int s_lastWorkerBacklog; + private static int s_lastQueuedCompletions; + + public static bool Enabled => StreamingDiagnostics.ProbeRevealTiming; + + /// Per-transaction accumulator, or null when the probe is off. + public static PublicationStageTimings? CreateTimings() => + Enabled ? new PublicationStageTimings() : null; + + /// + /// Reports one completed landblock publication and folds its stages into + /// the cumulative rollup. + /// + public static void EmitPublication( + uint landblockId, + string kind, + PublicationStageTimings timings) + { + s_publications++; + s_cumulativeTicks += timings.TotalTicks; + var line = new StringBuilder(256); + line.Append("[publish-timing] lb=0x") + .Append(landblockId.ToString("X8")) + .Append(" kind=").Append(kind) + .Append(" totalMs=") + .Append(ToMs(timings.TotalTicks).ToString("F2")) + .Append(" stages="); + AppendStagesByCost(line, timings.Stages); + Console.WriteLine(line.ToString()); + + foreach ((string stage, (long ticks, int count)) in timings.Stages) + { + s_cumulativeStages[stage] = s_cumulativeStages.TryGetValue( + stage, + out (long Ticks, int Count) prior) + ? (prior.Ticks + ticks, prior.Count + count) + : (ticks, count); + } + + if (s_publications % CumulativeEmitInterval == 0) + EmitCumulative(); + } + + private static void EmitCumulative() + { + var line = new StringBuilder(256); + line.Append("[publish-timing] CUMULATIVE landblocks=") + .Append(s_publications) + .Append(" totalMs=") + .Append(ToMs(s_cumulativeTicks).ToString("F0")) + .Append(" stages="); + AppendStagesByCost(line, s_cumulativeStages); + Console.WriteLine(line.ToString()); + } + + private static void AppendStagesByCost( + StringBuilder line, + IReadOnlyDictionary stages) + { + bool first = true; + foreach ((string stage, (long ticks, int count)) in + stages.OrderByDescending(static pair => pair.Value.Ticks)) + { + if (!first) + line.Append(','); + first = false; + line.Append(TrimStagePrefix(stage)) + .Append(':') + .Append(ToMs(ticks).ToString("F2")) + .Append('/') + .Append(count); + } + } + + /// + /// Every pipeline stage name starts with publication-; dropping the + /// shared prefix keeps the per-landblock line readable. + /// + private static string TrimStagePrefix(string stage) => + stage.StartsWith("publication-", StringComparison.Ordinal) + ? stage["publication-".Length..] + : stage; + + /// + /// Records one frame into the + /// current 1 Hz reporting window: elapsed time, meter operation/yield + /// counts, admissions, the reason the meter last refused work, and the + /// end-of-tick worker/queue backlogs. + /// + public static void ObserveStreamingTick( + in StreamingWorkMeterSnapshot snapshot, + int workerBacklog, + int queuedCompletions) + { + s_tickWindowCount++; + s_tickWindowSumMs += snapshot.ElapsedMilliseconds; + if (snapshot.ElapsedMilliseconds > s_tickWindowMaxMs) + s_tickWindowMaxMs = snapshot.ElapsedMilliseconds; + s_tickWindowYields += snapshot.YieldCount; + s_tickWindowOperations += snapshot.Operations; + s_tickWindowAdmissions += snapshot.Used.CompletionAdmissions; + if (snapshot.YieldCount > 0 + && snapshot.LastLimit != StreamingWorkLimit.None + && snapshot.LastStage is { } stage) + { + string reason = $"{stage}/{snapshot.LastLimit}"; + s_tickWindowYieldReasons[reason] = + s_tickWindowYieldReasons.TryGetValue(reason, out int prior) + ? prior + 1 + : 1; + } + s_lastWorkerBacklog = workerBacklog; + s_lastQueuedCompletions = queuedCompletions; + } + + /// + /// Emits and resets the current streaming-tick reporting window as one + /// [stream-tick] line. Called by 's + /// 1 Hz progress path. + /// + public static void EmitStreamingTickWindow() + { + var line = new StringBuilder(192); + line.Append("[stream-tick] ticks=").Append(s_tickWindowCount) + .Append(" sumMs=").Append(s_tickWindowSumMs.ToString("F1")) + .Append(" maxMs=").Append(s_tickWindowMaxMs.ToString("F1")) + .Append(" ops=").Append(s_tickWindowOperations) + .Append(" yields=").Append(s_tickWindowYields) + .Append(" admissions=").Append(s_tickWindowAdmissions) + .Append(" workerBacklog=").Append(s_lastWorkerBacklog) + .Append(" queuedCompletions=").Append(s_lastQueuedCompletions) + .Append(" yieldReasons="); + bool first = true; + foreach ((string reason, int count) in + s_tickWindowYieldReasons.OrderByDescending( + static pair => pair.Value)) + { + if (!first) + line.Append(','); + first = false; + line.Append(reason).Append('x').Append(count); + } + if (first) + line.Append("none"); + Console.WriteLine(line.ToString()); + + s_tickWindowCount = 0; + s_tickWindowSumMs = 0; + s_tickWindowMaxMs = 0; + s_tickWindowYields = 0; + s_tickWindowOperations = 0; + s_tickWindowAdmissions = 0; + s_tickWindowYieldReasons.Clear(); + } + + private static double ToMs(long stopwatchTicks) => + stopwatchTicks * 1000.0 / Stopwatch.Frequency; +} diff --git a/src/AcDream.App/Streaming/RevealTimingProbe.cs b/src/AcDream.App/Streaming/RevealTimingProbe.cs index 2b2d9f7b..3dd942bb 100644 --- a/src/AcDream.App/Streaming/RevealTimingProbe.cs +++ b/src/AcDream.App/Streaming/RevealTimingProbe.cs @@ -47,6 +47,7 @@ internal sealed class RevealTimingProbe private long _gateReadyMs = -1; private long _materializedMs = -1; private long _lastProgressMs; + private int _framesSinceProgress; public RevealTimingProbe(Func? loadedLandblockCount) => _loadedLandblockCount = loadedLandblockCount; @@ -88,6 +89,7 @@ internal sealed class RevealTimingProbe if (_generation == 0 || portal.Generation != _generation) return; + _framesSinceProgress++; long elapsed = _clock.ElapsedMilliseconds; if (!_render && readiness.IsRenderNeighborhoodReady) { @@ -136,13 +138,21 @@ internal sealed class RevealTimingProbe if (!_summarized && elapsed - _lastProgressMs >= 1000) { _lastProgressMs = elapsed; + // #418: frames = render frames observed since the previous + // progress line (the hold's effective frame rate). The paired + // [stream-tick] line carries the same window's streaming-tick + // wall clock, meter operation/yield/admission counts, backlogs, + // and the reasons the meter refused work. Console.WriteLine( $"[reveal-timing] elapsedMs={elapsed} " + $"render={(_render ? 1 : 0)} " + $"composites={(_composites ? 1 : 0)} " + $"collision={(_collision ? 1 : 0)} " + $"loaded={_loadedLandblockCount?.Invoke() ?? -1}" - + $"/{_windowLandblocks}"); + + $"/{_windowLandblocks} " + + $"frames={_framesSinceProgress}"); + PublicationTimingProbe.EmitStreamingTickWindow(); + _framesSinceProgress = 0; } } diff --git a/src/AcDream.App/Streaming/StreamingController.cs b/src/AcDream.App/Streaming/StreamingController.cs index d7938138..998410db 100644 --- a/src/AcDream.App/Streaming/StreamingController.cs +++ b/src/AcDream.App/Streaming/StreamingController.cs @@ -778,6 +778,13 @@ public sealed class StreamingController ObserveWorkLifetime(snapshot); _lastWorkMeter = snapshot; _activeWorkMeter = null; + if (PublicationTimingProbe.Enabled) + { + PublicationTimingProbe.ObserveStreamingTick( + snapshot, + _completionSource.BacklogCount, + _completionQueue.Count); + } } } diff --git a/tests/AcDream.App.Tests/Streaming/LandblockConcretePresentationPipelineTests.cs b/tests/AcDream.App.Tests/Streaming/LandblockConcretePresentationPipelineTests.cs index ec709125..d91c40fe 100644 --- a/tests/AcDream.App.Tests/Streaming/LandblockConcretePresentationPipelineTests.cs +++ b/tests/AcDream.App.Tests/Streaming/LandblockConcretePresentationPipelineTests.cs @@ -171,6 +171,57 @@ public sealed class LandblockConcretePresentationPipelineTests Assert.True(fixture.State.IsLoaded(LandblockId)); } + [Fact] + public void MeteredLoaded_NonterminalCommitWithoutDebt_CompletesInOneMeteredAdvance() + { + // #418: Runtime's collision-generation activation deliberately + // refuses its FIRST CommitCollisionGeneration poll (the quiescence + // boundary parks residents and returns nonterminal). The metered + // pipeline used to defer the second poll to the next frame + // unconditionally, which serialized the login completion drain to + // exactly one landblock per streaming tick (the flat 32 blocks/s + // hold). With no cross-cutting debt the second poll must now run in + // the SAME metered advance, so a whole publication completes in one + // frame when the budget allows it. + var calls = new List(); + ConcreteFixture fixture = Fixture( + calls, + commitEnvCells: _ => calls.Add("envcell")); + var pipeline = new LandblockPresentationPipeline( + fixture.Render, + fixture.Physics, + fixture.Static, + fixture.State, + fixture.RetirementOwner, + onLandblockLoaded: _ => calls.Add("live-recovery")); + LandblockStreamResult.Loaded result = + Result(Build(Entity(0x80A9B401u))); + LandblockStreamCostEstimate estimate = + LandblockStreamResultCost.Estimate(result); + var budget = new StreamingWorkBudget( + TimeSpan.FromSeconds(1), + maxCompletionAdmissions: 64, + maxAdoptedCpuBytes: 1_000_000, + maxEntityOperations: 4_096, + maxGpuUploadBytes: 1_000_000, + maxGlRetireOperations: 64, + destinationReserveFraction: 0.75f); + var meter = new StreamingWorkMeter(budget); + + LandblockPublicationAdvance advance = pipeline.PublishLoaded( + result, + estimate, + meter, + ensureProgress: true); + meter.FinishFrame(); + + Assert.True(advance.Completed); + Assert.False(pipeline.HasPendingPublication(result)); + Assert.True(fixture.State.IsNearTier(LandblockId)); + Assert.Equal(1, fixture.Physics.Diagnostics.CompleteCount); + Assert.Equal(1, fixture.Static.Diagnostics.CompleteCount); + } + [Fact] public void CrossOwnerValidationFailure_BlocksBeforeAnyPresentationMutation() {