measure(perf): in-process stack sampler; the game spends ~3/4 of worker CPU on room player-fit

A diagnostic stack-sampling profiler, off by default. A sampler thread captures the stacks of
registered generation workers with FPlatformStackWalk::CaptureThreadStackBackTrace every N us and
tags each sample with the tile's LOD. Symbolisation (inline frames included) happens after the
run, into a bounded CSV plus a summary. Registration is per tile task, never per sample; when the
sampler is off it costs one relaxed atomic load. Game: -voxel.SampleStacks=<us>. Commandlet:
-samplestacks[=us]. The streaming latency line now also prints applied tile, visible tile and
triangle counts.

Instrument checks (Codex, PERF-SAMPLED.md):
- a planted 20 ms busy loop was found at 10.5% inclusive, the expected share, then removed
- closure: 193k static / 251k moving samples, 0 capture failures, <0.75% wait frames,
  leaf resolved for 82-84%
- static game output identical with the sampler on or off: 841 tiles, 447 visible, 669,834
  triangles
- overhead at 1 ms: +4.7% static worker CPU; moving worker CPU within noise, moving timing +4-5%.
  So trust large shares, not single-digit deltas.

The finding, on the game path (the owner's instruction: profile the game, not the export):

                                all-LOD inclusive   static   moving
  BuildChunkCache                                   79.5%    80.5%
  VF_FindPlayerFitPointForRoom                      73.4%    74.0%

About three quarters of in-game worker CPU goes to player-fit searches for rooms. They are
recomputed on every per-worker room-cache rebuild, and coarse tiles span many cache windows. At
LOD0 the costs are the cave warp (3 Perlin per sample), the swept tunnel evaluated both in the
SDF and in EvaluateTunnelCoreWorld (~12% inclusive each, duplication confirmed), and the passage
structural tail (~11-14%). Candidate AABB rejection is cheap (1.5-2.2%). The 74-field params copy
does not show up as a separate cost.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VZS94UH8bSsBeg5sZaxe2Y
This commit is contained in:
Fr0zkaandClaude Opus 5 committed 2026-09-13 03:32:29 +02:00
1 parent c65b015f01
commit 8e40bdd92c
8 files changed
+2079 -4

No files matched your search

@@ -2,6 +2,7 @@
// Module implementation - boilerplate
#include "VoxelForgeModule.h"
#include "VoxelStackSampler.h"
// This macro registers our module with Unreal
// "VoxelForge" must match the module name in VoxelForge.Build.cs and .uplugin
@@ -17,6 +18,6 @@ void FVoxelForgeModule::StartupModule()
void FVoxelForgeModule::ShutdownModule()
{
// Called when plugin unloads
// Cleanup would go here if we had any global resources
FVoxelStackSampler::Get().Shutdown();
UE_LOG(LogTemp, Log, TEXT("VoxelForge module shutdown."));
}
File diff suppressed because it is too large. Load diff
+49 -3
View File
@@ -15,6 +15,7 @@
#include "VoxelDensityOpStack.h"
#include "VoxelDensityProfile.h"
#include "VoxelStartupTrace.h"
#include "VoxelStackSampler.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
@@ -73,6 +74,11 @@ namespace
TEXT("voxel.PerfAttribution"),
GVoxelForgePerfAttribution,
TEXT("Collect low-overhead component attribution for the game path."));
int32 GVoxelForgeSampleStacks = 0;
FAutoConsoleVariableRef CVarVoxelForgeSampleStacks(
TEXT("voxel.SampleStacks"),
GVoxelForgeSampleStacks,
TEXT("Sample active generation worker stacks at the requested interval in microseconds; 0 is off."));
// The nested 8^3 proof is useful for focused/offline measurements, but it is opt-in for
// streaming because every qualifying mixed tile would pay the recursive proof again.
@@ -988,6 +994,11 @@ void AVoxelWorld::EndPlay(const EEndPlayReason::Type EndPlayReason)
}
UE_LOG(LogTemp, Display, TEXT("[VoxelWorld] EndPlay: workers drained in %.6fs; obsolete_tile_aborts=%d"),
FPlatformTime::Seconds() - EndPlayStartSeconds, ObsoleteTileAbortCount);
if (bSampleStacksStarted)
{
FVoxelStackSampler::Get().StopAndWrite();
bSampleStacksStarted = false;
}
LogStreamingLatencySummary();
PendingTiles.Empty();
PendingTileCancellation.Empty();
@@ -1075,6 +1086,7 @@ void AVoxelWorld::BeginPlay()
int32 CommandLinePerfAttribution = GVoxelForgePerfAttribution;
int32 CommandLineUseBlockEarlyOut = GVoxelForgeUseBlockEarlyOut;
int32 CommandLineOuterClassifierMode = GVoxelForgeOuterClassifierMode;
int32 CommandLineSampleStacks = GVoxelForgeSampleStacks;
if (FParse::Value(FCommandLine::Get(), TEXT("voxel.ProfileDensity="), CommandLineProfile))
{
GVoxelForgeProfileDensity = CommandLineProfile;
@@ -1095,8 +1107,16 @@ void AVoxelWorld::BeginPlay()
{
GVoxelForgeOuterClassifierMode = CommandLineOuterClassifierMode;
}
if (FParse::Value(FCommandLine::Get(), TEXT("voxel.SampleStacks="), CommandLineSampleStacks))
{
GVoxelForgeSampleStacks = CommandLineSampleStacks;
}
GVoxelForgeUseBlockEarlyOut = GVoxelForgeUseBlockEarlyOut != 0 ? 1 : 0;
GVoxelForgeOuterClassifierMode = FMath::Clamp(GVoxelForgeOuterClassifierMode, 0, 1);
GVoxelForgeSampleStacks = FMath::Clamp(
GVoxelForgeSampleStacks,
0,
static_cast<int32>(FVoxelStackSampler::MaxIntervalUs));
if (GVoxelForgePerfAttribution != 0)
{
@@ -1276,6 +1296,21 @@ void AVoxelWorld::BeginPlay()
{
UpdatePawnCollisionGate(InitialPawn, InitialPlayerPosition, 0.0f);
}
if (GVoxelForgeSampleStacks > 0)
{
const FString SamplerOutputDirectory = FPaths::Combine(
FPaths::ProjectDir(), TEXT("Plugins/VoxelForge/Saved"));
bSampleStacksStarted = FVoxelStackSampler::Get().Start(
static_cast<uint32>(GVoxelForgeSampleStacks),
SamplerOutputDirectory,
TEXT("game"));
if (!bSampleStacksStarted)
{
UE_LOG(LogTemp, Error,
TEXT("[VoxelWorld] stack sampler requested but could not be started."));
}
}
}
void AVoxelWorld::ConfigureHeadlessStreamingTest()
@@ -2177,6 +2212,7 @@ void AVoxelWorld::LogStreamingLatencySummary() const
"collision_cook_s[p50=%.6f p95=%.6f max=%.6f] "
"peak_speed_cm_s=%.3f p95_travel_m=%.6f obsolete_tile_aborts=%d "
"outer_classifier_mode=%d nested_block_early_out=%d "
"applied_tiles=%llu applied_visible_tiles=%llu applied_triangles=%llu "
"worker_generation_tasks=%llu worker_generation_sum_s=%.6f "
"validation_density_calls=%llu mesher_density_calls=%llu "
"obsolete_worker_tasks=%llu obsolete_worker_sum_s=%.6f "
@@ -2188,9 +2224,12 @@ void AVoxelWorld::LogStreamingLatencySummary() const
Percentile(QueueWait, 0.50), Percentile(QueueWait, 0.95), Maximum(QueueWait),
Percentile(Generation, 0.50), Percentile(Generation, 0.95), Maximum(Generation),
Percentile(CollisionCook, 0.50), Percentile(CollisionCook, 0.95), Maximum(CollisionCook),
PeakObservedPawnSpeedCmPerSecond, TravelP95Metres, ObsoleteTileAbortCount,
GVoxelForgeOuterClassifierMode, GVoxelForgeUseBlockEarlyOut,
static_cast<unsigned long long>(TotalWorkerGenerationTasks.load(std::memory_order_relaxed)),
PeakObservedPawnSpeedCmPerSecond, TravelP95Metres, ObsoleteTileAbortCount,
GVoxelForgeOuterClassifierMode, GVoxelForgeUseBlockEarlyOut,
static_cast<unsigned long long>(AppliedTileCount),
static_cast<unsigned long long>(AppliedVisibleTileCount),
static_cast<unsigned long long>(AppliedTriangleCount),
static_cast<unsigned long long>(TotalWorkerGenerationTasks.load(std::memory_order_relaxed)),
FPlatformTime::ToSeconds64(WorkerGenerationCycles),
static_cast<unsigned long long>(TotalValidationDensityCalls.load(std::memory_order_relaxed)),
static_cast<unsigned long long>(TotalMesherDensityCalls.load(std::memory_order_relaxed)),
@@ -2444,6 +2483,12 @@ bool AVoxelWorld::ApplyTileResult(FChunkResult& Result)
Result.ApplyStartCycles = ApplyStartCycles;
const auto LogTileApplied = [&]()
{
++AppliedTileCount;
if (!bResultEmpty)
{
++AppliedVisibleTileCount;
AppliedTriangleCount += static_cast<uint64>(FMath::Max(0, Result.NumTriangles));
}
if ((GVoxelForgeProfileTileGeneration != 0 || bTraceTile)
&& Result.RequestStartCycles != 0)
{
@@ -3709,6 +3754,7 @@ void AVoxelWorld::LoadTile(const FVoxelTileKey& Tile, bool bHighPriority)
return;
}
FScopedVoxelStackRegistration StackRegistration(Tile.Level);
FChunkResult Result;
Result.DesiredEpoch = TaskDesiredEpoch;
const uint64 GenerationStartCycles = FPlatformTime::Cycles64();
@@ -0,0 +1,117 @@
// VoxelStackSampler.h
// Opt-in, out-of-process-symbolized stack sampling for active VoxelForge generation workers.
#pragma once
#include "CoreTypes.h"
#include "Containers/UnrealString.h"
/**
* A diagnostic-only in-process stack sampler.
*
* The generation path only constructs FScopedVoxelStackRegistration at task entry. When the
* sampler is disabled that constructor performs one relaxed load of the global enable flag and
* returns; it does not touch the registry, allocate, lock, or read a console variable.
*
* The sampler thread owns a bounded preallocated array of raw program counters. Symbolization
* and aggregation happen after the sampler thread has stopped, so DbgHelp and FString activity are
* kept out of both generation workers and the sampling loop.
*/
class VOXELFORGE_API FVoxelStackSampler
{
public:
static constexpr uint32 DefaultIntervalUs = 1000;
static constexpr uint32 MinIntervalUs = 1;
static constexpr uint32 MaxIntervalUs = 1000000;
static constexpr uint32 MaxStackDepth = 64;
// Bounded allocation. The implementation uses reservoir replacement after this fills so a
// long moving session is represented across its whole run rather than only its first window.
static constexpr uint32 MaxStoredSamples = 131072;
struct FSummary
{
bool bSupported = false;
bool bStarted = false;
bool bOutputWritten = false;
bool bStackWalkingInitialized = false;
uint32 IntervalUs = 0;
uint32 MaxDepth = 0;
uint32 MaxStoredSampleCount = 0;
uint64 SamplerTicks = 0;
uint64 CaptureAttempts = 0;
uint64 RegisteredThreadSamples = 0;
uint64 RegistrationRaceDrops = 0;
uint64 CaptureFailures = 0;
uint64 RetainedSamples = 0;
uint64 DroppedSamples = 0;
uint64 TotalFrames = 0;
uint64 ResolvedFrames = 0;
uint64 UnknownFrames = 0;
uint64 WaitLikeFrames = 0;
uint64 SamplesWithResolvedLeaf = 0;
uint64 SamplesWithWaitLikeFrame = 0;
uint64 UniqueProgramCounters = 0;
uint64 InlineSymbols = 0;
uint64 MaxActiveRegisteredThreads = 0;
double RunSeconds = 0.0;
FString RunLabel;
FString RawSamplesPath;
FString SummaryPath;
};
static FVoxelStackSampler& Get();
/** Start one sampling session. Returns false when another session is active or setup fails. */
bool Start(uint32 IntervalUs, const FString& OutputDirectory, const FString& RunLabel);
/** Stop, symbolize, aggregate, and write the bounded raw CSV plus readable summary. */
FSummary StopAndWrite();
/** Used by the module shutdown path as a final lifecycle backstop. */
void Shutdown();
bool IsRunning() const;
/** Called only by FScopedVoxelStackRegistration; cheap when disabled. */
static bool RegisterCurrentThread(int32 LODLevel = INDEX_NONE);
static void DeregisterCurrentThread();
static bool IsEnabled();
private:
FVoxelStackSampler() = default;
~FVoxelStackSampler() = default;
FVoxelStackSampler(const FVoxelStackSampler&) = delete;
FVoxelStackSampler& operator=(const FVoxelStackSampler&) = delete;
struct FImpl;
FImpl* Impl = nullptr;
bool RegisterThreadInternal(int32 LODLevel);
void DeregisterThreadInternal();
};
/** Scope a generation task, not an individual density sample. */
class FScopedVoxelStackRegistration final
{
public:
explicit FScopedVoxelStackRegistration(int32 InLODLevel = INDEX_NONE)
: bRegistered(FVoxelStackSampler::RegisterCurrentThread(InLODLevel))
{
}
~FScopedVoxelStackRegistration()
{
if (bRegistered)
{
FVoxelStackSampler::DeregisterCurrentThread();
}
}
FScopedVoxelStackRegistration(const FScopedVoxelStackRegistration&) = delete;
FScopedVoxelStackRegistration& operator=(const FScopedVoxelStackRegistration&) = delete;
private:
bool bRegistered = false;
};
+7
View File
@@ -913,6 +913,7 @@ public:
FIntVector LastUpdateCenter = FIntVector(INT32_MAX, INT32_MAX, INT32_MAX);
bool bAllChunksLoaded = false;
bool bStartupTraceDesiredRecorded = false;
bool bSampleStacksStarted = false;
TArray<FVoxelTileKey> DesiredSorted; // critical floor prefix, then true-pawn distance-first
TArray<FVoxelTileKey> CriticalDesiredTiles; // occupied/support tile, then heading tile
uint32 DesiredEpoch = 0; // increments whenever DesiredStamped is rebuilt
@@ -931,6 +932,12 @@ public:
std::atomic<uint64> OuterClassifierCallsByLOD[TrackedClassifierLODCount]{};
std::atomic<uint64> OuterClassifierVerdictsByLOD[TrackedClassifierLODCount][3]{};
// Low-overhead game-thread geometry totals used to prove that sampler toggling does not alter
// the applied tile/triangle stream. These are measurement counters, not generation inputs.
uint64 AppliedTileCount = 0;
uint64 AppliedVisibleTileCount = 0;
uint64 AppliedTriangleCount = 0;
struct FStreamingLatencySample
{
double RequestToReadySeconds = 0.0;
@@ -33,6 +33,7 @@
#include "VoxelMarchingCubesMesher.h"
#include "VoxelNoise.h"
#include "VoxelSettings.h"
#include "VoxelStackSampler.h"
#include "VoxelStrateDefinition.h"
#include "VoxelStrateManager.h"
#include "VoxelStrateMeasure.h"
@@ -267,6 +268,8 @@ struct FExploreArguments
bool bProfileDensity = false;
bool bProfileDensityFull = false;
bool bPerfAttribution = false;
bool bSampleStacks = false;
uint32 SampleStacksIntervalUs = FVoxelStackSampler::DefaultIntervalUs;
bool bProfileLod = false;
bool bOpBounds = false;
bool bFailureFocusRender = false;
@@ -365,6 +368,14 @@ bool ParseArguments(const FString& Params, FExploreArguments& OutArguments, FStr
OutArguments.bProfileDensityFull = FParse::Param(*Params, TEXT("profiledensityfull"));
OutArguments.bProfileDensity |= OutArguments.bProfileDensityFull;
OutArguments.bPerfAttribution = FParse::Param(*Params, TEXT("perfattribution"));
OutArguments.bSampleStacks = FParse::Param(*Params, TEXT("samplestacks"));
int32 SampleStacksIntervalUs = static_cast<int32>(
FVoxelStackSampler::DefaultIntervalUs);
if (FParse::Value(*Params, TEXT("samplestacks="), SampleStacksIntervalUs))
{
OutArguments.bSampleStacks = true;
OutArguments.SampleStacksIntervalUs = static_cast<uint32>(FMath::Max(0, SampleStacksIntervalUs));
}
OutArguments.bProfileLod = FParse::Param(*Params, TEXT("profilelod"));
OutArguments.bOpBounds = FParse::Param(*Params, TEXT("opbounds"));
FParse::Value(*Params, TEXT("out="), OutText);
@@ -605,6 +616,16 @@ bool ParseArguments(const FString& Params, FExploreArguments& OutArguments, FStr
TEXT("budget must be finite and in (0,%g] minutes."), MaxBudgetMinutes);
return false;
}
if (OutArguments.bSampleStacks
&& (OutArguments.SampleStacksIntervalUs < FVoxelStackSampler::MinIntervalUs
|| OutArguments.SampleStacksIntervalUs > FVoxelStackSampler::MaxIntervalUs))
{
OutError = FString::Printf(
TEXT("samplestacks interval must be in [%u,%u] microseconds."),
FVoxelStackSampler::MinIntervalUs,
FVoxelStackSampler::MaxIntervalUs);
return false;
}
if (OutArguments.bSurfaceRoughnessOverride
&& !bSurfaceRoughnessParsed)
{
@@ -1294,6 +1315,36 @@ struct FExploreRunOutput
FExploreProfilerComparison ProfilerComparison;
};
struct FExploreStackSamplerSession
{
bool bStarted = false;
~FExploreStackSamplerSession()
{
Stop();
}
bool Start(uint32 IntervalUs, const FString& OutputDirectory)
{
if (bStarted)
{
return true;
}
bStarted = FVoxelStackSampler::Get().Start(
IntervalUs, OutputDirectory, TEXT("commandlet"));
return bStarted;
}
void Stop()
{
if (bStarted)
{
FVoxelStackSampler::Get().StopAndWrite();
bStarted = false;
}
}
};
bool ValidateCanonicalTile(const FVoxelMeshData& MeshData, FString& OutError);
bool MeasureExploreMesh(
const FVoxelMeshData& MeshData,
@@ -1748,6 +1799,7 @@ bool EnsureExploreMesh(
bGridWorkCancelled.store(true, std::memory_order_relaxed);
return;
}
FScopedVoxelStackRegistration StackRegistration;
const int32 GridOctaveBias = (World.Mesher->LODOctaveDrop > 0
&& Arguments.ExportStep > 1)
? World.Mesher->LODOctaveDrop
@@ -1848,6 +1900,7 @@ bool EnsureExploreMesh(
return;
}
FScopedVoxelStackRegistration StackRegistration;
const double TileStartSeconds = FPlatformTime::Seconds();
TileStartOffsets[LinearTileIndex] = TileStartSeconds - ParallelStartSeconds;
TileThreadIds[LinearTileIndex] = FPlatformTLS::GetCurrentThreadId();
@@ -4406,6 +4459,9 @@ FString BuildExploreJson(
Writer->WriteValue(TEXT("profile_density"), Arguments.bProfileDensity);
Writer->WriteValue(TEXT("profile_density_full"), Arguments.bProfileDensityFull);
Writer->WriteValue(TEXT("perf_attribution"), Arguments.bPerfAttribution);
Writer->WriteValue(TEXT("sample_stacks"), Arguments.bSampleStacks);
Writer->WriteValue(TEXT("sample_stacks_interval_us"),
static_cast<double>(Arguments.SampleStacksIntervalUs));
Writer->WriteValue(TEXT("profile_lod"), Arguments.bProfileLod);
Writer->WriteValue(TEXT("op_bounds"), Arguments.bOpBounds);
Writer->WriteValue(TEXT("budget_minutes"), static_cast<double>(Arguments.BudgetMinutes));
@@ -5590,6 +5646,16 @@ int32 RunExploreCase(const FString& Params, FString* OutJson)
}
const double SetupSeconds = FPlatformTime::Seconds() - SetupStartSeconds;
FExploreStackSamplerSession StackSamplerSession;
if (Arguments.bSampleStacks
&& !StackSamplerSession.Start(
Arguments.SampleStacksIntervalUs, Arguments.OutDirectory))
{
UE_LOG(LogTemp, Error,
TEXT("[VoxelForgeExplore] stack sampler was requested but could not be started."));
return 1;
}
bool bRequestedModeFailed = false;
if (Arguments.bOpBounds)
{
@@ -5852,6 +5918,11 @@ int32 RunExploreCase(const FString& Params, FString* OutJson)
FPlatformTime::Seconds() - Start, *Output.Export.Status);
}
// Stop before the report is assembled, while World still owns the generation state. This
// guarantees that the sampler's summary describes only this case and that all worker stacks
// have been released before the commandlet tears the world down.
StackSamplerSession.Stop();
// A phase can finish just inside its own check and cross the deadline while its artifact is
// being closed. Mark that state before serialising the report so the JSON never claims a full
// run after the budget has actually expired.
@@ -6299,6 +6370,14 @@ bool BuildBatchCaseParams(
bProfileDensity |= bProfileDensityFull;
bool bPerfAttribution = false;
JsonBool(Case, TEXT("perf_attribution"), bPerfAttribution);
bool bSampleStacks = false;
JsonBool(Case, TEXT("sample_stacks"), bSampleStacks);
int32 SampleStacksIntervalUs = static_cast<int32>(FVoxelStackSampler::DefaultIntervalUs);
if (JsonNumber(Case, TEXT("sample_stacks_interval_us"), Number))
{
SampleStacksIntervalUs = FMath::RoundToInt(Number);
bSampleStacks = true;
}
bool bProfileLod = false;
JsonBool(Case, TEXT("profile_lod"), bProfileLod);
bool bOpBounds = false;
@@ -6343,6 +6422,11 @@ bool BuildBatchCaseParams(
{
OutParams += TEXT(" -perfattribution");
}
if (bSampleStacks)
{
OutParams += FString::Printf(
TEXT(" -samplestacks=%d"), SampleStacksIntervalUs);
}
if (bProfileLod)
{
OutParams += TEXT(" -profilelod");