diff --git a/src/AcDream.App/Rendering/GameWindow.cs b/src/AcDream.App/Rendering/GameWindow.cs index 6d78d60b..393f4e1e 100644 --- a/src/AcDream.App/Rendering/GameWindow.cs +++ b/src/AcDream.App/Rendering/GameWindow.cs @@ -81,6 +81,47 @@ public sealed class GameWindow : IDisposable private int _terrainCpuSampleCursor; private long _terrainLastDiagTick; + // [FRAME-DIAG] (ACDREAM_WB_DIAG=1): per-frame cost split for the FPS deep-dive. + // The crux this measures: terrain APPLY runs in OnUpdate (under _datLock — + // dat reads + physics/ShadowObjects/BSP registration + the terrain GPU + // upload), while the DRAW + the title-bar ms run in OnRender, so a heavy + // apply stalls the loop turn yet is INVISIBLE to the render-only ms. We + // accumulate apply cost across each OnUpdate and flush it next to the + // [TERRAIN-DIAG] draw cost. Samples are µs×100 over a rolling 256-ring, + // reusing the [TERRAIN-DIAG] median/p95 helpers. Removable (mirrors the + // probes stripped in 92e95be). Gated once at construction — zero cost off. + private readonly bool _frameDiag = string.Equals( + System.Environment.GetEnvironmentVariable("ACDREAM_WB_DIAG"), "1", System.StringComparison.Ordinal); + private long _applyAccumTicks; // apply CPU accumulated across this OnUpdate + private long _applyUploadAccumTicks; // terrain glBufferSubData sub-span this OnUpdate + private int _appliesThisUpdate; // # landblock LOADS applied this OnUpdate + private int _frameDiagMaxAppliesPerUpdate; // burst size over the 5s window + private readonly long[] _applyCpuSamples = new long[256]; // apply µs×100 / Update + private int _applyCpuSampleCursor; + private readonly long[] _applyUploadSamples = new long[256]; // terrain-upload µs×100 / Update + private int _applyUploadSampleCursor; + private readonly long[] _entityUploadSamples = new long[256]; // _wbMeshAdapter.Tick µs×100 / Render + private int _entityUploadSampleCursor; + // Apply CPU split into three sub-spans (to name WHICH part of the 40-110ms + // apply dominates): cell-build (EnvCell dat reads + physics surfaces + + // buildings), gfxobj-BSP (per-entity physics BSP cache), ShadowObjects+lights + // registration. Accumulated per OnUpdate via checkpoints in ApplyLoadedTerrainLocked. + private long _applyCellAccumTicks; + private long _applyBspAccumTicks; + private long _applyShadowAccumTicks; + private readonly long[] _applyCellSamples = new long[256]; + private int _applyCellSampleCursor; + private readonly long[] _applyBspSamples = new long[256]; + private int _applyBspSampleCursor; + private readonly long[] _applyShadowSamples = new long[256]; + private int _applyShadowSampleCursor; + // Direct measure of the _datLock acquisition wait (the streaming worker holds + // the lock for its full per-landblock build, stalling this apply). Confirms the + // apply≫sub-span gap is lock contention, not in-lock work. + private long _applyLockWaitAccumTicks; + private readonly long[] _applyLockWaitSamples = new long[256]; + private int _applyLockWaitSampleCursor; + // Phase A.1: streaming fields replacing the one-shot _entities list. private AcDream.App.Streaming.LandblockStreamer? _streamer; private AcDream.App.Streaming.GpuWorldState _worldState = new(); @@ -5896,7 +5937,8 @@ public sealed class GameWindow : IDisposable return new AcDream.Core.World.LoadedLandblock( landblockId, heightmapOnly, - System.Array.Empty()); + System.Array.Empty(), + AcDream.Core.World.PhysicsDatBundle.Empty); // far tier: no cells/buildings/entities } var baseLoaded = AcDream.Core.World.LandblockLoader.Load(_dats, landblockId); @@ -5975,10 +6017,91 @@ public sealed class GameWindow : IDisposable merged.AddRange(BuildSceneryEntitiesForStreaming(baseLoaded, lbX, lbY)); merged.AddRange(BuildInteriorEntitiesForStreaming(landblockId, lbX, lbY)); + // datLock fix: pre-read (under the worker's _datLock) every dat the apply + // consumes, so ApplyLoadedTerrainLocked can run lock-free. Built AFTER + // `merged` so entity GfxObj/Setup ids are known. + var physicsDats = BuildPhysicsDatBundle(landblockId, merged); return new AcDream.Core.World.LoadedLandblock( baseLoaded.LandblockId, baseLoaded.Heightmap, - merged); + merged, + physicsDats); + } + + /// + /// Pre-reads (under the worker's _datLock) every dat object + /// consumes, so the apply makes zero + /// DatCollection calls and the update thread never blocks on the + /// worker's lock. MIRRORS the apply's six read sites — gather and apply must + /// enumerate the same ids. Reads only; no build / registration. + /// + private AcDream.Core.World.PhysicsDatBundle BuildPhysicsDatBundle( + uint landblockId, + System.Collections.Generic.IReadOnlyList entities) + { + var envCells = new System.Collections.Generic.Dictionary(); + var environments = new System.Collections.Generic.Dictionary(); + var setups = new System.Collections.Generic.Dictionary(); + var gfxObjs = new System.Collections.Generic.Dictionary(); + + // (1) LandBlockInfo + var lbInfo = _dats!.Get( + (landblockId & 0xFFFF0000u) | 0xFFFEu); + + if (lbInfo is not null) + { + // (2)+(3) EnvCell + Environment, per cell + if (lbInfo.NumCells > 0) + { + uint firstCellId = (landblockId & 0xFFFF0000u) | 0x0100u; + for (uint offset = 0; offset < lbInfo.NumCells; offset++) + { + uint envCellId = firstCellId + offset; + var envCell = _dats.Get(envCellId); + if (envCell is null) continue; + envCells[envCellId] = envCell; + if (envCell.EnvironmentId == 0) continue; + uint envId = 0x0D000000u | envCell.EnvironmentId; + if (!environments.ContainsKey(envId)) + { + var environment = _dats.Get(envId); + if (environment is not null) environments[envId] = environment; + } + } + } + + // (4) building shell Setup, per building + foreach (var building in lbInfo.Buildings) + { + uint modelId = building.ModelId; + if ((modelId & 0xFF000000u) == 0x02000000u && !setups.ContainsKey(modelId)) + { + var bldSetup = _dats.Get(modelId); + if (bldSetup is not null) setups[modelId] = bldSetup; + } + } + } + + // (5)+(6) entity GfxObj (BSP cache) + entity Setup (ShadowObjects parts/lights) + foreach (var entity in entities) + { + uint src = entity.SourceGfxObjOrSetupId; + if ((src & 0xFF000000u) == 0x02000000u && !setups.ContainsKey(src)) + { + var s = _dats.Get(src); + if (s is not null) setups[src] = s; + } + foreach (var meshRef in entity.MeshRefs) + { + uint gid = meshRef.GfxObjId; + if ((gid & 0xFF000000u) != 0x01000000u) continue; + if (gfxObjs.ContainsKey(gid)) continue; + var gfx = _dats.Get(gid); + if (gfx is not null) gfxObjs[gid] = gfx; + } + } + + return new AcDream.Core.World.PhysicsDatBundle(lbInfo, envCells, environments, setups, gfxObjs); } /// @@ -6493,10 +6616,22 @@ public sealed class GameWindow : IDisposable // Hold the lock across the entity hydration below (GfxObj sub-mesh // builds). The terrain mesh is pre-built by the worker (T12) and passed // in via meshData, so LandblockMesh.Build no longer runs under this lock. + // [FRAME-DIAG]: time the full locked apply (dat reads + physics/registry + + // the terrain GPU upload) — this is the OnUpdate cost the title-bar ms misses. + long fdT0 = _frameDiag ? System.Diagnostics.Stopwatch.GetTimestamp() : 0L; lock (_datLock) { + // [FRAME-DIAG]: time blocked acquiring _datLock — the streaming worker + // holds it for the full per-landblock build (tens of ms), stalling us. + if (_frameDiag) + _applyLockWaitAccumTicks += System.Diagnostics.Stopwatch.GetTimestamp() - fdT0; ApplyLoadedTerrainLocked(lb, meshData); } + if (_frameDiag) + { + _applyAccumTicks += System.Diagnostics.Stopwatch.GetTimestamp() - fdT0; + _appliesThisUpdate++; + } } /// @@ -6667,7 +6802,16 @@ public sealed class GameWindow : IDisposable // Phase A.5 T15/T16: route through AddLandblockWithMesh — the named // two-tier entry point. Delegates to AddLandblock internally; both // paths share one GPU upload path. + // [FRAME-DIAG]: bracket the terrain glBufferSubData sub-span so we can tell + // the (tiny ~17KB) GPU upload apart from the dat-read/registration tail. + long fdU0 = _frameDiag ? System.Diagnostics.Stopwatch.GetTimestamp() : 0L; _terrain.AddLandblockWithMesh(lb.LandblockId, meshData, origin); + if (_frameDiag) + _applyUploadAccumTicks += System.Diagnostics.Stopwatch.GetTimestamp() - fdU0; + + // [FRAME-DIAG]: split the post-upload apply CPU into three sub-spans via + // method-scope checkpoints — cell-build → gfxobj-BSP → ShadowObjects+lights. + long fdCheck = _frameDiag ? System.Diagnostics.Stopwatch.GetTimestamp() : 0L; // Step 4: drain pending LoadedCells from the worker thread. // Also collect into a local dict for the BuildingLoader stamping pass below. @@ -6916,6 +7060,8 @@ public sealed class GameWindow : IDisposable // (and _pendingCellMeshes drain) are retired with InstancedMeshRenderer. // Cache GfxObj physics data (BSP trees) for the physics engine — this // loop is physics-only, not renderer-side. + // [FRAME-DIAG] checkpoint: end cell-build, begin gfxobj-BSP. + if (_frameDiag) { long t = System.Diagnostics.Stopwatch.GetTimestamp(); _applyCellAccumTicks += t - fdCheck; fdCheck = t; } foreach (var entity in lb.Entities) { foreach (var meshRef in entity.MeshRefs) @@ -6930,6 +7076,8 @@ public sealed class GameWindow : IDisposable // The data is no longer consumed (WB handles EnvCell geometry through // its own pipeline), but the worker thread still populates this dict. _pendingCellMeshes.Clear(); + // [FRAME-DIAG] checkpoint: end gfxobj-BSP, begin ShadowObjects+lights. + if (_frameDiag) { long t = System.Diagnostics.Stopwatch.GetTimestamp(); _applyBspAccumTicks += t - fdCheck; fdCheck = t; } // Task 7: register static entities into the ShadowObjectRegistry so the // Transition system can find and collide against them during movement. @@ -7459,10 +7607,37 @@ public sealed class GameWindow : IDisposable _worldGameState.Add(snapshot); _worldEvents.FireEntitySpawned(snapshot); } + // [FRAME-DIAG] checkpoint: end ShadowObjects+lights registration (apply tail). + if (_frameDiag) _applyShadowAccumTicks += System.Diagnostics.Stopwatch.GetTimestamp() - fdCheck; } private void OnUpdate(double dt) { + // [FRAME-DIAG]: applies run later this frame inside _streamingController.Tick; + // flush the PREVIOUS OnUpdate's accumulated apply cost here (a clean per-frame + // boundary, independent of where in OnUpdate the applies landed) and reset. + if (_frameDiag) + { + if (_appliesThisUpdate > 0) + { + FrameDiagPush(_applyCpuSamples, ref _applyCpuSampleCursor, _applyAccumTicks); + FrameDiagPush(_applyUploadSamples, ref _applyUploadSampleCursor, _applyUploadAccumTicks); + FrameDiagPush(_applyCellSamples, ref _applyCellSampleCursor, _applyCellAccumTicks); + FrameDiagPush(_applyBspSamples, ref _applyBspSampleCursor, _applyBspAccumTicks); + FrameDiagPush(_applyShadowSamples, ref _applyShadowSampleCursor, _applyShadowAccumTicks); + FrameDiagPush(_applyLockWaitSamples, ref _applyLockWaitSampleCursor, _applyLockWaitAccumTicks); + if (_appliesThisUpdate > _frameDiagMaxAppliesPerUpdate) + _frameDiagMaxAppliesPerUpdate = _appliesThisUpdate; + } + _applyAccumTicks = 0; + _applyUploadAccumTicks = 0; + _applyCellAccumTicks = 0; + _applyBspAccumTicks = 0; + _applyShadowAccumTicks = 0; + _applyLockWaitAccumTicks = 0; + _appliesThisUpdate = 0; + } + // Phase A.1: advance the streaming controller FIRST so the initial // landblocks are loaded into GpuWorldState before live-session // CreateObject events drain. The earlier order (live tick first, @@ -8224,7 +8399,13 @@ public sealed class GameWindow : IDisposable // GL thread queue). Must happen before any draw work so that // resources uploaded this frame are available immediately. // No-op when ACDREAM_USE_WB_FOUNDATION is off (_wbMeshAdapter is null). + // [FRAME-DIAG]: this OnRender drain is where staged GfxObj/entity meshes hit + // the GPU (uncapped) — the H2 entity-upload suspect, separate from the apply. + long fdE0 = _frameDiag ? System.Diagnostics.Stopwatch.GetTimestamp() : 0L; _wbMeshAdapter?.Tick(); + if (_frameDiag) + FrameDiagPush(_entityUploadSamples, ref _entityUploadSampleCursor, + System.Diagnostics.Stopwatch.GetTimestamp() - fdE0); // Phase D.2a — begin ImGui frame. Paired with the Render() call // after the scene draws (below). ImGuiController.Update() @@ -13136,6 +13317,45 @@ public sealed class GameWindow : IDisposable $"visible={_terrain?.VisibleSlots ?? 0} " + $"loaded={_terrain?.LoadedSlots ?? 0} " + $"capacity={_terrain?.CapacitySlots ?? 0}"); + + // [FRAME-DIAG]: the FPS-deep-dive per-frame cost split + leak/churn counters. + // apply_us = terrain-apply CPU in OnUpdate (dat reads + physics/ShadowObjects + // registration + terrain upload) — INVISIBLE to the title-bar ms (H1). + // upl_us = the terrain glBufferSubData sub-span of that apply (expected tiny). + // entUpl_us= the OnRender _wbMeshAdapter.Tick entity-mesh GPU drain (H2). + // For entity-DRAW CPU/GPU see the [WB-DIAG] line; walked = resident-N proxy (H3). + double applyMedUs = TerrainDiagMedianMicros(_applyCpuSamples) / 100.0; + double applyP95Us = TerrainDiagPercentile95Micros(_applyCpuSamples) / 100.0; + double uplMedUs = TerrainDiagMedianMicros(_applyUploadSamples) / 100.0; + double uplP95Us = TerrainDiagPercentile95Micros(_applyUploadSamples) / 100.0; + double entUplMedUs = TerrainDiagMedianMicros(_entityUploadSamples) / 100.0; + double entUplP95Us = TerrainDiagPercentile95Micros(_entityUploadSamples) / 100.0; + // apply CPU split: cell-build / gfxobj-BSP / ShadowObjects+lights — names + // WHICH part of the apply dominates (decides the fix shape). + double cellMedUs = TerrainDiagMedianMicros(_applyCellSamples) / 100.0; + double cellP95Us = TerrainDiagPercentile95Micros(_applyCellSamples) / 100.0; + double bspMedUs = TerrainDiagMedianMicros(_applyBspSamples) / 100.0; + double bspP95Us = TerrainDiagPercentile95Micros(_applyBspSamples) / 100.0; + double shadMedUs = TerrainDiagMedianMicros(_applyShadowSamples) / 100.0; + double shadP95Us = TerrainDiagPercentile95Micros(_applyShadowSamples) / 100.0; + double lockMedUs = TerrainDiagMedianMicros(_applyLockWaitSamples) / 100.0; + double lockP95Us = TerrainDiagPercentile95Micros(_applyLockWaitSamples) / 100.0; + int walked = _wbDrawDispatcher?.LastDrawStats.EntitiesWalked ?? 0; + Console.WriteLine( + $"[FRAME-DIAG] apply_us={applyMedUs:F1}m/{applyP95Us:F1}p95 " + + $"lockwait={lockMedUs:F1}m/{lockP95Us:F1}p95 " + + $"[cell={cellMedUs:F1}m/{cellP95Us:F1}p95 bsp={bspMedUs:F1}m/{bspP95Us:F1}p95 " + + $"shadow={shadMedUs:F1}m/{shadP95Us:F1}p95] " + + $"(upl={uplMedUs:F1}m/{uplP95Us:F1}p95) " + + $"entUpl_us={entUplMedUs:F1}m/{entUplP95Us:F1}p95 " + + $"applies_max/upd={_frameDiagMaxAppliesPerUpdate} " + + $"deferred={_streamingController?.DeferredApplyBacklog ?? 0} " + + $"forceReload={_streamingController?.ForceReloadCount ?? 0}" + + $"(drop={_streamingController?.LastForceReloadDropCount ?? 0}) " + + $"esg={_entitiesByServerGuid.Count} spawn={_lastSpawnByGuid.Count} " + + $"resident={_worldState.Entities.Count} walked={walked}"); + _frameDiagMaxAppliesPerUpdate = 0; // reset the per-window burst tracker + _terrainLastDiagTick = now; } @@ -13167,6 +13387,17 @@ public sealed class GameWindow : IDisposable return copy[copy.Length - 1 - offset]; } + /// [FRAME-DIAG] helper: convert a + /// timestamp-tick delta to the microseconds×100 fixed-point used by the rolling + /// sample rings and store it (zeros are ignored by the median/p95 helpers, so an + /// idle frame's 0-sample doesn't dilute the non-zero cost distribution). + private static void FrameDiagPush(long[] samples, ref int cursor, long ticks) + { + // µs×100 = ticks × 1e8 / Stopwatch.Frequency. + samples[cursor] = (long)(ticks * 100_000_000.0 / System.Diagnostics.Stopwatch.Frequency); + cursor = (cursor + 1) % samples.Length; + } + /// A.5 T22: parse a float environment variable, returning /// when the variable is absent or unparseable. private static float ParseEnvFloat(string name, float defaultValue)