probe: ACDREAM_PROBE_REVEAL_TIMING — wall-clock attribution of the login/portal hold

[reveal-timing] lines from the reveal coordinator: per-dimension
first-ready edges (render neighborhood, composite textures, collision,
gate, materialization), 1 Hz progress with the resident-landblock count
(new GpuWorldState.LoadedLandblockCount), and one SUMMARY line at the
viewport reveal. Measurement-first groundwork for the login-load speedup:
the readiness barrier observes its dimensions serially, so the edges give
each dimension's observed tail while the progress lines expose the
pacing shape (a budget-paced linear drip reads directly off the counts).
Probe-gated in StreamingDiagnostics per Code Structure Rules §5; no
behavior change, one branch per Evaluate poll when unset.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Erik 2026-08-17 19:04:15 +02:00
parent 0bb47f2711
commit 695a27b48a
5 changed files with 190 additions and 2 deletions

View file

@ -425,7 +425,8 @@ internal sealed class SessionPlayerCompositionPhase
spawnClaimClassifier.IsUnhydratable,
worldQuiescence,
streaming,
revealRenderResources);
revealRenderResources,
() => live.WorldState.LoadedLandblockCount);
Fault(SessionPlayerCompositionPoint.WorldRevealCreated);
return CompleteSessionPlayer(

View file

@ -198,6 +198,10 @@ public sealed class GpuWorldState : ILiveEntitySpatialQuery
/// that need to enumerate entities before the landblock is dropped
/// (e.g. unregistering dynamic lights on a RemoveLandblock).
/// </summary>
/// <summary>Resident landblock count — reveal-timing probe progress
/// lines only (<see cref="RevealTimingProbe"/>).</summary>
public int LoadedLandblockCount => _loaded.Count;
public bool TryGetLandblock(uint landblockId, out LoadedLandblock? lb)
{
if (_loaded.TryGetValue(landblockId, out var found))

View file

@ -0,0 +1,155 @@
using System.Diagnostics;
using AcDream.Runtime;
namespace AcDream.App.Streaming;
/// <summary>
/// <c>ACDREAM_PROBE_REVEAL_TIMING=1</c> (see
/// <see cref="StreamingDiagnostics.ProbeRevealTiming"/>): wall-clock
/// attribution of one login/portal hold. Emits <c>[reveal-timing]</c> lines:
///
/// <list type="bullet">
/// <item><c>event=begin</c> — the hold starts, with the required window and
/// its landblock count.</item>
/// <item><c>event=render-ready / composites-ready / collision-ready /
/// gate-ready / materialized</c> — first-true edges with elapsed ms. The
/// readiness barrier OBSERVES the dimensions serially (composites are only
/// evaluated once render is ready, collision once both are), so each edge's
/// delta over the previous one is that dimension's observed TAIL, not its
/// total concurrent cost — the progress lines carry the concurrency
/// shape.</item>
/// <item>1 Hz progress — elapsed, the three flags, and the resident
/// landblock count, so a budget-paced linear drip is visually obvious in the
/// log.</item>
/// <item><c>SUMMARY</c> once at the viewport reveal — the per-edge
/// timeline on one line.</item>
/// </list>
///
/// Diagnostic-only: never constructed unless the probe env is set, changes
/// no behavior, and costs one branch per <c>Evaluate</c> poll otherwise.
/// </summary>
internal sealed class RevealTimingProbe
{
private readonly Func<int>? _loadedLandblockCount;
private readonly Stopwatch _clock = new();
private long _generation;
private string _kind = "";
private int _windowLandblocks;
private bool _render;
private bool _composites;
private bool _collision;
private bool _gateReady;
private bool _materialized;
private bool _summarized;
private long _renderMs = -1;
private long _compositesMs = -1;
private long _collisionMs = -1;
private long _gateReadyMs = -1;
private long _materializedMs = -1;
private long _lastProgressMs;
public RevealTimingProbe(Func<int>? loadedLandblockCount) =>
_loadedLandblockCount = loadedLandblockCount;
public void Begin(
string kind,
long generation,
uint destinationCell,
in StreamingRevealWindow window)
{
_generation = generation;
_kind = kind;
int side = window.FarRadius * 2 + 1;
_windowLandblocks = side * side;
_render = false;
_composites = false;
_collision = false;
_gateReady = false;
_materialized = false;
_summarized = false;
_renderMs = -1;
_compositesMs = -1;
_collisionMs = -1;
_gateReadyMs = -1;
_materializedMs = -1;
_lastProgressMs = 0;
_clock.Restart();
Console.WriteLine(
$"[reveal-timing] event=begin kind={kind} gen={generation} "
+ $"cell=0x{destinationCell:X8} window={window.NearRadius}/"
+ $"{window.FarRadius} landblocks={_windowLandblocks} "
+ $"loaded={_loadedLandblockCount?.Invoke() ?? -1}");
}
public void Observe(
in WorldRevealReadinessSnapshot readiness,
in RuntimePortalSnapshot portal)
{
if (_generation == 0 || portal.Generation != _generation)
return;
long elapsed = _clock.ElapsedMilliseconds;
if (!_render && readiness.IsRenderNeighborhoodReady)
{
_render = true;
_renderMs = elapsed;
Edge("render-ready", elapsed);
}
if (!_composites && readiness.AreCompositeTexturesReady)
{
_composites = true;
_compositesMs = elapsed;
Edge("composites-ready", elapsed);
}
if (!_collision && readiness.IsCollisionReady)
{
_collision = true;
_collisionMs = elapsed;
Edge("collision-ready", elapsed);
}
if (!_gateReady && readiness.IsReady)
{
_gateReady = true;
_gateReadyMs = elapsed;
Edge("gate-ready", elapsed);
}
if (!_materialized && portal.Materialized)
{
_materialized = true;
_materializedMs = elapsed;
Edge("materialized", elapsed);
}
if (!_summarized && portal.WorldViewportObserved)
{
_summarized = true;
Console.WriteLine(
$"[reveal-timing] SUMMARY kind={_kind} gen={_generation} "
+ $"totalMs={elapsed} renderMs={_renderMs} "
+ $"compositesMs={_compositesMs} collisionMs={_collisionMs} "
+ $"gateReadyMs={_gateReadyMs} "
+ $"materializedMs={_materializedMs} "
+ $"landblocks={_windowLandblocks}");
return;
}
if (!_summarized && elapsed - _lastProgressMs >= 1000)
{
_lastProgressMs = elapsed;
Console.WriteLine(
$"[reveal-timing] elapsedMs={elapsed} "
+ $"render={(_render ? 1 : 0)} "
+ $"composites={(_composites ? 1 : 0)} "
+ $"collision={(_collision ? 1 : 0)} "
+ $"loaded={_loadedLandblockCount?.Invoke() ?? -1}"
+ $"/{_windowLandblocks}");
}
}
private void Edge(string name, long elapsed) =>
Console.WriteLine(
$"[reveal-timing] event={name} kind={_kind} gen={_generation} "
+ $"elapsedMs={elapsed} "
+ $"loaded={_loadedLandblockCount?.Invoke() ?? -1}"
+ $"/{_windowLandblocks}");
}

View file

@ -51,6 +51,19 @@ internal static class StreamingDiagnostics
far);
}
/// <summary>
/// Login-load measurement probe (2026-08-17): when set, the reveal
/// coordinator emits a <c>[reveal-timing]</c> wall-clock timeline for
/// every login/portal hold — per-dimension first-ready edges
/// (render neighborhood, composite textures, collision), 1 Hz progress
/// with the resident-landblock count, and one summary line at the
/// viewport reveal — so optimization targets the measured dominant
/// phase instead of a guess. Diagnostic-only: not a user setting, not
/// persisted, no behavior change.
/// </summary>
public static bool ProbeRevealTiming { get; } =
Environment.GetEnvironmentVariable("ACDREAM_PROBE_REVEAL_TIMING") == "1";
/// <summary>
/// The floor is 1, not 0. An outdoor destination's acknowledgement must
/// carry <c>RequiredRenderRadius &gt;= 1</c> or

View file

@ -68,6 +68,7 @@ internal sealed class WorldRevealCoordinator
private readonly IWorldRevealStreamingScheduler? _streaming;
private readonly IWorldRevealRenderResourceScheduler? _renderResources;
private readonly List<HostProjection> _hostProjections = [];
private readonly RevealTimingProbe? _timing;
private bool _hostRetryActive;
private bool _hostRetryRequested;
@ -83,7 +84,8 @@ internal sealed class WorldRevealCoordinator
Func<uint, bool> isSpawnClaimUnhydratable,
WorldGenerationQuiescence? quiescence = null,
IWorldRevealStreamingScheduler? streaming = null,
IWorldRevealRenderResourceScheduler? renderResources = null)
IWorldRevealRenderResourceScheduler? renderResources = null,
Func<int>? loadedLandblockCount = null)
{
_transit = transit ?? throw new ArgumentNullException(nameof(transit));
_readiness = new WorldRevealReadinessBarrier(
@ -98,6 +100,8 @@ internal sealed class WorldRevealCoordinator
_quiescence = quiescence;
_streaming = streaming;
_renderResources = renderResources;
if (StreamingDiagnostics.ProbeRevealTiming)
_timing = new RevealTimingProbe(loadedLandblockCount);
}
public RuntimePortalSnapshot Snapshot => _transit.Snapshot;
@ -117,6 +121,11 @@ internal sealed class WorldRevealCoordinator
_quiescence?.CaptureBegin() ?? default;
_readiness.Begin();
long generation = _transit.BeginLoginReveal(destinationCell);
_timing?.Begin(
"login",
generation,
destinationCell,
_readiness.RequiredWindow(destinationCell));
BeginHostLifetime(
generation,
destinationCell,
@ -151,6 +160,11 @@ internal sealed class WorldRevealCoordinator
}
_readiness.Begin();
_timing?.Begin(
"portal",
generation,
destinationCell,
_readiness.RequiredWindow(destinationCell));
BeginHostLifetime(
generation,
destinationCell,
@ -195,6 +209,7 @@ internal sealed class WorldRevealCoordinator
WorldRevealReadinessSnapshot snapshot = _readiness.Evaluate(destinationCell);
ReconcileDestinationReservationRadius(snapshot);
RuntimePortalSnapshot portal = _transit.Snapshot;
_timing?.Observe(snapshot, portal);
if (portal.Generation != 0)
{
_transit.AcknowledgeDestinationReadiness(