unreal: remove 121 ms per-frame overlap scoring and 162 ms world-lock wait; keep support tiles (L96)

- Per-frame passage-overlap scoring over outstanding tiles (added in L85) measured 121 ms for
  407 LOD2 candidates; removed (deterministic desired/travel order kept).
- Visibility reconciliation read-locked the Core world per candidate while the far-world build
  held the writer lock (162 ms scan, 123 ms lock wait); the immutable render distance is cached.
  Visibility now <= 0.17 ms.
- Ready player-support collision tiles stay in the collision-desired set: fixes the L95 SW outlier
  (LOD0 (3,0,-47/-48/-50) re-admitted); 6 SW runs without re-admission.
- AVoxelWorld::Tick during the arrival burst: FI p99 3.7-4.3 ms (max 6.0), SW p99 8.2-8.9 ms
  (max 11.2). FI still shows rare 40-60 ms world ticks outside our actor scope (engine tick group).
- Near-set times kept: FI 2.06-2.12 s, SW median 1.30 s after first admission. World unchanged.
  Fast tier PASS; Linux UE host builds.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016dhxM43dnWvUu2B5Ph1iG1
This commit is contained in:
Fr0zkaandClaude Opus 5.5 committed 2026-10-28 10:28:28 +01:00
1 parent 5389abed2e
commit 94f9aa6790
7 files changed
+891 -35

No files matched your search

@@ -1,9 +1,12 @@
#include "VoxelStartupTrace.h" #include "VoxelStartupTrace.h"
#include "HAL/FileManager.h" #include "HAL/FileManager.h"
#include "HAL/PlatformTLS.h"
#include "HAL/PlatformTime.h" #include "HAL/PlatformTime.h"
#include "CoreGlobals.h"
#include "Misc/CommandLine.h" #include "Misc/CommandLine.h"
#include "Misc/Parse.h" #include "Misc/Parse.h"
#include "UObject/UObjectGlobals.h"
#include <atomic> #include <atomic>
@@ -15,7 +18,13 @@ namespace
{ {
FArchive* Archive = nullptr; FArchive* Archive = nullptr;
FString Path; FString Path;
uint32 GameThreadId = 0;
double StartSeconds = 0.0; double StartSeconds = 0.0;
double GameThreadJsonWriteSeconds = 0.0;
double GameThreadArchiveSerializeSeconds = 0.0;
double GarbageCollectionStartSeconds = 0.0;
FDelegateHandle PreGarbageCollectHandle;
FDelegateHandle PostGarbageCollectHandle;
int32 TileRecordCap = 4096; int32 TileRecordCap = 4096;
int32 TileRecordsSeen = 0; int32 TileRecordsSeen = 0;
int32 TileRecordsWritten = 0; int32 TileRecordsWritten = 0;
@@ -50,15 +59,22 @@ namespace
void WriteLineLocked(FState& State, const FString& Line) void WriteLineLocked(FState& State, const FString& Line)
{ {
if (State.Archive == nullptr) return; if (State.Archive == nullptr) return;
const uint64 StartCycles = FPlatformTime::Cycles64();
const FString WithNewline = Line + TEXT("\n"); const FString WithNewline = Line + TEXT("\n");
FTCHARToUTF8 Utf8(*WithNewline); FTCHARToUTF8 Utf8(*WithNewline);
State.Archive->Serialize(const_cast<ANSICHAR*>(Utf8.Get()), Utf8.Length()); State.Archive->Serialize(const_cast<ANSICHAR*>(Utf8.Get()), Utf8.Length());
if (FPlatformTLS::GetCurrentThreadId() == State.GameThreadId)
{
State.GameThreadArchiveSerializeSeconds += FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - StartCycles);
}
// The file archive buffers records; flushing every tile/request can stall the game thread. // The file archive buffers records; flushing every tile/request can stall the game thread.
// L'archive tamponne les lignes ; vider apres chaque tuile/requete peut bloquer le thread de jeu. // L'archive tamponne les lignes ; vider apres chaque tuile/requete peut bloquer le thread de jeu.
} }
void WriteEventLocked(FState& State, const TCHAR* Type, const FString& FieldsJson) void WriteEventLocked(FState& State, const TCHAR* Type, const FString& FieldsJson)
{ {
const uint64 StartCycles = FPlatformTime::Cycles64();
FString Line = FString::Printf( FString Line = FString::Printf(
TEXT("{\"type\":\"%s\",\"t_s\":%s"), TEXT("{\"type\":\"%s\",\"t_s\":%s"),
Type, Type,
@@ -70,6 +86,11 @@ namespace
} }
Line += TEXT("}"); Line += TEXT("}");
WriteLineLocked(State, Line); WriteLineLocked(State, Line);
if (FPlatformTLS::GetCurrentThreadId() == State.GameThreadId)
{
State.GameThreadJsonWriteSeconds += FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - StartCycles);
}
} }
double Percentile(TArray<double> Values, double Fraction) double Percentile(TArray<double> Values, double Fraction)
@@ -198,6 +219,7 @@ void BeginFromCommandLine()
TUniquePtr<FState> NewState = MakeUnique<FState>(); TUniquePtr<FState> NewState = MakeUnique<FState>();
NewState->Path = Path; NewState->Path = Path;
NewState->GameThreadId = FPlatformTLS::GetCurrentThreadId();
FParse::Value(FCommandLine::Get(), TEXT("voxel.StartupTraceMaxTiles="), NewState->TileRecordCap); FParse::Value(FCommandLine::Get(), TEXT("voxel.StartupTraceMaxTiles="), NewState->TileRecordCap);
NewState->TileRecordCap = FMath::Clamp(NewState->TileRecordCap, 64, 16384); NewState->TileRecordCap = FMath::Clamp(NewState->TileRecordCap, 64, 16384);
NewState->Samples.Reserve(NewState->TileRecordCap); NewState->Samples.Reserve(NewState->TileRecordCap);
@@ -211,6 +233,32 @@ void BeginFromCommandLine()
NewState->bActive = true; NewState->bActive = true;
GState = MoveTemp(NewState); GState = MoveTemp(NewState);
GTraceActive.store(true, std::memory_order_release); GTraceActive.store(true, std::memory_order_release);
GState->PreGarbageCollectHandle = FCoreUObjectDelegates::GetPreGarbageCollectDelegate()
.AddLambda([]()
{
FScopeLock CallbackLock(&GTraceLock);
if (GState.IsValid() && GState->bActive)
{
GState->GarbageCollectionStartSeconds = FPlatformTime::Seconds();
}
});
GState->PostGarbageCollectHandle = FCoreUObjectDelegates::GetPostGarbageCollect()
.AddLambda([]()
{
FScopeLock CallbackLock(&GTraceLock);
if (!GState.IsValid() || !GState->bActive
|| GState->GarbageCollectionStartSeconds <= 0.0)
{
return;
}
const double DurationMilliseconds = FMath::Max(
0.0, FPlatformTime::Seconds() - GState->GarbageCollectionStartSeconds) * 1000.0;
GState->GarbageCollectionStartSeconds = 0.0;
WriteEventLocked(*GState, TEXT("garbage_collect"), FString::Printf(
TEXT("\"frame\":%llu,\"duration_ms\":%s"),
static_cast<unsigned long long>(GFrameCounter),
*Number(DurationMilliseconds)));
});
WriteEventLocked(*GState, TEXT("header"), FString::Printf( WriteEventLocked(*GState, TEXT("header"), FString::Printf(
TEXT("\"schema\":1,\"path\":\"%s\",\"tile_record_cap\":%d"), TEXT("\"schema\":1,\"path\":\"%s\",\"tile_record_cap\":%d"),
*JsonEscape(GState->Path), GState->TileRecordCap)); *JsonEscape(GState->Path), GState->TileRecordCap));
@@ -221,6 +269,21 @@ bool IsActive()
return GTraceActive.load(std::memory_order_acquire); return GTraceActive.load(std::memory_order_acquire);
} }
FWriteMetrics ConsumeCurrentThreadWriteMetrics()
{
FWriteMetrics Metrics;
FScopeLock Lock(&GTraceLock);
if (!GState.IsValid() || FPlatformTLS::GetCurrentThreadId() != GState->GameThreadId)
{
return Metrics;
}
Metrics.JsonWriteMilliseconds = GState->GameThreadJsonWriteSeconds * 1000.0;
Metrics.ArchiveSerializeMilliseconds = GState->GameThreadArchiveSerializeSeconds * 1000.0;
GState->GameThreadJsonWriteSeconds = 0.0;
GState->GameThreadArchiveSerializeSeconds = 0.0;
return Metrics;
}
void RecordEvent(const TCHAR* Type, const FString& FieldsJson) void RecordEvent(const TCHAR* Type, const FString& FieldsJson)
{ {
FScopeLock Lock(&GTraceLock); FScopeLock Lock(&GTraceLock);
@@ -378,6 +441,18 @@ void Finish(const TCHAR* Reason)
FScopeLock Lock(&GTraceLock); FScopeLock Lock(&GTraceLock);
if (!GState.IsValid() || !GState->bActive) return; if (!GState.IsValid() || !GState->bActive) return;
GTraceActive.store(false, std::memory_order_release); GTraceActive.store(false, std::memory_order_release);
if (GState->PreGarbageCollectHandle.IsValid())
{
FCoreUObjectDelegates::GetPreGarbageCollectDelegate().Remove(
GState->PreGarbageCollectHandle);
GState->PreGarbageCollectHandle.Reset();
}
if (GState->PostGarbageCollectHandle.IsValid())
{
FCoreUObjectDelegates::GetPostGarbageCollect().Remove(
GState->PostGarbageCollectHandle);
GState->PostGarbageCollectHandle.Reset();
}
// Close any stage left open by an abnormal early exit so the summary remains useful. // Close any stage left open by an abnormal early exit so the summary remains useful.
const double Now = FPlatformTime::Seconds(); const double Now = FPlatformTime::Seconds();
@@ -387,7 +462,19 @@ void Finish(const TCHAR* Reason)
} }
GState->StageStarts.Reset(); GState->StageStarts.Reset();
WriteEventLocked(*GState, TEXT("summary"), BuildSummaryFieldsLocked(*GState, Reason)); WriteEventLocked(*GState, TEXT("summary"), BuildSummaryFieldsLocked(*GState, Reason));
const uint64 FlushStartCycles = FPlatformTime::Cycles64();
GState->Archive->Flush(); GState->Archive->Flush();
const double FlushMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - FlushStartCycles) * 1000.0;
WriteEventLocked(*GState, TEXT("trace_finish_flush"), FString::Printf(
TEXT("\"first_flush_ms\":%s"), *Number(FlushMilliseconds)));
const uint64 FinalFlushStartCycles = FPlatformTime::Cycles64();
GState->Archive->Flush();
const double FinalFlushMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - FinalFlushStartCycles) * 1000.0;
UE_LOG(LogTemp, Display,
TEXT("[VoxelForgeStartupTrace] finish_flush_ms=%.3f final_flush_ms=%.3f"),
FlushMilliseconds, FinalFlushMilliseconds);
delete GState->Archive; delete GState->Archive;
GState->Archive = nullptr; GState->Archive = nullptr;
GState->bActive = false; GState->bActive = false;
+305 -35
View File
@@ -6966,6 +6966,20 @@ void AVoxelWorld::LogReadyTransitionVisibilityMeasure()
void AVoxelWorld::Tick(float DeltaTime) void AVoxelWorld::Tick(float DeltaTime)
{ {
const bool bTraceFrameTiming = VoxelForgeStartupTrace::IsActive();
const uint64 TickStartCycles = bTraceFrameTiming ? FPlatformTime::Cycles64() : 0;
uint64 CollisionGateCycles = 0;
uint64 UpdateChunksCycles = 0;
uint64 PendingDrainCycles = 0;
uint64 PostApplyCallbacksCycles = 0;
uint64 CollisionProbeCycles = 0;
uint64 VisibilityReconcileCycles = 0;
uint64 VisibleApplyProbeCycles = 0;
uint64 LOD0ReadyCycles = 0;
uint64 SteadyTraceCycles = 0;
uint64 ModificationCycles = 0;
uint64 UnloadCycles = 0;
uint64 LifecycleAuditCycles = 0;
Super::Tick(DeltaTime); Super::Tick(DeltaTime);
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_Tick); // game-thread streaming orchestration breakdown TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_Tick); // game-thread streaming orchestration breakdown
if (bUseVoxelForgeCore && VoxelForgeCoreState.IsValid() if (bUseVoxelForgeCore && VoxelForgeCoreState.IsValid()
@@ -7069,14 +7083,26 @@ void AVoxelWorld::Tick(float DeltaTime)
PeakObservedPawnSpeedCmPerSecond = FMath::Max( PeakObservedPawnSpeedCmPerSecond = FMath::Max(
PeakObservedPawnSpeedCmPerSecond, PlayerHeading.Size()); PeakObservedPawnSpeedCmPerSecond, PlayerHeading.Size());
StartupTraceSpeedCmPerSecond = PlayerHeading.Size(); StartupTraceSpeedCmPerSecond = PlayerHeading.Size();
const uint64 CollisionGateStartCycles = bTraceFrameTiming
? FPlatformTime::Cycles64() : 0;
UpdatePawnCollisionGate(PlayerPawn, PlayerLastPos, DeltaTime); UpdatePawnCollisionGate(PlayerPawn, PlayerLastPos, DeltaTime);
if (bTraceFrameTiming)
{
CollisionGateCycles += FPlatformTime::Cycles64() - CollisionGateStartCycles;
}
RecordHeadlessDigMotionFrame(PlayerPawn, PlayerLastPos, DeltaTime); RecordHeadlessDigMotionFrame(PlayerPawn, PlayerLastPos, DeltaTime);
ObserveHeadlessStrateCrossingTest(PlayerLastPos, PlayerPawn); ObserveHeadlessStrateCrossingTest(PlayerLastPos, PlayerPawn);
ObserveHeadlessCollisionGateStressTest(PlayerLastPos, PlayerPawn); ObserveHeadlessCollisionGateStressTest(PlayerLastPos, PlayerPawn);
const FVector StreamingCenterPosition = bHeadlessStreamingTestCenterOverride const FVector StreamingCenterPosition = bHeadlessStreamingTestCenterOverride
? LocalVoxelToWorld(HeadlessStreamingTestCenterVoxel) ? LocalVoxelToWorld(HeadlessStreamingTestCenterVoxel)
: PlayerLastPos; : PlayerLastPos;
const uint64 UpdateChunksStartCycles = bTraceFrameTiming
? FPlatformTime::Cycles64() : 0;
UpdateChunksAroundPosition(StreamingCenterPosition, PlayerPawn, PlayerHeading); UpdateChunksAroundPosition(StreamingCenterPosition, PlayerPawn, PlayerHeading);
if (bTraceFrameTiming)
{
UpdateChunksCycles += FPlatformTime::Cycles64() - UpdateChunksStartCycles;
}
if (AtmosphereManager) if (AtmosphereManager)
{ {
AtmosphereManager->UpdateForPlayer(PlayerLastPos); AtmosphereManager->UpdateForPlayer(PlayerLastPos);
@@ -7110,8 +7136,14 @@ void AVoxelWorld::Tick(float DeltaTime)
{ {
// Headless/server worlds without a local pawn still keep the Core fallback region // Headless/server worlds without a local pawn still keep the Core fallback region
// streamed; this is the same explicit anchor path used by BuildHost validation. // streamed; this is the same explicit anchor path used by BuildHost validation.
const uint64 UpdateChunksStartCycles = bTraceFrameTiming
? FPlatformTime::Cycles64() : 0;
UpdateChunksAroundPosition( UpdateChunksAroundPosition(
GetVoxelForgeCoreDefaultCenterWorld(), nullptr, FVector::ZeroVector); GetVoxelForgeCoreDefaultCenterWorld(), nullptr, FVector::ZeroVector);
if (bTraceFrameTiming)
{
UpdateChunksCycles += FPlatformTime::Cycles64() - UpdateChunksStartCycles;
}
} }
ReleasePawnCollisionGate(); ReleasePawnCollisionGate();
if (APawn* PreviousPawn = PawnTickPrerequisite.Get()) if (APawn* PreviousPawn = PawnTickPrerequisite.Get())
@@ -7160,18 +7192,48 @@ void AVoxelWorld::Tick(float DeltaTime)
GVoxelForgePendingTestModification = 1; GVoxelForgePendingTestModification = 1;
} }
} }
const uint64 PendingDrainStartCycles = bTraceFrameTiming
? FPlatformTime::Cycles64() : 0;
ProcessPendingChunks(); ProcessPendingChunks();
if (bTraceFrameTiming)
{
PendingDrainCycles += FPlatformTime::Cycles64() - PendingDrainStartCycles;
}
const uint64 PostApplyCallbacksStartCycles = bTraceFrameTiming
? FPlatformTime::Cycles64() : 0;
uint64 CallbackStartCycles = bTraceFrameTiming ? FPlatformTime::Cycles64() : 0;
PollStep1SupportSweepProbes(); PollStep1SupportSweepProbes();
if (bTraceFrameTiming)
{
CollisionProbeCycles += FPlatformTime::Cycles64() - CallbackStartCycles;
CallbackStartCycles = FPlatformTime::Cycles64();
}
ReconcileReadyTransitionVisibility(); ReconcileReadyTransitionVisibility();
if (bTraceFrameTiming)
{
VisibilityReconcileCycles += FPlatformTime::Cycles64() - CallbackStartCycles;
CallbackStartCycles = FPlatformTime::Cycles64();
}
PollStep1VisibleApplyProbes(); PollStep1VisibleApplyProbes();
if (bTraceFrameTiming)
{
VisibleApplyProbeCycles += FPlatformTime::Cycles64() - CallbackStartCycles;
CallbackStartCycles = FPlatformTime::Cycles64();
}
// Near-field evidence is independent of the full horizon settle point. Record one completion // Near-field evidence is independent of the full horizon settle point. Record one completion
// for each desired-set epoch after this frame's result drain, including moving crossings. // for each desired-set epoch after this frame's result drain, including moving crossings.
RecordLOD0RingReadyIfComplete(); RecordLOD0RingReadyIfComplete();
if (bTraceFrameTiming)
{
LOD0ReadyCycles += FPlatformTime::Cycles64() - CallbackStartCycles;
PostApplyCallbacksCycles += FPlatformTime::Cycles64() - PostApplyCallbacksStartCycles;
}
// The startup trace stops at the same point the streaming policy declares itself settled: // The startup trace stops at the same point the streaming policy declares itself settled:
// every desired key is loaded, no generation task remains, and the game-thread result drain // every desired key is loaded, no generation task remains, and the game-thread result drain
// has run for the frame. This is intentionally after ProcessPendingChunks so request-to-apply // has run for the frame. This is intentionally after ProcessPendingChunks so request-to-apply
// includes the final submission; the separate collision_ready events carry cook latency. // includes the final submission; the separate collision_ready events carry cook latency.
const uint64 SteadyTraceStartCycles = bTraceFrameTiming ? FPlatformTime::Cycles64() : 0;
if (VoxelForgeStartupTrace::IsActive() if (VoxelForgeStartupTrace::IsActive()
&& bAllChunksLoaded && bAllChunksLoaded
&& PendingTiles.Num() == 0 && PendingTiles.Num() == 0
@@ -7265,12 +7327,17 @@ void AVoxelWorld::Tick(float DeltaTime)
FPlatformMisc::RequestExit(false, TEXT("VoxelForge steady streaming measurement complete")); FPlatformMisc::RequestExit(false, TEXT("VoxelForge steady streaming measurement complete"));
} }
} }
if (bTraceFrameTiming)
{
SteadyTraceCycles += FPlatformTime::Cycles64() - SteadyTraceStartCycles;
}
// Complete the one-shot diagnostic request only after the player's level-0 centre tile is // Complete the one-shot diagnostic request only after the player's level-0 centre tile is
// loaded and idle. The edit fixture selects an already-visible level-0 geometry tile, so it // loaded and idle. The edit fixture selects an already-visible level-0 geometry tile, so it
// measures the normal synchronous centre remesh without depending on a coarse overlay being // measures the normal synchronous centre remesh without depending on a coarse overlay being
// visible. No pawn is distinct from a pawn at (0,0,0); retain the actor-location fallback for // visible. No pawn is distinct from a pawn at (0,0,0); retain the actor-location fallback for
// headless/editor use without making the world-origin pawn skip streaming. // headless/editor use without making the world-origin pawn skip streaming.
const uint64 ModificationStartCycles = bTraceFrameTiming ? FPlatformTime::Cycles64() : 0;
FVector ModificationPosition = bHasPlayer ? PlayerLastPos : GetActorLocation(); FVector ModificationPosition = bHasPlayer ? PlayerLastPos : GetActorLocation();
FVoxelTileKey ModificationCenterTile( FVoxelTileKey ModificationCenterTile(
GetTileCoordAtLocalCm(WorldToLocalCm(ModificationPosition)), 0); GetTileCoordAtLocalCm(WorldToLocalCm(ModificationPosition)), 0);
@@ -7360,9 +7427,25 @@ void AVoxelWorld::Tick(float DeltaTime)
ModificationCenterTile.Coord.X, ModificationCenterTile.Coord.Y, ModificationCenterTile.Coord.X, ModificationCenterTile.Coord.Y,
ModificationCenterTile.Coord.Z, bProofSurvivedCarve ? 1 : 0); ModificationCenterTile.Coord.Z, bProofSurvivedCarve ? 1 : 0);
} }
if (bTraceFrameTiming)
{
ModificationCycles += FPlatformTime::Cycles64() - ModificationStartCycles;
}
const uint64 UnloadStartCycles = bTraceFrameTiming
? FPlatformTime::Cycles64() : 0;
ProcessUnloadQueue(); ProcessUnloadQueue();
if (bTraceFrameTiming)
{
UnloadCycles += FPlatformTime::Cycles64() - UnloadStartCycles;
}
const uint64 LifecycleAuditStartCycles = bTraceFrameTiming
? FPlatformTime::Cycles64() : 0;
UpdateVisualStalenessAudit(); UpdateVisualStalenessAudit();
MaybeFinishHeadlessStreamingTest(); MaybeFinishHeadlessStreamingTest();
if (bTraceFrameTiming)
{
LifecycleAuditCycles += FPlatformTime::Cycles64() - LifecycleAuditStartCycles;
}
if (bTestCeilingViewEnabled) if (bTestCeilingViewEnabled)
{ {
@@ -7531,6 +7614,37 @@ void AVoxelWorld::Tick(float DeltaTime)
} }
} }
#endif #endif
if (bTraceFrameTiming && VoxelForgeStartupTrace::IsActive())
{
const VoxelForgeStartupTrace::FWriteMetrics TraceWriteMetrics =
VoxelForgeStartupTrace::ConsumeCurrentThreadWriteMetrics();
const uint64 TickEndCycles = FPlatformTime::Cycles64();
VoxelForgeStartupTrace::RecordEvent(TEXT("game_thread_work_frame"), FString::Printf(
TEXT("\"frame\":%llu,\"tick_ms\":%s,\"collision_gate_ms\":%s,"
"\"update_chunks_ms\":%s,\"pending_drain_ms\":%s,\"unload_ms\":%s,"
"\"post_apply_callbacks_ms\":%s,\"steady_trace_ms\":%s,"
"\"collision_probe_ms\":%s,\"visibility_reconcile_ms\":%s,"
"\"visible_apply_probe_ms\":%s,\"lod0_ready_ms\":%s,"
"\"modification_ms\":%s,\"lifecycle_audit_ms\":%s,"
"\"trace_json_ms\":%s,\"trace_archive_serialize_ms\":%s"),
static_cast<unsigned long long>(GFrameCounter),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(
TickEndCycles - TickStartCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(CollisionGateCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(UpdateChunksCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(PendingDrainCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(UnloadCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(PostApplyCallbacksCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(SteadyTraceCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(CollisionProbeCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(VisibilityReconcileCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(VisibleApplyProbeCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(LOD0ReadyCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(ModificationCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(LifecycleAuditCycles) * 1000.0),
*FString::SanitizeFloat(TraceWriteMetrics.JsonWriteMilliseconds),
*FString::SanitizeFloat(TraceWriteMetrics.ArchiveSerializeMilliseconds)));
}
} }
//============================================================================= //=============================================================================
@@ -7760,6 +7874,7 @@ bool AVoxelWorld::InitializeVoxelForgeCoreWorld(FString& OutFailureReason)
MakeShared<FVoxelForgeCoreRuntimeState, ESPMode::ThreadSafe>(); MakeShared<FVoxelForgeCoreRuntimeState, ESPMode::ThreadSafe>();
State->World = std::make_unique<VoxelForgeCore::World>(std::move(*Snapshot)); State->World = std::make_unique<VoxelForgeCore::World>(std::move(*Snapshot));
State->FullResolutionLodCount = State->World->configuration().fullResolutionLodCount; State->FullResolutionLodCount = State->World->configuration().fullResolutionLodCount;
CoreRenderDistanceChunks = State->World->configuration().renderDistanceChunks;
const bool bFarWorldRequired=State->World->configuration().maxLod const bool bFarWorldRequired=State->World->configuration().maxLod
>=State->FullResolutionLodCount; >=State->FullResolutionLodCount;
State->bFarWorldRequired.store(bFarWorldRequired,std::memory_order_release); State->bFarWorldRequired.store(bFarWorldRequired,std::memory_order_release);
@@ -7954,6 +8069,7 @@ void AVoxelWorld::FallBackToLegacyAfterCoreInitializationFailure(const FString&
StrateManager->SetHardTransitionFallbackForAssembly(false); StrateManager->SetHardTransitionFallbackForAssembly(false);
} }
CoreFallbackCenterLocalCm = FVector::ZeroVector; CoreFallbackCenterLocalCm = FVector::ZeroVector;
CoreRenderDistanceChunks = 0;
if (Mesher != nullptr) if (Mesher != nullptr)
{ {
Mesher->SetGeometryVoxelSizeCm(VOXEL_SIZE); Mesher->SetGeometryVoxelSizeCm(VOXEL_SIZE);
@@ -8481,6 +8597,7 @@ void AVoxelWorld::RequestCollisionGateSupportTile(const FVoxelTileKey& SupportTi
void AVoxelWorld::UpdatePawnCollisionGate(APawn* Pawn, const FVector& PlayerPosition, void AVoxelWorld::UpdatePawnCollisionGate(APawn* Pawn, const FVector& PlayerPosition,
float DeltaTime) float DeltaTime)
{ {
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_UpdatePawnCollisionGate);
if (!IsValid(Pawn) || bShuttingDown.load(std::memory_order_relaxed)) if (!IsValid(Pawn) || bShuttingDown.load(std::memory_order_relaxed))
{ {
return; return;
@@ -9280,6 +9397,10 @@ void AVoxelWorld::HandleTileCollisionCookComplete(
return; return;
} }
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_HandleTileCollisionCookComplete);
const bool bTraceCollisionCompletion = VoxelForgeStartupTrace::IsActive();
const uint64 TraceCollisionCompletionStartCycles = bTraceCollisionCompletion
? FPlatformTime::Cycles64() : 0;
if (bShuttingDown.load(std::memory_order_relaxed)) if (bShuttingDown.load(std::memory_order_relaxed))
{ {
return; return;
@@ -9524,6 +9645,16 @@ void AVoxelWorld::HandleTileCollisionCookComplete(
{ {
UpdatePawnCollisionGate(PlayerPawn, PlayerPosition, 0.0f); UpdatePawnCollisionGate(PlayerPawn, PlayerPosition, 0.0f);
} }
if (bTraceCollisionCompletion && VoxelForgeStartupTrace::IsActive())
{
const double HandlerMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceCollisionCompletionStartCycles) * 1000.0;
VoxelForgeStartupTrace::RecordEvent(TEXT("collision_completion"), FString::Printf(
TEXT("\"frame\":%llu,\"tile\":[%d,%d,%d],\"handler_ms\":%s"),
static_cast<unsigned long long>(GFrameCounter),
Tile.Coord.X, Tile.Coord.Y, Tile.Coord.Z,
*FString::SanitizeFloat(HandlerMilliseconds)));
}
} }
void AVoxelWorld::ProcessPendingChunks() void AVoxelWorld::ProcessPendingChunks()
@@ -10430,6 +10561,7 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility()
const FVisualGapAuditState* GapAudit = GVoxelForgeVisualGapAudits.Find(this); const FVisualGapAuditState* GapAudit = GVoxelForgeVisualGapAudits.Find(this);
const bool bUseLegacyVisualHandoff = GapAudit && GapAudit->bLegacyVisualHandoff; const bool bUseLegacyVisualHandoff = GapAudit && GapAudit->bLegacyVisualHandoff;
const bool bMeasure = bMeasureReadyTransitionVisibility; const bool bMeasure = bMeasureReadyTransitionVisibility;
const bool bTraceReconcile = VoxelForgeStartupTrace::IsActive();
const uint64 MeasureStartCycles = bMeasure ? FPlatformTime::Cycles64() : 0; const uint64 MeasureStartCycles = bMeasure ? FPlatformTime::Cycles64() : 0;
const int32 ComponentCountAtStart = bMeasure ? TileComponents.Num() : 0; const int32 ComponentCountAtStart = bMeasure ? TileComponents.Num() : 0;
const int32 DesiredCountAtStart = bMeasure ? DesiredSorted.Num() : 0; const int32 DesiredCountAtStart = bMeasure ? DesiredSorted.Num() : 0;
@@ -10464,6 +10596,7 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility()
// queue below. // queue below.
TArray<FVoxelTileKey> ReadyToHide; TArray<FVoxelTileKey> ReadyToHide;
ReadyToHide.Reserve(TileComponents.Num()); ReadyToHide.Reserve(TileComponents.Num());
uint64 CandidateScanCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0;
auto GetAncestorAtLevel = [](const FVoxelTileKey& Tile, int32 AncestorLevel) auto GetAncestorAtLevel = [](const FVoxelTileKey& Tile, int32 AncestorLevel)
{ {
const int32 Divisor = VF_ClipLevelScale(AncestorLevel - Tile.Level); const int32 Divisor = VF_ClipLevelScale(AncestorLevel - Tile.Level);
@@ -10529,11 +10662,16 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility()
ReadyToHide.Add(OldTile); ReadyToHide.Add(OldTile);
} }
} }
const uint64 CandidateScanElapsedCycles = bTraceReconcile
? FPlatformTime::Cycles64() - CandidateScanCycles : 0;
uint64 QueueUnloadCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0;
for (const FVoxelTileKey& Tile : ReadyToHide) for (const FVoxelTileKey& Tile : ReadyToHide)
{ {
QueuePendingUnload(Tile); QueuePendingUnload(Tile);
} }
const uint64 QueueUnloadElapsedCycles = bTraceReconcile
? FPlatformTime::Cycles64() - QueueUnloadCycles : 0;
// Replacement components may have been uploaded hidden while a retired tile still covered // Replacement components may have been uploaded hidden while a retired tile still covered
// only part of the transition. Reveal them only after every overlapping retired component has // only part of the transition. Reveal them only after every overlapping retired component has
@@ -10542,6 +10680,7 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility()
TSet<FVoxelTileKey> VisibleRetiredTiles; TSet<FVoxelTileKey> VisibleRetiredTiles;
TSet<FVoxelTileKey> VisibleRetiredAncestors; TSet<FVoxelTileKey> VisibleRetiredAncestors;
int32 MaxVisibleRetiredLevel = DesiredTransitionMaxLevel; int32 MaxVisibleRetiredLevel = DesiredTransitionMaxLevel;
uint64 RetiredIndexCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0;
for (const TPair<FVoxelTileKey, URealtimeMeshComponent*>& OldPair : TileComponents) for (const TPair<FVoxelTileKey, URealtimeMeshComponent*>& OldPair : TileComponents)
{ {
const FVoxelTileKey& OldTile = OldPair.Key; const FVoxelTileKey& OldTile = OldPair.Key;
@@ -10558,7 +10697,10 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility()
VisibleRetiredAncestors.Add(GetAncestorAtLevel(OldTile, Level)); VisibleRetiredAncestors.Add(GetAncestorAtLevel(OldTile, Level));
} }
} }
const uint64 RetiredIndexElapsedCycles = bTraceReconcile
? FPlatformTime::Cycles64() - RetiredIndexCycles : 0;
uint64 RevealCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0;
for (const TPair<FVoxelTileKey, URealtimeMeshComponent*>& NewPair : TileComponents) for (const TPair<FVoxelTileKey, URealtimeMeshComponent*>& NewPair : TileComponents)
{ {
const FVoxelTileKey& NewTile = NewPair.Key; const FVoxelTileKey& NewTile = NewPair.Key;
@@ -10582,8 +10724,24 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility()
NewComp->SetVisibility(true); NewComp->SetVisibility(true);
} }
} }
const uint64 RevealElapsedCycles = bTraceReconcile
? FPlatformTime::Cycles64() - RevealCycles : 0;
RecordMeasure(); RecordMeasure();
if (bTraceReconcile)
{
VoxelForgeStartupTrace::RecordEvent(TEXT("visibility_reconcile"), FString::Printf(
TEXT("\"frame\":%llu,\"tile_components\":%d,\"desired_tiles\":%d,"
"\"ready_to_hide\":%d,\"visible_retired\":%d,"
"\"candidate_scan_ms\":%s,\"queue_unload_ms\":%s,"
"\"retired_index_ms\":%s,\"reveal_ms\":%s"),
static_cast<unsigned long long>(GFrameCounter), TileComponents.Num(),
DesiredSorted.Num(), ReadyToHide.Num(), VisibleRetiredTiles.Num(),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(CandidateScanElapsedCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(QueueUnloadElapsedCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(RetiredIndexElapsedCycles) * 1000.0),
*FString::SanitizeFloat(FPlatformTime::ToSeconds64(RevealElapsedCycles) * 1000.0)));
}
} }
// Integer floor-division (correct for negatives), scalar + vector. // Integer floor-division (correct for negatives), scalar + vector.
@@ -10688,6 +10846,21 @@ void AVoxelWorld::BuildCoreDesiredTiles(const FIntVector& Center, const FVector&
APawn* PlayerPawn, const FVector& PlayerHeading, APawn* PlayerPawn, const FVector& PlayerHeading,
TArray<FVoxelTileKey>& OutLeavers) TArray<FVoxelTileKey>& OutLeavers)
{ {
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_BuildCoreDesiredTiles);
// Capture the resolved floor before rebuilding CollisionDesiredTiles. The gate request set
// drops keys as soon as they have a body, while the pawn-radius set may not include a floor
// tile below a known-empty band. Keeping the active support here prevents that body from
// being retired and re-requested every subsequent tick.
FVoxelTileKey SupportProbeTile;
FVoxelTileKey ResolvedSupportTile;
const bool bHasSupportProbe = GetPlayerSupportTile(
PlayerPawn, PlayerPosition, SupportProbeTile);
const TCHAR* SupportUnavailableReason = nullptr;
const bool bRetainResolvedSupport = bHasSupportProbe
&& IsCollisionReadyFromSupportTile(
SupportProbeTile, &ResolvedSupportTile, &SupportUnavailableReason)
&& SupportUnavailableReason == nullptr;
DesiredSorted.Reset(); DesiredSorted.Reset();
CriticalDesiredTiles.Reset(); CriticalDesiredTiles.Reset();
OutLeavers.Reset(); OutLeavers.Reset();
@@ -10794,6 +10967,17 @@ void AVoxelWorld::BuildCoreDesiredTiles(const FIntVector& Center, const FVector&
CollisionAnchorTiles.Add(Key); CollisionAnchorTiles.Add(Key);
} }
if (bRetainResolvedSupport)
{
AddCandidate(ResolvedSupportTile);
CollisionDesiredTiles.Add(ResolvedSupportTile);
if (!BaseVisualTiles.Contains(ResolvedSupportTile)
&& !FullVisualAnchorTiles.Contains(ResolvedSupportTile))
{
CollisionAnchorTiles.Add(ResolvedSupportTile);
}
}
const FVoxelTileKey PlayerTile(GetTileCoordAtLocalCm(WorldToLocalCm(PlayerPosition)), 0); const FVoxelTileKey PlayerTile(GetTileCoordAtLocalCm(WorldToLocalCm(PlayerPosition)), 0);
FVoxelTileKey OccupiedTile = PlayerTile; FVoxelTileKey OccupiedTile = PlayerTile;
FVoxelTileKey SupportTile; FVoxelTileKey SupportTile;
@@ -11724,15 +11908,8 @@ bool AVoxelWorld::IsTileInClipRange(const FVoxelTileKey& Tile, const FIntVector&
int32 MaxLevel = MaxLevelBase, ROuter = R; int32 MaxLevel = MaxLevelBase, ROuter = R;
if (bUseVoxelForgeCore) if (bUseVoxelForgeCore)
{ {
VoxelForgeCore::WorldConfiguration Configuration;
const TSharedPtr<FVoxelForgeCoreRuntimeState, ESPMode::ThreadSafe> State = VoxelForgeCoreState;
if (State.IsValid())
{
FReadScopeLock Lock(State->WorldLock);
if (State->World) Configuration = State->World->configuration();
}
VoxelClipmapDesiredTiles::FParameters Parameters; VoxelClipmapDesiredTiles::FParameters Parameters;
Parameters.RenderDistanceChunks = Configuration.renderDistanceChunks; Parameters.RenderDistanceChunks = CoreRenderDistanceChunks;
VoxelClipmapDesiredTiles::OuterShell(Parameters, R, MaxLevelBase, MaxLevel, ROuter); VoxelClipmapDesiredTiles::OuterShell(Parameters, R, MaxLevelBase, MaxLevel, ROuter);
} }
else else
@@ -11912,6 +12089,12 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
const uint64 ResultBacklogCapStopsAtUpdateEntry = const uint64 ResultBacklogCapStopsAtUpdateEntry =
StreamingResultBacklogCapStops.load(std::memory_order_relaxed); StreamingResultBacklogCapStops.load(std::memory_order_relaxed);
double DesiredRebuildMilliseconds = 0.0; double DesiredRebuildMilliseconds = 0.0;
double SubmitTilesMilliseconds = 0.0;
double SubmitLevelMilliseconds = 0.0;
double LevelCandidateScanMilliseconds = 0.0;
double PassageScoreMilliseconds = 0.0;
double LevelSortMilliseconds = 0.0;
double LevelAdmissionMilliseconds = 0.0;
const auto RecordSchedulerSkip = [&](const TCHAR* Reason) const auto RecordSchedulerSkip = [&](const TCHAR* Reason)
{ {
if (!bTraceStreamingScheduler) return; if (!bTraceStreamingScheduler) return;
@@ -12569,6 +12752,8 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
// Le travail grossier reste sous le budget total pour reserver des admissions aux tuiles proches. // Le travail grossier reste sous le budget total pour reserver des admissions aux tuiles proches.
//========================================================================= //=========================================================================
const bool bSubmissionLoopRan = !bAllChunksLoaded; const bool bSubmissionLoopRan = !bAllChunksLoaded;
const uint64 TraceSubmitTilesStartCycles = bTraceStreamingScheduler && bSubmissionLoopRan
? FPlatformTime::Cycles64() : 0;
if (bSubmissionLoopRan) if (bSubmissionLoopRan)
{ {
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_SubmitTiles); TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_SubmitTiles);
@@ -12644,12 +12829,21 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
auto SubmitLevel = [&](int32 Level, EVoxelTileWorkPriority Priority, int32 AdmissionCap, auto SubmitLevel = [&](int32 Level, EVoxelTileWorkPriority Priority, int32 AdmissionCap,
bool bPreferTravelDirection) bool bPreferTravelDirection)
{ {
const uint64 TraceLevelStartCycles = bTraceStreamingScheduler
? FPlatformTime::Cycles64() : 0;
if (GetGenerationAdmissionCount() >= AdmissionCap) if (GetGenerationAdmissionCount() >= AdmissionCap)
{ {
if (Level >= 0 && Level < 9) { ++SchedulerLevelCapReturns[Level]; } if (Level >= 0 && Level < 9) { ++SchedulerLevelCapReturns[Level]; }
if (bTraceStreamingScheduler)
{
SubmitLevelMilliseconds += FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceLevelStartCycles) * 1000.0;
}
return; return;
} }
TArray<FVoxelTileKey> LevelTiles; TArray<FVoxelTileKey> LevelTiles;
const uint64 TraceCandidateScanStartCycles = bTraceStreamingScheduler
? FPlatformTime::Cycles64() : 0;
for (const FVoxelTileKey& T : DesiredSorted) for (const FVoxelTileKey& T : DesiredSorted)
{ {
if (T.Level == Level && !PendingTiles.Contains(T) && !LoadedTiles.Contains(T)) if (T.Level == Level && !PendingTiles.Contains(T) && !LoadedTiles.Contains(T))
@@ -12657,25 +12851,16 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
LevelTiles.Add(T); LevelTiles.Add(T);
} }
} }
// Sort only outstanding keys; re-sorting loaded or pending tiles on every tick inflated game-thread work. if (bTraceStreamingScheduler)
// Trier uniquement les cles restantes ; re-trier chaque tick les tuiles chargees ou en attente alourdissait le thread de jeu.
TMap<FVoxelTileKey,uint32> PassageScores;
if(Level<=2&&CoreState.IsValid()&&CoreState->bReady.load(std::memory_order_acquire))
{ {
FReadScopeLock WorldReadLock(CoreState->WorldLock); LevelCandidateScanMilliseconds += FPlatformTime::ToSeconds64(
if(CoreState->World) FPlatformTime::Cycles64() - TraceCandidateScanStartCycles) * 1000.0;
{
PassageScores.Reserve(LevelTiles.Num());
for(const FVoxelTileKey& Key:LevelTiles)
{
const VoxelForgeCore::TileKey CoreKey{
{Key.Coord.X,Key.Coord.Y,Key.Coord.Z},Key.Level};
PassageScores.Add(Key,CoreState->World->passageOverlapScore(CoreKey));
} }
} // Keep admission work bounded. Recomputing passageOverlapScore for every outstanding
} // near tile rescanned all resolved passage segments on every frame and could consume
const bool bSortForPassagePriority=Level<=2&&!PassageScores.IsEmpty(); // >120 ms on the game thread. DesiredSorted already has deterministic near/distance
if ((bPreferTravelDirection||bSortForPassagePriority)&&LevelTiles.Num()>1) // order; this optional sort only adds the current travel heading and distance.
if (bPreferTravelDirection && LevelTiles.Num() > 1)
{ {
FVector Heading=FVector::ZeroVector; FVector Heading=FVector::ZeroVector;
FVector PlayerLocalCm=FVector::ZeroVector; FVector PlayerLocalCm=FVector::ZeroVector;
@@ -12693,16 +12878,11 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
TileSizeCm=static_cast<double>(VF_ClipLevelExtentVoxels(Level)) TileSizeCm=static_cast<double>(VF_ClipLevelExtentVoxels(Level))
*GetActiveVoxelSizeCm(); *GetActiveVoxelSizeCm();
} }
const uint64 TraceLevelSortStartCycles = bTraceStreamingScheduler
? FPlatformTime::Cycles64() : 0;
std::stable_sort(LevelTiles.GetData(),LevelTiles.GetData()+LevelTiles.Num(), std::stable_sort(LevelTiles.GetData(),LevelTiles.GetData()+LevelTiles.Num(),
[&](const FVoxelTileKey& A,const FVoxelTileKey& B) [&](const FVoxelTileKey& A,const FVoxelTileKey& B)
{ {
if(bSortForPassagePriority)
{
const uint32 ScoreA=PassageScores.FindRef(A);
const uint32 ScoreB=PassageScores.FindRef(B);
if(ScoreA!=ScoreB)return ScoreA>ScoreB;
}
if(!bPreferTravelDirection)return false;
const FVector CenterA( const FVector CenterA(
(static_cast<double>(A.Coord.X) + 0.5) * TileSizeCm, (static_cast<double>(A.Coord.X) + 0.5) * TileSizeCm,
(static_cast<double>(A.Coord.Y) + 0.5) * TileSizeCm, (static_cast<double>(A.Coord.Y) + 0.5) * TileSizeCm,
@@ -12723,7 +12903,14 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
if (A.Coord.Y != B.Coord.Y) return A.Coord.Y < B.Coord.Y; if (A.Coord.Y != B.Coord.Y) return A.Coord.Y < B.Coord.Y;
return A.Coord.Z < B.Coord.Z; return A.Coord.Z < B.Coord.Z;
}); });
if (bTraceStreamingScheduler)
{
LevelSortMilliseconds += FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceLevelSortStartCycles) * 1000.0;
} }
}
const uint64 TraceLevelAdmissionStartCycles = bTraceStreamingScheduler
? FPlatformTime::Cycles64() : 0;
for (const FVoxelTileKey& T : LevelTiles) for (const FVoxelTileKey& T : LevelTiles)
{ {
if (GetGenerationAdmissionCount() >= AdmissionCap) if (GetGenerationAdmissionCount() >= AdmissionCap)
@@ -12736,6 +12923,13 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
SubmitTileWithTraceCount(T, Priority); SubmitTileWithTraceCount(T, Priority);
++Submitted; ++Submitted;
} }
if (bTraceStreamingScheduler)
{
LevelAdmissionMilliseconds += FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceLevelAdmissionStartCycles) * 1000.0;
SubmitLevelMilliseconds += FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceLevelStartCycles) * 1000.0;
}
}; };
const auto AreCriticalTilesReady = [this]() const auto AreCriticalTilesReady = [this]()
@@ -13003,6 +13197,11 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
bAllChunksLoaded = true; bAllChunksLoaded = true;
} }
} }
if (TraceSubmitTilesStartCycles != 0)
{
SubmitTilesMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceSubmitTilesStartCycles) * 1000.0;
}
if (VoxelForgeStartupTrace::IsActive()) if (VoxelForgeStartupTrace::IsActive())
{ {
@@ -13220,6 +13419,8 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
? LastStreamingSchedulerSampleSeconds : StreamingUpdateStartSeconds; ? LastStreamingSchedulerSampleSeconds : StreamingUpdateStartSeconds;
const double IntervalSeconds = FMath::Max(0.0, SchedulerTraceNow - IntervalStart); const double IntervalSeconds = FMath::Max(0.0, SchedulerTraceNow - IntervalStart);
const double BusySeconds = FPlatformTime::ToSeconds64(WorkerCyclesDelta); const double BusySeconds = FPlatformTime::ToSeconds64(WorkerCyclesDelta);
const double SchedulerUpdateMilliseconds = (SchedulerTraceNow
- StreamingUpdateStartSeconds) * 1000.0;
VoxelForgeStartupTrace::RecordEvent(TEXT("scheduler_admission"), FString::Printf( VoxelForgeStartupTrace::RecordEvent(TEXT("scheduler_admission"), FString::Printf(
TEXT("\"frame\":%llu,\"center\":[%d,%d,%d],\"desired_rebuilt\":%d," TEXT("\"frame\":%llu,\"center\":[%d,%d,%d],\"desired_rebuilt\":%d,"
"\"submission_loop_ran\":%d,\"all_chunks_loaded\":%d," "\"submission_loop_ran\":%d,\"all_chunks_loaded\":%d,"
@@ -13238,6 +13439,10 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
"\"result_backlog\":%d,\"result_backlog_cap\":%d," "\"result_backlog\":%d,\"result_backlog_cap\":%d,"
"\"region_independent_submissions\":%llu,\"region_dependent_declines\":%llu," "\"region_independent_submissions\":%llu,\"region_dependent_declines\":%llu,"
"\"worker_busy_s_interval\":%s,\"worker_busy_avg\":%s," "\"worker_busy_s_interval\":%s,\"worker_busy_avg\":%s,"
"\"update_chunks_ms\":%s,\"desired_rebuild_ms\":%s,"
"\"submit_tiles_ms\":%s,\"submit_level_ms\":%s,"
"\"level_candidate_scan_ms\":%s,\"passage_score_ms\":%s,"
"\"level_sort_ms\":%s,\"level_admit_ms\":%s,"
"\"desired_missing_by_lod\":%s,\"loaded_by_lod\":%s,\"pending_by_lod\":%s," "\"desired_missing_by_lod\":%s,\"loaded_by_lod\":%s,\"pending_by_lod\":%s,"
"\"submitted_by_lod\":%s,\"load_attempts_by_lod\":%s," "\"submitted_by_lod\":%s,\"load_attempts_by_lod\":%s,"
"\"admission_cap_by_lod\":%s,\"declined_rule_by_lod\":%s," "\"admission_cap_by_lod\":%s,\"declined_rule_by_lod\":%s,"
@@ -13265,6 +13470,14 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw
static_cast<unsigned long long>(CoreRegionDependentDeclines), static_cast<unsigned long long>(CoreRegionDependentDeclines),
*FString::SanitizeFloat(BusySeconds), *FString::SanitizeFloat(BusySeconds),
*FString::SanitizeFloat(IntervalSeconds > 0.0 ? BusySeconds / IntervalSeconds : 0.0), *FString::SanitizeFloat(IntervalSeconds > 0.0 ? BusySeconds / IntervalSeconds : 0.0),
*FString::SanitizeFloat(SchedulerUpdateMilliseconds),
*FString::SanitizeFloat(DesiredRebuildMilliseconds),
*FString::SanitizeFloat(SubmitTilesMilliseconds),
*FString::SanitizeFloat(SubmitLevelMilliseconds),
*FString::SanitizeFloat(LevelCandidateScanMilliseconds),
*FString::SanitizeFloat(PassageScoreMilliseconds),
*FString::SanitizeFloat(LevelSortMilliseconds),
*FString::SanitizeFloat(LevelAdmissionMilliseconds),
*IntArrayJson(DesiredMissingByLevel), *IntArrayJson(LoadedByLevel), *IntArrayJson(DesiredMissingByLevel), *IntArrayJson(LoadedByLevel),
*IntArrayJson(PendingByLevel), *IntArrayJson(SchedulerSubmittedByLevel), *IntArrayJson(PendingByLevel), *IntArrayJson(SchedulerSubmittedByLevel),
*IntArrayJson(SchedulerLoadAttemptsByLevel), *IntArrayJson(AdmissionCapByLevel), *IntArrayJson(SchedulerLoadAttemptsByLevel), *IntArrayJson(AdmissionCapByLevel),
@@ -14583,7 +14796,12 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_ApplyMeshToChunk); TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_ApplyMeshToChunk);
const bool bProfileApply = GVoxelForgeProfileTileGeneration != 0; const bool bProfileApply = GVoxelForgeProfileTileGeneration != 0;
const bool bTraceRmcTiming = VoxelForgeStartupTrace::IsActive();
const uint64 ApplyStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0; const uint64 ApplyStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0;
double TraceComponentAcquireMilliseconds = 0.0;
double TraceSectionGroupMilliseconds = 0.0;
double TraceSectionConfigMilliseconds = 0.0;
double TraceCollisionHandoffMilliseconds = 0.0;
// Streams are pre-built on the worker (T1.f) and guaranteed non-empty by the caller // Streams are pre-built on the worker (T1.f) and guaranteed non-empty by the caller
// (ProcessPendingChunks skips empty tiles). This path is game-thread-CHEAP: material lookup + // (ProcessPendingChunks skips empty tiles). This path is game-thread-CHEAP: material lookup +
@@ -14704,10 +14922,19 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
bool bComponentCreated = false; bool bComponentCreated = false;
if (!MeshComp) if (!MeshComp)
{ {
const uint64 TraceStartCycles = bTraceRmcTiming ? FPlatformTime::Cycles64() : 0;
{
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CreateTileComponent);
MeshComp = AcquireTileComponent( MeshComp = AcquireTileComponent(
bProfileApply ? &ComponentCreationSeconds : nullptr, bProfileApply ? &ComponentCreationSeconds : nullptr,
bProfileApply ? &ComponentRegistrationSeconds : nullptr, bProfileApply ? &ComponentRegistrationSeconds : nullptr,
&bComponentCreated); &bComponentCreated);
}
if (bTraceRmcTiming)
{
TraceComponentAcquireMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceStartCycles) * 1000.0;
}
TileComponents.Add(Tile, MeshComp); TileComponents.Add(Tile, MeshComp);
} }
if (!IsValid(MeshComp)) if (!IsValid(MeshComp))
@@ -14804,7 +15031,17 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
// CreateSectionGroup. Keep this as one phase: it is the exact plugin/RMC boundary we can // CreateSectionGroup. Keep this as one phase: it is the exact plugin/RMC boundary we can
// budget without modifying RealtimeMeshComponent. // budget without modifying RealtimeMeshComponent.
const uint64 StreamUploadStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0; const uint64 StreamUploadStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0;
const uint64 TraceSectionGroupStartCycles = bTraceRmcTiming
? FPlatformTime::Cycles64() : 0;
{
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CreateSectionGroup);
RTMesh->CreateSectionGroup(GroupKey, MoveTemp(Streams)); RTMesh->CreateSectionGroup(GroupKey, MoveTemp(Streams));
}
if (bTraceRmcTiming)
{
TraceSectionGroupMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceSectionGroupStartCycles) * 1000.0;
}
const uint64 MeshSubmittedCycles = FPlatformTime::Cycles64(); const uint64 MeshSubmittedCycles = FPlatformTime::Cycles64();
const double StreamUploadSeconds = bProfileApply const double StreamUploadSeconds = bProfileApply
? FPlatformTime::ToSeconds64(FPlatformTime::Cycles64() - StreamUploadStartCycles) ? FPlatformTime::ToSeconds64(FPlatformTime::Cycles64() - StreamUploadStartCycles)
@@ -14816,9 +15053,13 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
// (default config already maps material slot = polygroup index); only config sections that // (default config already maps material slot = polygroup index); only config sections that
// exist — the bHas* flags come from the worker. Collision at level 0 only (T1.c), both groups. // exist — the bHas* flags come from the worker. Collision at level 0 only (T1.c), both groups.
const uint64 CollisionConfigStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0; const uint64 CollisionConfigStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0;
const uint64 TraceSectionConfigStartCycles = bTraceRmcTiming
? FPlatformTime::Cycles64() : 0;
const int32 NumIndices = Result.NumTriangles * 3; const int32 NumIndices = Result.NumTriangles * 3;
const int32 FirstCapIndex = FMath::Clamp( const int32 FirstCapIndex = FMath::Clamp(
NumIndices - Result.NumCeilingTriangles * 3, 0, NumIndices); NumIndices - Result.NumCeilingTriangles * 3, 0, NumIndices);
{
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CreateSections);
if (bHasGroundTris) if (bHasGroundTris)
{ {
FRealtimeMeshSectionConfig GroundConfig(0); FRealtimeMeshSectionConfig GroundConfig(0);
@@ -14841,6 +15082,12 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
FRealtimeMeshSectionKey::CreateForPolyGroup(GroupKey, 1), FRealtimeMeshSectionKey::CreateForPolyGroup(GroupKey, 1),
CapConfig, CapRange, /*bShouldCreateCollision*/ bWantsCollision); CapConfig, CapRange, /*bShouldCreateCollision*/ bWantsCollision);
} }
}
if (bTraceRmcTiming)
{
TraceSectionConfigMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceSectionConfigStartCycles) * 1000.0;
}
const double CollisionConfigSeconds = bProfileApply const double CollisionConfigSeconds = bProfileApply
? FPlatformTime::ToSeconds64(FPlatformTime::Cycles64() - CollisionConfigStartCycles) ? FPlatformTime::ToSeconds64(FPlatformTime::Cycles64() - CollisionConfigStartCycles)
: 0.0; : 0.0;
@@ -14888,11 +15135,14 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
// Register the serial before asking RMC to dirty collision. The current implementation // Register the serial before asking RMC to dirty collision. The current implementation
// defers the future to end-of-frame, but this ordering also keeps an already-fulfilled // defers the future to end-of-frame, but this ordering also keeps an already-fulfilled
// future or an inline body-update event from racing the per-tile record. // future or an inline body-update event from racing the per-tile record.
TFuture<ERealtimeMeshCollisionUpdateResult> CollisionFuture =
RTMesh->SetCollisionConfig(CollisionConfig);
TWeakObjectPtr<AVoxelWorld> WeakWorld(this); TWeakObjectPtr<AVoxelWorld> WeakWorld(this);
TWeakObjectPtr<URealtimeMesh> WeakMesh(RTMesh); TWeakObjectPtr<URealtimeMesh> WeakMesh(RTMesh);
const uint64 TraceCollisionHandoffStartCycles = bTraceRmcTiming
? FPlatformTime::Cycles64() : 0;
{
TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CollisionHandoff);
TFuture<ERealtimeMeshCollisionUpdateResult> CollisionFuture =
RTMesh->SetCollisionConfig(CollisionConfig);
CollisionFuture.Next( CollisionFuture.Next(
[WeakWorld, WeakMesh, Tile, SubmissionId](ERealtimeMeshCollisionUpdateResult CollisionResult) [WeakWorld, WeakMesh, Tile, SubmissionId](ERealtimeMeshCollisionUpdateResult CollisionResult)
{ {
@@ -14904,6 +15154,12 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
} }
}); });
} }
if (bTraceRmcTiming)
{
TraceCollisionHandoffMilliseconds = FPlatformTime::ToSeconds64(
FPlatformTime::Cycles64() - TraceCollisionHandoffStartCycles) * 1000.0;
}
}
if (bProfileApply) if (bProfileApply)
{ {
@@ -14931,6 +15187,20 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result)
TotalSeconds); TotalSeconds);
} }
if (bTraceRmcTiming)
{
VoxelForgeStartupTrace::RecordEvent(TEXT("rmc_submit"), FString::Printf(
TEXT("\"frame\":%llu,\"tile\":[%d,%d,%d],\"level\":%d,"
"\"component_acquire_ms\":%s,\"create_section_group_ms\":%s,"
"\"create_sections_ms\":%s,\"collision_handoff_ms\":%s"),
static_cast<unsigned long long>(GFrameCounter),
Tile.Coord.X, Tile.Coord.Y, Tile.Coord.Z, Tile.Level,
*FString::SanitizeFloat(TraceComponentAcquireMilliseconds),
*FString::SanitizeFloat(TraceSectionGroupMilliseconds),
*FString::SanitizeFloat(TraceSectionConfigMilliseconds),
*FString::SanitizeFloat(TraceCollisionHandoffMilliseconds)));
}
// Water is not spawned per tile — it's a single player-following ocean plane (UpdateWater, // Water is not spawned per tile — it's a single player-following ocean plane (UpdateWater,
// driven from Tick), so it renders at every LOD and to the horizon with no per-tile gaps. // driven from Tick), so it renders at every LOD and to the horizon with no per-tile gaps.
return true; return true;
@@ -69,11 +69,20 @@ namespace VoxelForgeStartupTrace
TStaticArray<double, 9> ApplySecondsByLevel{}; TStaticArray<double, 9> ApplySecondsByLevel{};
}; };
struct VOXELFORGE_API FWriteMetrics
{
double JsonWriteMilliseconds = 0.0;
double ArchiveSerializeMilliseconds = 0.0;
};
/** Starts when -voxel.StartupTraceFile=<absolute path> is present. */ /** Starts when -voxel.StartupTraceFile=<absolute path> is present. */
VOXELFORGE_API void BeginFromCommandLine(); VOXELFORGE_API void BeginFromCommandLine();
VOXELFORGE_API bool IsActive(); VOXELFORGE_API bool IsActive();
/** Returns and resets startup-trace writes performed by the current game-thread frame. */
VOXELFORGE_API FWriteMetrics ConsumeCurrentThreadWriteMetrics();
/** FieldsJson is the contents after the type/timestamp object prefix, without braces. */ /** FieldsJson is the contents after the type/timestamp object prefix, without braces. */
VOXELFORGE_API void RecordEvent(const TCHAR* Type, const FString& FieldsJson = FString()); VOXELFORGE_API void RecordEvent(const TCHAR* Type, const FString& FieldsJson = FString());
+1
View File
@@ -790,6 +790,7 @@ private:
FString VoxelForgeCoreResolvedLayoutJson; FString VoxelForgeCoreResolvedLayoutJson;
FString VoxelForgeCoreResolvedLayoutIdentity; FString VoxelForgeCoreResolvedLayoutIdentity;
FVector CoreFallbackCenterLocalCm = FVector::ZeroVector; FVector CoreFallbackCenterLocalCm = FVector::ZeroVector;
int32 CoreRenderDistanceChunks = 0;
bool bCoreRegionCompilePending = false; bool bCoreRegionCompilePending = false;
TArray<FVoxelTileKey> PendingCoreRegionTiles; TArray<FVoxelTileKey> PendingCoreRegionTiles;
TSet<FVoxelTileKey> PendingCoreRegionTileSet; TSet<FVoxelTileKey> PendingCoreRegionTileSet;
@@ -18172,11 +18172,60 @@ bool RunCoreWorldActorIntegrationTest(const FExploreArguments& Arguments, FStrin
TArray<double> SpawnTickMilliseconds; TArray<double> SpawnTickMilliseconds;
TArray<double> WalkTickMilliseconds; TArray<double> WalkTickMilliseconds;
TArray<TPair<double, double>> TickSamples; TArray<TPair<double, double>> TickSamples;
double WorldTickStartedSeconds = 0.0;
double WorldActorPhaseStartedSeconds = 0.0;
double WorldPostActorStartedSeconds = 0.0;
double WorldPreActorMilliseconds = 0.0;
double WorldActorPhaseMilliseconds = 0.0;
double WorldPostActorMilliseconds = 0.0;
const FDelegateHandle WorldTickStartHandle = FWorldDelegates::OnWorldTickStart.AddLambda(
[&](UWorld* World, ELevelTick, float)
{
if (World == TestWorld)
{
WorldTickStartedSeconds = FPlatformTime::Seconds();
}
});
const FDelegateHandle WorldPreActorTickHandle = FWorldDelegates::OnWorldPreActorTick.AddLambda(
[&](UWorld* World, ELevelTick, float)
{
if (World == TestWorld)
{
const double NowSeconds = FPlatformTime::Seconds();
WorldPreActorMilliseconds =
(NowSeconds - WorldTickStartedSeconds) * 1000.0;
WorldActorPhaseStartedSeconds = NowSeconds;
}
});
const FDelegateHandle WorldPostActorTickHandle = FWorldDelegates::OnWorldPostActorTick.AddLambda(
[&](UWorld* World, ELevelTick, float)
{
if (World == TestWorld)
{
const double NowSeconds = FPlatformTime::Seconds();
WorldActorPhaseMilliseconds =
(NowSeconds - WorldActorPhaseStartedSeconds) * 1000.0;
WorldPostActorStartedSeconds = NowSeconds;
}
});
const FDelegateHandle WorldTickEndHandle = FWorldDelegates::OnWorldTickEnd.AddLambda(
[&](UWorld* World, ELevelTick, float)
{
if (World == TestWorld)
{
WorldPostActorMilliseconds =
(FPlatformTime::Seconds() - WorldPostActorStartedSeconds) * 1000.0;
}
});
bool bInitialSetReady = false; bool bInitialSetReady = false;
double InitialSetReadySeconds = -1.0; double InitialSetReadySeconds = -1.0;
while (FPlatformTime::Seconds() - ActorBeginSeconds < RunDurationSeconds) while (FPlatformTime::Seconds() - ActorBeginSeconds < RunDurationSeconds)
{ {
const double TickStartSeconds = FPlatformTime::Seconds(); const double TickStartSeconds = FPlatformTime::Seconds();
const uint64 TickFrame = GFrameCounter;
WorldPreActorMilliseconds = 0.0;
WorldActorPhaseMilliseconds = 0.0;
WorldPostActorMilliseconds = 0.0;
TestWorld->Tick(LEVELTICK_All, 0.016f); TestWorld->Tick(LEVELTICK_All, 0.016f);
const double TickMilliseconds = const double TickMilliseconds =
(FPlatformTime::Seconds() - TickStartSeconds) * 1000.0; (FPlatformTime::Seconds() - TickStartSeconds) * 1000.0;
@@ -18184,6 +18233,7 @@ bool RunCoreWorldActorIntegrationTest(const FExploreArguments& Arguments, FStrin
const double ElapsedSeconds = FPlatformTime::Seconds() - ActorBeginSeconds; const double ElapsedSeconds = FPlatformTime::Seconds() - ActorBeginSeconds;
TickSamples.Emplace(ElapsedSeconds, TickMilliseconds); TickSamples.Emplace(ElapsedSeconds, TickMilliseconds);
const double ReadinessCheckStartSeconds = FPlatformTime::Seconds();
if (!bInitialSetReady && Actor->IsVoxelForgeCoreReady() if (!bInitialSetReady && Actor->IsVoxelForgeCoreReady()
&& Actor->bAllChunksLoaded && Actor->PendingTiles.IsEmpty() && Actor->bAllChunksLoaded && Actor->PendingTiles.IsEmpty()
&& Actor->PendingCollisionCooks.IsEmpty() && Actor->PendingUnload.IsEmpty() && Actor->PendingCollisionCooks.IsEmpty() && Actor->PendingUnload.IsEmpty()
@@ -18198,8 +18248,30 @@ bool RunCoreWorldActorIntegrationTest(const FExploreArguments& Arguments, FStrin
Actor->LoadedTiles.Num(), Actor->CollisionDesiredTiles.Num(), Actor->LoadedTiles.Num(), Actor->CollisionDesiredTiles.Num(),
Actor->CollisionReadyTiles.Num())); Actor->CollisionReadyTiles.Num()));
} }
const double ReadinessCheckMilliseconds =
(FPlatformTime::Seconds() - ReadinessCheckStartSeconds) * 1000.0;
const double SleepStartSeconds = FPlatformTime::Seconds();
FPlatformProcess::Sleep(0.016f); FPlatformProcess::Sleep(0.016f);
const double SleepMilliseconds =
(FPlatformTime::Seconds() - SleepStartSeconds) * 1000.0;
VoxelForgeStartupTrace::RecordEvent(TEXT("commandlet_world_tick_frame"), FString::Printf(
TEXT("\"frame\":%llu,\"world_tick_ms\":%s,"
"\"world_pre_actor_ms\":%s,\"world_actor_phase_ms\":%s,"
"\"world_post_actor_ms\":%s,"
"\"readiness_check_ms\":%s,\"sleep_ms\":%s,\"loop_ms\":%s"),
static_cast<unsigned long long>(TickFrame),
*FString::SanitizeFloat(TickMilliseconds),
*FString::SanitizeFloat(WorldPreActorMilliseconds),
*FString::SanitizeFloat(WorldActorPhaseMilliseconds),
*FString::SanitizeFloat(WorldPostActorMilliseconds),
*FString::SanitizeFloat(ReadinessCheckMilliseconds),
*FString::SanitizeFloat(SleepMilliseconds),
*FString::SanitizeFloat((FPlatformTime::Seconds() - TickStartSeconds) * 1000.0)));
} }
FWorldDelegates::OnWorldTickStart.Remove(WorldTickStartHandle);
FWorldDelegates::OnWorldPreActorTick.Remove(WorldPreActorTickHandle);
FWorldDelegates::OnWorldPostActorTick.Remove(WorldPostActorTickHandle);
FWorldDelegates::OnWorldTickEnd.Remove(WorldTickEndHandle);
for (const TPair<double, double>& Sample : TickSamples) for (const TPair<double, double>& Sample : TickSamples)
{ {
@@ -0,0 +1,40 @@
# Linux L96: WorldAssembler frame spikes
## What the timings show
The starting point is L95 after its queue fix. `frame_ms` is the interval between apply-frame entries, not a rendered VR frame; this commandlet manually ticks the world and sleeps about 16 ms each loop.
| Arrival | L95 p95 / max interval | L96 p95 / max interval |
|---|---:|---:|
| FI | 20.8–21.3 / 118–122 ms | 19.25–20.12 / 22.4–202.8 ms (5 runs) |
| SW | 24.7–27.6 / 118–145 ms | 23.27–25.12 / 25.08–30.98 ms (6 runs) |
I used a target of p99 ≤16 ms and max ≤25 ms for our `AVoxelWorld::Tick` work. That scope met it:
| Arrival | `AVoxelWorld::Tick` p99 | Maximum |
|---|---:|---:|
| FI | 3.71–4.26 ms | 4.12–6.04 ms |
| SW | 8.24–8.89 ms | 8.39–11.19 ms |
The residual FI interval spike is outside that actor scope. A repeat measured `AVoxelWorld::Tick` at 2.17 ms and the enclosing `UWorld::Tick` at 39.50 ms; 39.46 ms fell between Unreal’s pre-actor and post-actor tick delegates. Another FI repeat measured a 62.23 ms full world tick, with a 16.16 ms commandlet sleep in the same loop. The earlier 202.8 ms interval had a 185.6 ms aggregate `TestWorld->Tick` maximum. These are measured world/tick-group delays; the specific engine child timer was not isolated. A task-group wait or scheduling stall is inference, not proven. SW’s full-world-tick p99 was 8.78–11.79 ms, max 14.82 ms.
GC callbacks recorded zero collections during all measured bursts. RMC section-group creation peaked at 2.37 ms; collision handoff at 0.022 ms and completion handling at 3.96 ms. Per-frame JSON writing peaked at 1.46 ms; final trace flush peaked at 4.99 ms during teardown. The commandlet readiness check stayed below 0.01 ms, while its deliberate sleep was normally 16.2 ms. These commandlet timings cannot explain the 39–62 ms world tick by themselves.
The headless `-trace=cpu,frame` capture produced `.utrace` files. Unreal Insights export could not start: SDL failed to initialize UDEV in this headless environment. Custom per-frame timings identify the actor/tick-group interval, but not its engine child scope.
## Fixes and throughput
- Removed the per-frame passage-overlap scoring pass over outstanding tiles. It measured 121.37 ms for 407 missing LOD2 candidates; the remaining candidate scan, sort, and admission scopes were each below 0.32 ms. Existing deterministic desired/travel ordering remains.
- Cached the immutable Core render distance instead of read-locking the Core world for every visibility candidate. Before the fix, one visibility scan took 162.03 ms and a measured `WorldLock` read wait took 122.65 ms while the far-world build held the writer lock. Afterward, visibility reconciliation peaked at 0.17 ms in FI and 0.14 ms in SW. The writer contention is inferred from the matching build path and lock timing.
- Kept ready player-support collision tiles in the next collision-desired set, preventing an unload/re-admit cycle for support keys.
- Kept the L95 queue settings. FI settled in 2.061–2.124 s (L95: 2.068–2.114 s). Six SW runs had a 1.300 s median (range 1.282–1.544 s); four were 1.282–1.328 s. A seven-worker experiment slowed SW and did not reliably remove the outer world-tick stall, so it was removed.
The L95 SW outlier keys were LOD0 `(3,0,-47)`, `(3,0,-48)`, and `(3,0,-50)`. They were non-empty, collision-ready floor/support tiles that fell out of the rebuilt collision-desired set, then were unloaded and requested again. This is the same support-retention family as L92’s empty-collision churn, but these were not empty results. Traces showed no cancellation or epoch race. The retention fix kept each key to one request in SW repeats 27–32; all six had `repeated_lod0_request_keys_before_settle=[]`. One run reached backlog 256 and settled in 1.544 s without re-admission.
Fast tier passed: 274 checks, 80 runs, 300.6 s. Final Linux UE build passed with `-NoUBA -MaxParallelActions=4`. Timed processes were pinned to CPUs 0–11; Unreal used no `--as`. Headless fast tier used `prlimit --as=6442450944`.
## Source and failed diagnostics
Changed: `Source/VoxelForge/Private/VoxelWorld.cpp`, `Source/VoxelForge/Public/VoxelWorld.h`, `Source/VoxelForge/Private/VoxelStartupTrace.cpp`, `Source/VoxelForge/Public/VoxelStartupTrace.h`, `Source/VoxelForgeEditor/Private/VoxelForgeExploreCommandlet.cpp`, and `Standalone/Research/WorldAssemblerM3/Linux96/RunL96UnrealArrival.py`. No passage-composer source changed.
The first fast-tier launch lacked its binary; it was built and the tier then passed. One diagnostic mistakenly applied the headless 6 GiB `prlimit` to Unreal and failed module loading; subsequent Unreal runs had no address-space limit. Insights export attempts failed on SDL/UDEV; no installs were made. An initial build could not write UBT’s default log under read-only `~/.config`; builds with explicit `-Log` passed. No run exceeded 30 minutes. No commit, push, or stash was made.
@@ -0,0 +1,377 @@
#!/usr/bin/env python3
"""Run one pinned null-RHI SW/FI arrival for Linux 96."""
from __future__ import annotations
import argparse
from collections import Counter
import json
import re
import subprocess
import time
from pathlib import Path
ROOT = Path(__file__).resolve().parents[4]
HOST = Path("/home/jahni/VFHost")
HOST_PLUGIN_SAVED = HOST / "Plugins/VoxelForge/Saved/Linux/l96"
HOST_SAVED = HOST / "Saved/Linux/l96"
EDITOR = Path("/home/jahni/UnrealEngine/Engine/Binaries/Linux/UnrealEditor-Cmd")
OUT = ROOT / "Saved/Linux/l96/unreal-arrival"
SPAWNS_M = {
"FI": (25.8369140625, 3.19921875, -737.0),
"SW": (25.8369140625, 3.19921875, -200.0),
}
MOVE_START_S = 20.0
MOVE_DURATION_S = 12.0
EXIT_S = MOVE_START_S + MOVE_DURATION_S + 5.0
def read_events(path: Path) -> list[dict]:
events = []
if path.is_file():
for line in path.read_text(encoding="utf-8", errors="replace").splitlines():
if line.startswith("{"):
try:
events.append(json.loads(line))
except json.JSONDecodeError:
pass
return events
def percentile(values: list[float], fraction: float) -> float | None:
if not values:
return None
ordered = sorted(values)
return ordered[min(len(ordered) - 1, int(round((len(ordered) - 1) * fraction)))]
def run(stratum: str, repeat: int, phase: str, ready_depth: int,
background_cap: int, startup_boost: int, insights: bool) -> dict:
label = (f"{phase}-{stratum.lower()}-rd{ready_depth}-bg{background_cap}"
f"-boost{startup_boost}-{repeat}")
trace = OUT / f"{label}.trace.jsonl"
utrace = OUT / f"{label}.utrace"
abslog = OUT / f"{label}.log"
stdout = OUT / f"{label}.stdout.log"
output = HOST_PLUGIN_SAVED / "output" / label
userdir = HOST_SAVED / "user" / label
zendata = HOST_SAVED / "zen" / label
ddc = HOST_SAVED / "DDC"
for directory in (OUT, output, userdir, zendata, ddc):
directory.mkdir(parents=True, exist_ok=True)
trace.unlink(missing_ok=True)
utrace.unlink(missing_ok=True)
spawn_cm = ",".join(f"{value * 100.0:.3f}" for value in SPAWNS_M[stratum])
command = [
str(EDITOR), str(HOST / "VFHost.uproject"), "-nullrhi", "-unattended",
"-nop4", "-nosplash", "-NoSound", "-corelimit=12", "-NoZenAutoLaunch",
"-notraceserver", "-nocrashreports", "-DisablePlugins=AndroidFileServer",
"-ddc=NoZenLocalFallback", f"-userdir={userdir}", f"-ZenDataPath={zendata}",
f"-LocalDataCachePath={ddc}", "-run=VoxelForgeExplore", "-seed=0",
"-archetype=TunnelNetwork", f"-slot={1 if stratum == 'FI' else 0}",
"-modes=export", "-gameconfig=1", "-coreworldtest=1",
"-ownerfourstrateplan=1", "-corevoxelsizecm=25", "-coreislandtest=0",
"-corefallbacktest=0", "-coreofftest=0", "-coreplantest=0",
"-settingsref=/Game/VoxelForge/DA_Settings.DA_Settings", "-corehybridmesher=0",
f"-out={output}", "-voxel.StreamingCoarseFirst=1",
"-voxel.StreamingDynamicNearReserve=1",
"-voxel.StreamingLegacyPendingResultCap=0",
"-voxel.CoreRegionConcurrentAdmission=1",
"-voxel.StreamingResultBacklogCap=256",
f"-voxel.StreamingReadyQueueDepth={ready_depth}",
f"-voxel.StreamingBackgroundWorkerCap={background_cap}",
"-voxel.CoreColumnCacheDirectMapped=0", "-voxel.CoreMCGradientMemoization=1",
"-voxel.StreamingCollisionLookahead=1",
f"-voxel.StreamingStartupApplyBoost={startup_boost}",
"-voxel.TestMove=1", "-voxel.TestMoveSpeedCmPerSecond=140.0",
f"-voxel.TestMoveStartSeconds={MOVE_START_S:.1f}",
f"-voxel.TestMoveDurationSeconds={MOVE_DURATION_S:.1f}",
f"-voxel.TestExitSeconds={EXIT_S:.1f}", "-voxel.TestMoveDirection=1,0,0",
"-voxel.StreamingSchedulerPolicy=3", "-voxel.TestExitOnSteady=0",
"-coreworldstreamtrace=1", f"-voxel.StartupTraceSpawnCm={spawn_cm}",
"-voxel.StartupTraceUntilEndPlay=1", "-voxel.StartupTraceThroughCrossing=1",
"-voxel.StartupTraceMaxTiles=16384", f"-voxel.StartupTraceFile={trace}",
f"-abslog={abslog}",
]
if insights:
command += ["-trace=cpu,frame", f"-tracefile={utrace}", "-tracefiletrunc"]
wrapped = ["taskset", "-c", "0-11", "timeout", "1740s", *command]
started = time.monotonic()
with stdout.open("w", encoding="utf-8") as stream:
result = subprocess.run(wrapped, cwd=ROOT, stdout=stream,
stderr=subprocess.STDOUT, check=False, timeout=1740)
events = read_events(trace)
samples = [e for e in events if e.get("type") == "streaming_sample"]
arrival = [e for e in samples if float(e.get("t_s", 0.0)) < MOVE_START_S]
full = next((e for e in arrival
if sum(e.get("desired_by_lod", [0] * 9)[:3]) > 0
and sum(e.get("settled_by_lod", [0] * 9)[:3])
>= sum(e.get("desired_by_lod", [0] * 9)[:3])), None)
first_admission = next((e for e in events if e.get("type") == "scheduler_admission"
and e.get("desired_rebuilt") == 1), None)
request_events = [e for e in events if e.get("type") == "request"]
initial_request_events = [e for e in request_events if e.get("epoch") == 0]
tile_by_ordinal = {e.get("request_ordinal"): e for e in events
if e.get("type") == "tile"}
collision_count = sum(1 for e in events if e.get("type") == "collision_ready"
and e.get("level", 9) <= 2
and full and e.get("t_s", 1e30) <= full["t_s"])
initial_tiles = [tile_by_ordinal[r.get("request_ordinal")] for r in initial_request_events
if full and r.get("t_s", 1e30) <= full["t_s"]
and r.get("request_ordinal") in tile_by_ordinal
and tile_by_ordinal[r["request_ordinal"]].get("level", 9) <= 2]
burst_start_s = float(first_admission["t_s"]) if first_admission else -1.0
burst_end_s = float(full["t_s"]) if full else -1.0
work_by_frame = {int(e.get("frame", -1)): e for e in events
if e.get("type") == "game_thread_work_frame"}
work_values = [e for e in work_by_frame.values()
if burst_start_s <= float(e.get("t_s", -1.0)) <= burst_end_s]
arrival_frame_ids = {int(e.get("frame", -1)) for e in work_values}
scheduler_by_frame = {int(e.get("frame", -1)): e for e in events
if e.get("type") == "scheduler_admission"}
scheduler_values = [e for e in events if e.get("type") == "scheduler_admission"
and burst_start_s <= float(e.get("t_s", -1.0)) <= burst_end_s]
apply_by_frame = {int(e.get("frame", -1)): e for e in events
if e.get("type") == "apply_frame"}
commandlet_tick_by_frame = {int(e.get("frame", -1)): e for e in events
if e.get("type") == "commandlet_world_tick_frame"}
garbage_collect_by_frame = {int(e.get("frame", -1)): e for e in events
if e.get("type") == "garbage_collect"}
# apply_frame N+1 records the interval containing AVoxelWorld::Tick N. Its apply_ms
# belongs to Tick N+1, so use apply_by_frame[N] for the same-tick apply breakdown.
near_intervals = [apply_by_frame[frame + 1] for frame in arrival_frame_ids
if frame + 1 in apply_by_frame]
rmc_by_frame: dict[int, dict[str, float]] = {}
for event in events:
frame = int(event.get("frame", -1))
if event.get("type") != "rmc_submit" or frame not in arrival_frame_ids:
continue
values = rmc_by_frame.setdefault(frame, {
"component_acquire_ms": 0.0,
"create_section_group_ms": 0.0,
"create_sections_ms": 0.0,
"collision_handoff_ms": 0.0,
})
for key in values:
values[key] += float(event.get(key, 0.0))
collision_completion_by_frame: dict[int, float] = {}
for event in events:
frame = int(event.get("frame", -1))
if event.get("type") == "collision_completion" and frame in arrival_frame_ids:
collision_completion_by_frame[frame] = collision_completion_by_frame.get(frame, 0.0) \
+ float(event.get("handler_ms", 0.0))
near_requests = [r for r in request_events if full and r.get("t_s", 1e30) <= full["t_s"]
and r.get("level", 9) <= 2]
initial_lod0_counts = Counter(
tuple(r.get("tile", ())) for r in near_requests if r.get("level") == 0)
repeated_lod0_keys = [
{"tile": list(tile), "requests": count}
for tile, count in sorted(initial_lod0_counts.items()) if count > 1]
initial_scheduler_frames = [e for e in events
if e.get("type") == "scheduler_admission" and full
and e.get("t_s", 1e30) <= full["t_s"]]
worst_interval = max(near_intervals, key=lambda e: float(e.get("frame_ms", 0.0)), default=None)
worst_interval_frame_id = int(worst_interval.get("frame", -1)) if worst_interval else -1
worst_work_frame_id = worst_interval_frame_id - 1
worst_work = work_by_frame.get(worst_work_frame_id, {})
worst_apply = apply_by_frame.get(worst_work_frame_id, {})
worst_scheduler = scheduler_by_frame.get(worst_work_frame_id, {})
worst_rmc = rmc_by_frame.get(worst_work_frame_id, {})
worst_collision_completion_ms = collision_completion_by_frame.get(worst_work_frame_id, 0.0)
rmc_values = [rmc_by_frame.get(frame, {}) for frame in arrival_frame_ids]
apply_values = [apply_by_frame[frame] for frame in arrival_frame_ids
if frame in apply_by_frame]
commandlet_tick_values = [commandlet_tick_by_frame[frame] for frame in arrival_frame_ids
if frame in commandlet_tick_by_frame]
garbage_collect_values = [garbage_collect_by_frame[frame] for frame in arrival_frame_ids
if frame in garbage_collect_by_frame]
def work_stat(name: str, fraction: float | None = None) -> float | None:
values = [float(e.get(name, 0.0)) for e in work_values]
return percentile(values, fraction) if fraction is not None else max(values, default=0.0)
def scheduler_stat(name: str, fraction: float | None = None) -> float | None:
values = [float(e.get(name, 0.0)) for e in scheduler_values]
return percentile(values, fraction) if fraction is not None else max(values, default=0.0)
def rmc_stat(name: str, fraction: float | None = None) -> float | None:
values = [float(e.get(name, 0.0)) for e in rmc_values]
return percentile(values, fraction) if fraction is not None else max(values, default=0.0)
def commandlet_stat(name: str, fraction: float | None = None) -> float | None:
values = [float(e.get(name, 0.0)) for e in commandlet_tick_values]
return percentile(values, fraction) if fraction is not None else max(values, default=0.0)
row = {
"label": label, "stratum": stratum, "repeat": repeat, "phase": phase,
"ready_queue_depth": ready_depth, "background_worker_cap": background_cap,
"startup_apply_boost": startup_boost, "insights": insights,
"exit_code": result.returncode,
"wall_s": round(time.monotonic() - started, 3),
"desired_t_s": next((e.get("t_s") for e in events if e.get("type") == "desired_set"), None),
"first_admission_t_s": first_admission.get("t_s") if first_admission else None,
"lod02_full_settled_t_s": full.get("t_s") if full else None,
"near_settle_from_first_admission_s": round(
float(full["t_s"]) - float(first_admission["t_s"]), 4)
if full and first_admission else None,
"desired_by_lod": full.get("desired_by_lod", [])[:3] if full else None,
"settled_by_lod": full.get("settled_by_lod", [])[:3] if full else None,
"near_admitted_tiles": len(near_requests),
"initial_lod0_admissions": sum(initial_lod0_counts.values()),
"repeated_lod0_request_keys_before_settle": repeated_lod0_keys,
"peak_result_backlog_before_settle": max(
(int(e.get("result_backlog", 0)) for e in initial_scheduler_frames), default=0),
"last_admission_t_s": max((e.get("t_s", 0.0) for e in near_requests), default=None),
"near_tile_events": len(initial_tiles),
"near_worker_seconds": round(sum(e.get("worker_task_s", 0.0) for e in initial_tiles), 4),
"near_core_seconds": round(sum(e.get("core_generate_s", 0.0) for e in initial_tiles), 4),
"collision_ready_by_settle": collision_count,
"burst_frame_count": len(near_intervals),
"burst_frame_ms_p95": round(sorted(e.get("frame_ms", 0.0) for e in near_intervals)[
min(len(near_intervals) - 1, int(.95 * (len(near_intervals) - 1)))], 3)
if near_intervals else None,
"burst_frame_ms_max": round(max((e.get("frame_ms", 0.0) for e in near_intervals), default=0.0), 3),
"burst_full_world_tick_ms_p99": round(commandlet_stat("world_tick_ms", .99) or 0.0, 3),
"burst_full_world_tick_ms_max": round(commandlet_stat("world_tick_ms") or 0.0, 3),
"burst_world_pre_actor_ms_p99": round(commandlet_stat("world_pre_actor_ms", .99) or 0.0, 3),
"burst_world_pre_actor_ms_max": round(commandlet_stat("world_pre_actor_ms") or 0.0, 3),
"burst_world_actor_phase_ms_p99": round(commandlet_stat("world_actor_phase_ms", .99) or 0.0, 3),
"burst_world_actor_phase_ms_max": round(commandlet_stat("world_actor_phase_ms") or 0.0, 3),
"burst_world_post_actor_ms_p99": round(commandlet_stat("world_post_actor_ms", .99) or 0.0, 3),
"burst_world_post_actor_ms_max": round(commandlet_stat("world_post_actor_ms") or 0.0, 3),
"burst_commandlet_readiness_check_ms_max": round(
commandlet_stat("readiness_check_ms") or 0.0, 3),
"burst_commandlet_sleep_ms_p99": round(commandlet_stat("sleep_ms", .99) or 0.0, 3),
"burst_commandlet_sleep_ms_max": round(commandlet_stat("sleep_ms") or 0.0, 3),
"burst_commandlet_loop_ms_max": round(commandlet_stat("loop_ms") or 0.0, 3),
"burst_gc_count": len(garbage_collect_values),
"burst_gc_duration_ms_max": round(max(
(float(e.get("duration_ms", 0.0)) for e in garbage_collect_values), default=0.0), 3),
"burst_max_meshes_per_frame": max((e.get("meshes_applied", 0) for e in apply_values), default=0),
"burst_max_apply_ms": round(max((e.get("apply_ms", 0.0) for e in apply_values), default=0.0), 3),
"burst_max_admit_per_frame": max((sum(e.get("submitted_by_lod", [0] * 9)[:3])
for e in scheduler_values), default=0),
"burst_frame_timing_count": len(work_values),
"burst_world_tick_ms_p99": round(work_stat("tick_ms", .99) or 0.0, 3),
"burst_world_tick_ms_max": round(work_stat("tick_ms") or 0.0, 3),
"burst_update_chunks_ms_p99": round(work_stat("update_chunks_ms", .99) or 0.0, 3),
"burst_update_chunks_ms_max": round(work_stat("update_chunks_ms") or 0.0, 3),
"burst_pending_drain_ms_p99": round(work_stat("pending_drain_ms", .99) or 0.0, 3),
"burst_pending_drain_ms_max": round(work_stat("pending_drain_ms") or 0.0, 3),
"burst_post_apply_callbacks_ms_p99": round(work_stat("post_apply_callbacks_ms", .99) or 0.0, 3),
"burst_post_apply_callbacks_ms_max": round(work_stat("post_apply_callbacks_ms") or 0.0, 3),
"burst_visibility_reconcile_ms_p99": round(work_stat("visibility_reconcile_ms", .99) or 0.0, 3),
"burst_visibility_reconcile_ms_max": round(work_stat("visibility_reconcile_ms") or 0.0, 3),
"burst_collision_probe_ms_max": round(work_stat("collision_probe_ms") or 0.0, 3),
"burst_visible_apply_probe_ms_max": round(work_stat("visible_apply_probe_ms") or 0.0, 3),
"burst_lod0_ready_ms_max": round(work_stat("lod0_ready_ms") or 0.0, 3),
"burst_steady_trace_ms_max": round(work_stat("steady_trace_ms") or 0.0, 3),
"burst_modification_ms_max": round(work_stat("modification_ms") or 0.0, 3),
"burst_lifecycle_audit_ms_p99": round(work_stat("lifecycle_audit_ms", .99) or 0.0, 3),
"burst_lifecycle_audit_ms_max": round(work_stat("lifecycle_audit_ms") or 0.0, 3),
"burst_collision_gate_ms_p99": round(work_stat("collision_gate_ms", .99) or 0.0, 3),
"burst_collision_gate_ms_max": round(work_stat("collision_gate_ms") or 0.0, 3),
"burst_unload_ms_p99": round(work_stat("unload_ms", .99) or 0.0, 3),
"burst_unload_ms_max": round(work_stat("unload_ms") or 0.0, 3),
"burst_trace_json_ms_p99": round(work_stat("trace_json_ms", .99) or 0.0, 3),
"burst_trace_json_ms_max": round(work_stat("trace_json_ms") or 0.0, 3),
"burst_desired_rebuild_ms_max": round(scheduler_stat("desired_rebuild_ms") or 0.0, 3),
"burst_rmc_create_group_ms_p99": round(rmc_stat("create_section_group_ms", .99) or 0.0, 3),
"burst_rmc_create_group_ms_max": round(rmc_stat("create_section_group_ms") or 0.0, 3),
"burst_rmc_collision_handoff_ms_max": round(rmc_stat("collision_handoff_ms") or 0.0, 3),
"burst_collision_completion_ms_max": round(max(
collision_completion_by_frame.values(), default=0.0), 3),
"worst_frame_breakdown": {
"frame": worst_work_frame_id,
"world_tick_frame": worst_work_frame_id,
"frame_interval_end_frame": worst_interval_frame_id,
"frame_interval_ms": round(float(worst_interval.get("frame_ms", 0.0)), 3)
if worst_interval else None,
"apply_ms": round(float(worst_apply.get("apply_ms", 0.0)), 3)
if worst_apply else None,
"result_drain_ms": round(float(worst_apply.get("drain_ms", 0.0)), 3)
if worst_apply else None,
"outside_world_tick_ms": round(max(0.0, float(worst_interval.get("frame_ms", 0.0))
- float(worst_work.get("tick_ms", 0.0))), 3)
if worst_interval else None,
"outside_full_world_tick_ms": round(max(0.0, float(worst_interval.get("frame_ms", 0.0))
- float(commandlet_tick_by_frame.get(worst_work_frame_id, {}).get("world_tick_ms", 0.0))), 3)
if worst_interval else None,
"full_world_tick_ms": round(float(commandlet_tick_by_frame.get(
worst_work_frame_id, {}).get("world_tick_ms", 0.0)), 3),
"world_pre_actor_ms": round(float(commandlet_tick_by_frame.get(
worst_work_frame_id, {}).get("world_pre_actor_ms", 0.0)), 3),
"world_actor_phase_ms": round(float(commandlet_tick_by_frame.get(
worst_work_frame_id, {}).get("world_actor_phase_ms", 0.0)), 3),
"world_post_actor_ms": round(float(commandlet_tick_by_frame.get(
worst_work_frame_id, {}).get("world_post_actor_ms", 0.0)), 3),
"commandlet_readiness_check_ms": round(float(commandlet_tick_by_frame.get(
worst_work_frame_id, {}).get("readiness_check_ms", 0.0)), 3),
"commandlet_sleep_ms": round(float(commandlet_tick_by_frame.get(
worst_work_frame_id, {}).get("sleep_ms", 0.0)), 3),
"commandlet_loop_ms": round(float(commandlet_tick_by_frame.get(
worst_work_frame_id, {}).get("loop_ms", 0.0)), 3),
"gc_duration_ms": round(float(garbage_collect_by_frame.get(
worst_work_frame_id, {}).get("duration_ms", 0.0)), 3),
"world_tick_ms": round(float(worst_work.get("tick_ms", 0.0)), 3),
"collision_gate_ms": round(float(worst_work.get("collision_gate_ms", 0.0)), 3),
"update_chunks_ms": round(float(worst_work.get("update_chunks_ms", 0.0)), 3),
"desired_rebuild_ms": round(float(worst_scheduler.get("desired_rebuild_ms", 0.0)), 3),
"pending_drain_ms": round(float(worst_work.get("pending_drain_ms", 0.0)), 3),
"post_apply_callbacks_ms": round(float(worst_work.get("post_apply_callbacks_ms", 0.0)), 3),
"collision_probe_ms": round(float(worst_work.get("collision_probe_ms", 0.0)), 3),
"visibility_reconcile_ms": round(float(worst_work.get("visibility_reconcile_ms", 0.0)), 3),
"visible_apply_probe_ms": round(float(worst_work.get("visible_apply_probe_ms", 0.0)), 3),
"lod0_ready_ms": round(float(worst_work.get("lod0_ready_ms", 0.0)), 3),
"unload_ms": round(float(worst_work.get("unload_ms", 0.0)), 3),
"steady_trace_ms": round(float(worst_work.get("steady_trace_ms", 0.0)), 3),
"modification_ms": round(float(worst_work.get("modification_ms", 0.0)), 3),
"lifecycle_audit_ms": round(float(worst_work.get("lifecycle_audit_ms", 0.0)), 3),
"trace_json_ms": round(float(worst_work.get("trace_json_ms", 0.0)), 3),
"trace_archive_serialize_ms": round(float(
worst_work.get("trace_archive_serialize_ms", 0.0)), 3),
"collision_completion_ms": round(worst_collision_completion_ms, 3),
**{key: round(float(worst_rmc.get(key, 0.0)), 3)
for key in ("component_acquire_ms", "create_section_group_ms",
"create_sections_ms", "collision_handoff_ms")},
},
"trace": str(trace.relative_to(ROOT)), "utrace": str(utrace.relative_to(ROOT)),
"abslog": str(abslog.relative_to(ROOT)), "stdout": str(stdout.relative_to(ROOT)),
}
stdout_text = stdout.read_text(encoding="utf-8", errors="replace")
failure = re.search(r"\[VoxelForgeCoreWorldTest\] failed: ([^\r\n]+)", stdout_text)
if failure:
row["world_test_failure"] = failure.group(1)
with (OUT / "runs.jsonl").open("a", encoding="utf-8") as stream:
stream.write(json.dumps(row, sort_keys=True) + "\n")
(OUT / f"{label}.summary.json").write_text(json.dumps(row, indent=2) + "\n",
encoding="utf-8")
print("[L96UnrealArrival] " + json.dumps(row, sort_keys=True), flush=True)
if result.returncode:
raise SystemExit(f"Unreal commandlet failed: {stdout}; exit={result.returncode}")
if not full or len(arrival) < 8:
raise SystemExit(f"Unreal arrival trace incomplete: {stdout}; exit={result.returncode}")
if insights and (not utrace.is_file() or utrace.stat().st_size < 1024):
raise SystemExit(f"Unreal Insights trace missing or empty: {utrace}")
return row
def main() -> int:
parser = argparse.ArgumentParser()
parser.add_argument("--stratum", choices=("FI", "SW"), required=True)
parser.add_argument("--repeat", type=int, default=1)
parser.add_argument("--phase", choices=("probe", "before", "after", "snapshot"), default="probe")
parser.add_argument("--ready-depth", type=int, default=64)
parser.add_argument("--background-cap", type=int, choices=(0, 1), default=1)
parser.add_argument("--startup-boost", type=int, choices=(0, 1), default=1)
parser.add_argument("--insights", action="store_true")
args = parser.parse_args()
if not EDITOR.is_file():
raise SystemExit(f"missing Unreal commandlet executable: {EDITOR}")
run(args.stratum, args.repeat, args.phase, args.ready_depth,
args.background_cap, args.startup_boost, args.insights)
return 0
if __name__ == "__main__":
raise SystemExit(main())