perf(opstack): invert the loop + prune per block -- 1.45s to 1.02s, byte-identical

The architecture round. Loop inverted from per-sample-per-op to per-op-per-block, operators pruned per block by interval bounds, profiler moved out of the hot loop. my build, 3 runs: 1.013 / 1.036 / 1.075 s (adb34df was 1.418 / 1.445 / 1.458) mean 1.041 vs 1.440 = -28.5%, 1.39x geometry SHA-256 b3e5f4c3..9b377 IDENTICAL to adb34df pruning removed 20,999 / 31,320 operator-block visits = 67.1% surviving ops per block: LOD0 6.63 LOD1 6.30 LOD2 5.23 LOD3 4.41 LOD4 3.89 (out of 22) ⚠️ I PREDICTED THE DISPATCH OVERHEAD WAS "THE 10x". IT WAS NOT. 864,688 virtual dispatches per chunk sounded decisive and is worth ~20-28%. Real, and worth having, but the order of magnitude is elsewhere. That is my fourth wrong performance prediction in this project, and the pattern is identical each time: I reason from a call site's shape instead of measuring what the data actually costs. ⭐⭐ AND THE "5-20x GAME/EXPORT GAP" WAS MY ARITHMETIC ERROR. IT DOES NOT EXIST. I told the owner the largest unexplained number in the project was that export does 22 ms/tile while the game does 115-500 ms. That 22 ms came from dividing 1.4 s of WALL CLOCK by 64 tiles -- ignoring that 15 workers ran them in parallel. Per-job means on the same build: nonshared block export 447 ms/job shared-grid export 261 ms/job game LOD0 meshing 253 ms/tile p50 They are the same. The game is not anomalously slow; generation simply costs ~250 ms per LOD0 tile. The shared grid's benefit is real but modest, and a neighbourhood cache is NOT justified by these numbers -- I would have had Codex build one on the strength of a division error. GAME PATH, final build (841 profiles, 447 applies) meshed p50/p95/max LOD0 253/521/697 ms LOD1 79/130/135 LOD2 19/42/51 LOD3 36/64/81 LOD4 93/238/271 LOD0 request-to-ready p50 47.7 ms p95 389 ms max 798 ms worker queue p95 84 ms, generation p95 344 ms at 6 m/s: p95 = 2.3 m of travel, max = 4.8 m empty LOD0 tiles never enter the mesher; classifier p50 8.7 ms, p95 17.2 ms apply is not the bottleneck: p50 0.107 ms, p95 0.161 ms, max 0.296 ms ⭐ THE BINDING CONSTRAINT IS COMPUTE, NOT POLICY: logical cores 16, automatic core cap 14, effective generation cap 14, CAP HIT. Apply limits never bind. We are saturating the machine, which means the remaining wins must come from doing less work, not from scheduling it better. NOT DONE, with reasons rather than excuses: - Coarse-first LOD refinement: coarse tiles carry NO COLLISION, so streaming them first would let the player fall through. Needs a conservative collision proxy or an L0 handoff first. Correct refusal. - Heading prefetch: desired tiles are sorted by distance only (VoxelWorld.cpp:1748). Velocity-weighted prediction with a bounded budget and expiry is the shape, not built. A failed experiment, reported rather than buried: eagerly filling every classifier leaf with EvalBlock regressed export to 3.2-3.3 s because it defeated the classifier's early exit. Removed. Build 43 actions, 0 errors. Peak RSS under 2.1 GB. Sources: Epic's Tasks System and Level Streaming docs, Lorensen-Cline. Cumulative on this region: 342.2 s -> 1.02 s. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012aheo2crrZmHuYtPpdY2Cb
2026-09-11 18:09:12 +02:00
1 parent adb34dffa9
commit 5ddd96664d
@@ -12,6 +12,7 @@
 #include "VoxelContentManager.h"
 #include "VoxelDensityVolume.h"
 #include "VoxelDensityOpStack.h"
+#include "VoxelDensityProfile.h"
 #include "VoxelStats.h"
 // IWYU (FPSemantics = Precise ⇒ plus de PCH partagé) : GetPlayerPosition déréférence le pawn, donc
 // APawn doit être COMPLET — `Casts.h` n'en donne qu'une déclaration avant. APlayerController était
@@ -49,6 +50,17 @@ namespace
        GVoxelForgeProfileTileGeneration,
        TEXT("Log worker tile generation time with level/step/cell count."));

+    int32 GVoxelForgeProfileDensity = 0;
+    FAutoConsoleVariableRef CVarVoxelForgeProfileDensity(
+        TEXT("voxel.ProfileDensity"),
+        GVoxelForgeProfileDensity,
+        TEXT("Collect sampled per-density profiling for the game path."));
+    int32 GVoxelForgeProfileDensityFull = 0;
+    FAutoConsoleVariableRef CVarVoxelForgeProfileDensityFull(
+        TEXT("voxel.ProfileDensityFull"),
+        GVoxelForgeProfileDensityFull,
+        TEXT("Collect full per-operator profiling for the game path."));
+
    // Startup command-line cvars can arrive before the game world has spawned AVoxelWorld (or
    // before its first tiles have become visible). Keep the diagnostic edit pending until Tick has
    // a loaded tile; otherwise a startup measurement silently becomes a no-op or edits the wrong
@@ -972,6 +984,39 @@ void AVoxelWorld::BeginPlay()
    Super::BeginPlay();
    bShuttingDown.store(false, std::memory_order_relaxed);

+    // Some headless harnesses load module CVars after the engine's startup-CVar pass. Read the
+    // profiling switches explicitly as well, so a reported game profile cannot silently run with
+    // the default mode because of startup ordering.
+    int32 CommandLineProfile = GVoxelForgeProfileDensity;
+    int32 CommandLineProfileFull = GVoxelForgeProfileDensityFull;
+    if (FParse::Value(FCommandLine::Get(), TEXT("voxel.ProfileDensity="), CommandLineProfile))
+    {
+        GVoxelForgeProfileDensity = CommandLineProfile;
+    }
+    if (FParse::Value(FCommandLine::Get(), TEXT("voxel.ProfileDensityFull="), CommandLineProfileFull))
+    {
+        GVoxelForgeProfileDensityFull = CommandLineProfileFull;
+    }
+
+    if (GVoxelForgeProfileDensityFull != 0)
+    {
+        VoxelDensityProfile::SetMode(
+            VoxelDensityProfile::EMode::Full,
+            VoxelDensityProfile::DefaultSampleInterval);
+        UE_LOG(LogTemp, Display,
+            TEXT("[VoxelForgeDensityProfile] game_mode=full sample_interval=%u"),
+            VoxelDensityProfile::DefaultSampleInterval);
+    }
+    else if (GVoxelForgeProfileDensity != 0)
+    {
+        VoxelDensityProfile::SetMode(
+            VoxelDensityProfile::EMode::Sampled,
+            VoxelDensityProfile::DefaultSampleInterval);
+        UE_LOG(LogTemp, Display,
+            TEXT("[VoxelForgeDensityProfile] game_mode=sampled sample_interval=%u"),
+            VoxelDensityProfile::DefaultSampleInterval);
+    }
+
    if (!Settings)
    {
        UE_LOG(LogTemp, Error, TEXT("[VoxelWorld] No Settings assigned — world won't generate."));
@@ -2379,10 +2424,24 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector
    double StreamSeconds = 0.0;
    int32 ClassifyVerdict = -1; // Mixed = 0, AllSolid = 1, AllAir = 2
    FVoxelTileClassificationStats ClassifierStats;
+    const bool bProfileOps = bProfileTile
+        && VoxelDensityProfile::GetMode() == VoxelDensityProfile::EMode::Full;
+    const VoxelDensityProfile::FSnapshot TileProfileStart = bProfileTile
+        ? VoxelDensityProfile::SnapshotCurrentThread()
+        : VoxelDensityProfile::FSnapshot();
    auto EmitTileProfile = [&]()
    {
        if (bProfileTile)
        {
+            const VoxelDensityProfile::FSnapshot TileProfileEnd = bProfileTile
+                ? VoxelDensityProfile::SnapshotCurrentThread()
+                : VoxelDensityProfile::FSnapshot();
+            const auto CounterDelta = [&](VoxelDensityProfile::ECounter Counter) -> uint64
+            {
+                const int32 Index = static_cast<int32>(Counter);
+                return bProfileTile && TileProfileEnd.Counters[Index] >= TileProfileStart.Counters[Index]
+                    ? TileProfileEnd.Counters[Index] - TileProfileStart.Counters[Index] : 0;
+            };
            UE_LOG(LogTemp, Display,
                TEXT("[VoxelForgeTileProfile] tile=(%d,%d,%d) level=%d step=%d cells=%d sheet=%d aborted=%d empty=%d "
                     "verdict=%d classify=%.6f mesh=%.6f streams=%.6f seconds=%.6f "
@@ -2392,7 +2451,8 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector
                     "room_work=%.6f room_exact=%.6f cache_work=%.6f "
                     "rooms=%d tunnels=%d joins=%d pits=%d chimneys=%d "
                     "whole_mixed=%u whole_solid=%u whole_air=%u final_nodes=%u "
-                     "split_nodes=%u max_depth=%u"),
+                     "split_nodes=%u max_depth=%u block_builds=%llu block_samples=%llu "
+                     "block_ops=%llu block_active=%llu block_pruned=%llu"),
                Tile.Coord.X, Tile.Coord.Y, Tile.Coord.Z, Tile.Level, Step, Cells,
                bSheetTile ? 1 : 0, Result.bAborted ? 1 : 0,
                Result.bEmpty ? 1 : 0, ClassifyVerdict, ClassifySeconds, MeshSeconds, StreamSeconds,
@@ -2414,7 +2474,53 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector
                ClassifierStats.RoomNumChimneys,
                ClassifierStats.WholeMixedNodes, ClassifierStats.WholeSolidNodes,
                ClassifierStats.WholeAirNodes, ClassifierStats.NeedsFinalFieldNodes,
-                ClassifierStats.SplitNodes, ClassifierStats.MaxRefinementDepth);
+                ClassifierStats.SplitNodes, ClassifierStats.MaxRefinementDepth,
+                static_cast<unsigned long long>(CounterDelta(VoxelDensityProfile::ECounter::OpBlockBuilds)),
+                static_cast<unsigned long long>(CounterDelta(VoxelDensityProfile::ECounter::OpBlockSamples)),
+                static_cast<unsigned long long>(CounterDelta(VoxelDensityProfile::ECounter::OpBlockOperators)),
+                static_cast<unsigned long long>(CounterDelta(VoxelDensityProfile::ECounter::OpBlockActiveOperators)),
+                static_cast<unsigned long long>(CounterDelta(VoxelDensityProfile::ECounter::OpBlockPrunedOperators)));
+
+            if (bProfileOps)
+            {
+                static const VoxelDensityProfile::EBucket GameOpBuckets[] = {
+                    VoxelDensityProfile::EBucket::RoomGraphSource,
+                    VoxelDensityProfile::EBucket::SdfCarve,
+                    VoxelDensityProfile::EBucket::CaveRoughnessMod,
+                    VoxelDensityProfile::EBucket::CaveTerraceMod,
+                    VoxelDensityProfile::EBucket::LayerLineMod,
+                    VoxelDensityProfile::EBucket::RibbingMod,
+                    VoxelDensityProfile::EBucket::CaveOverhangMod,
+                    VoxelDensityProfile::EBucket::CaveCliffMod,
+                    VoxelDensityProfile::EBucket::ScallopMod,
+                    VoxelDensityProfile::EBucket::CaveArchMod,
+                    VoxelDensityProfile::EBucket::RoomColumnMod,
+                    VoxelDensityProfile::EBucket::DomeMod,
+                    VoxelDensityProfile::EBucket::PinchMod,
+                    VoxelDensityProfile::EBucket::FloorBiasMod,
+                    VoxelDensityProfile::EBucket::WormFieldSource,
+                    VoxelDensityProfile::EBucket::OriginSpineOp,
+                    VoxelDensityProfile::EBucket::BoundarySealOp,
+                    VoxelDensityProfile::EBucket::PassageCarveOp,
+                    VoxelDensityProfile::EBucket::XYEdgeSealOp,
+                };
+                for (const VoxelDensityProfile::EBucket Bucket : GameOpBuckets)
+                {
+                    const int32 Index = static_cast<int32>(Bucket);
+                    const uint64 Calls = TileProfileEnd.Calls[Index] >= TileProfileStart.Calls[Index]
+                        ? TileProfileEnd.Calls[Index] - TileProfileStart.Calls[Index] : 0;
+                    const uint64 Cycles = TileProfileEnd.WallCycles[Index] >= TileProfileStart.WallCycles[Index]
+                        ? TileProfileEnd.WallCycles[Index] - TileProfileStart.WallCycles[Index] : 0;
+                    if (Calls == 0) { continue; }
+                    UE_LOG(LogTemp, Display,
+                        TEXT("[VoxelForgeGameOpProfile] tile=(%d,%d,%d) level=%d op=%s calls=%llu total_us=%.3f us_per_call=%.6f"),
+                        Tile.Coord.X, Tile.Coord.Y, Tile.Coord.Z, Tile.Level,
+                        VoxelDensityProfile::BucketName(Bucket),
+                        static_cast<unsigned long long>(Calls),
+                        FPlatformTime::ToSeconds64(Cycles) * 1.0e6,
+                        FPlatformTime::ToSeconds64(Cycles) * 1.0e6 / static_cast<double>(Calls));
+                }
+            }
        }
    };