From 94f9aa679030bbf348e7d26a38b2bea7ed9b44a2 Mon Sep 17 00:00:00 2001 From: Fr0zka Date: Wed, 28 Oct 2026 10:28:28 +0100 Subject: [PATCH] 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 Claude-Session: https://claude.ai/code/session_016dhxM43dnWvUu2B5Ph1iG1 --- .../VoxelForge/Private/VoxelStartupTrace.cpp | 87 ++++ Source/VoxelForge/Private/VoxelWorld.cpp | 404 +++++++++++++++--- Source/VoxelForge/Public/VoxelStartupTrace.h | 9 + Source/VoxelForge/Public/VoxelWorld.h | 1 + .../Private/VoxelForgeExploreCommandlet.cpp | 72 ++++ .../WorldAssemblerM3/Linux96/REPORT.md | 40 ++ .../Linux96/RunL96UnrealArrival.py | 377 ++++++++++++++++ 7 files changed, 923 insertions(+), 67 deletions(-) create mode 100644 Standalone/Research/WorldAssemblerM3/Linux96/REPORT.md create mode 100644 Standalone/Research/WorldAssemblerM3/Linux96/RunL96UnrealArrival.py diff --git a/Source/VoxelForge/Private/VoxelStartupTrace.cpp b/Source/VoxelForge/Private/VoxelStartupTrace.cpp index 8f52456..16aaf1e 100644 --- a/Source/VoxelForge/Private/VoxelStartupTrace.cpp +++ b/Source/VoxelForge/Private/VoxelStartupTrace.cpp @@ -1,9 +1,12 @@ #include "VoxelStartupTrace.h" #include "HAL/FileManager.h" +#include "HAL/PlatformTLS.h" #include "HAL/PlatformTime.h" +#include "CoreGlobals.h" #include "Misc/CommandLine.h" #include "Misc/Parse.h" +#include "UObject/UObjectGlobals.h" #include @@ -15,7 +18,13 @@ namespace { FArchive* Archive = nullptr; FString Path; + uint32 GameThreadId = 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 TileRecordsSeen = 0; int32 TileRecordsWritten = 0; @@ -50,15 +59,22 @@ namespace void WriteLineLocked(FState& State, const FString& Line) { if (State.Archive == nullptr) return; + const uint64 StartCycles = FPlatformTime::Cycles64(); const FString WithNewline = Line + TEXT("\n"); FTCHARToUTF8 Utf8(*WithNewline); State.Archive->Serialize(const_cast(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. // 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) { + const uint64 StartCycles = FPlatformTime::Cycles64(); FString Line = FString::Printf( TEXT("{\"type\":\"%s\",\"t_s\":%s"), Type, @@ -70,6 +86,11 @@ namespace } Line += TEXT("}"); WriteLineLocked(State, Line); + if (FPlatformTLS::GetCurrentThreadId() == State.GameThreadId) + { + State.GameThreadJsonWriteSeconds += FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - StartCycles); + } } double Percentile(TArray Values, double Fraction) @@ -198,6 +219,7 @@ void BeginFromCommandLine() TUniquePtr NewState = MakeUnique(); NewState->Path = Path; + NewState->GameThreadId = FPlatformTLS::GetCurrentThreadId(); FParse::Value(FCommandLine::Get(), TEXT("voxel.StartupTraceMaxTiles="), NewState->TileRecordCap); NewState->TileRecordCap = FMath::Clamp(NewState->TileRecordCap, 64, 16384); NewState->Samples.Reserve(NewState->TileRecordCap); @@ -211,6 +233,32 @@ void BeginFromCommandLine() NewState->bActive = true; GState = MoveTemp(NewState); GTraceActive.store(true, std::memory_order_release); + GState->PreGarbageCollectHandle = FCoreUObjectDelegates::GetPreGarbageCollectDelegate() + .AddLambda([]() + { + FScopeLock CallbackLock(>raceLock); + if (GState.IsValid() && GState->bActive) + { + GState->GarbageCollectionStartSeconds = FPlatformTime::Seconds(); + } + }); + GState->PostGarbageCollectHandle = FCoreUObjectDelegates::GetPostGarbageCollect() + .AddLambda([]() + { + FScopeLock CallbackLock(>raceLock); + 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(GFrameCounter), + *Number(DurationMilliseconds))); + }); WriteEventLocked(*GState, TEXT("header"), FString::Printf( TEXT("\"schema\":1,\"path\":\"%s\",\"tile_record_cap\":%d"), *JsonEscape(GState->Path), GState->TileRecordCap)); @@ -221,6 +269,21 @@ bool IsActive() return GTraceActive.load(std::memory_order_acquire); } +FWriteMetrics ConsumeCurrentThreadWriteMetrics() +{ + FWriteMetrics Metrics; + FScopeLock Lock(>raceLock); + 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) { FScopeLock Lock(>raceLock); @@ -378,6 +441,18 @@ void Finish(const TCHAR* Reason) FScopeLock Lock(>raceLock); if (!GState.IsValid() || !GState->bActive) return; 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. const double Now = FPlatformTime::Seconds(); @@ -387,7 +462,19 @@ void Finish(const TCHAR* Reason) } GState->StageStarts.Reset(); WriteEventLocked(*GState, TEXT("summary"), BuildSummaryFieldsLocked(*GState, Reason)); + const uint64 FlushStartCycles = FPlatformTime::Cycles64(); 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; GState->Archive = nullptr; GState->bActive = false; diff --git a/Source/VoxelForge/Private/VoxelWorld.cpp b/Source/VoxelForge/Private/VoxelWorld.cpp index 7337477..54596d1 100644 --- a/Source/VoxelForge/Private/VoxelWorld.cpp +++ b/Source/VoxelForge/Private/VoxelWorld.cpp @@ -6966,6 +6966,20 @@ void AVoxelWorld::LogReadyTransitionVisibilityMeasure() 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); TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_Tick); // game-thread streaming orchestration breakdown if (bUseVoxelForgeCore && VoxelForgeCoreState.IsValid() @@ -7069,14 +7083,26 @@ void AVoxelWorld::Tick(float DeltaTime) PeakObservedPawnSpeedCmPerSecond = FMath::Max( PeakObservedPawnSpeedCmPerSecond, PlayerHeading.Size()); StartupTraceSpeedCmPerSecond = PlayerHeading.Size(); + const uint64 CollisionGateStartCycles = bTraceFrameTiming + ? FPlatformTime::Cycles64() : 0; UpdatePawnCollisionGate(PlayerPawn, PlayerLastPos, DeltaTime); + if (bTraceFrameTiming) + { + CollisionGateCycles += FPlatformTime::Cycles64() - CollisionGateStartCycles; + } RecordHeadlessDigMotionFrame(PlayerPawn, PlayerLastPos, DeltaTime); ObserveHeadlessStrateCrossingTest(PlayerLastPos, PlayerPawn); ObserveHeadlessCollisionGateStressTest(PlayerLastPos, PlayerPawn); const FVector StreamingCenterPosition = bHeadlessStreamingTestCenterOverride ? LocalVoxelToWorld(HeadlessStreamingTestCenterVoxel) : PlayerLastPos; + const uint64 UpdateChunksStartCycles = bTraceFrameTiming + ? FPlatformTime::Cycles64() : 0; UpdateChunksAroundPosition(StreamingCenterPosition, PlayerPawn, PlayerHeading); + if (bTraceFrameTiming) + { + UpdateChunksCycles += FPlatformTime::Cycles64() - UpdateChunksStartCycles; + } if (AtmosphereManager) { 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 // streamed; this is the same explicit anchor path used by BuildHost validation. + const uint64 UpdateChunksStartCycles = bTraceFrameTiming + ? FPlatformTime::Cycles64() : 0; UpdateChunksAroundPosition( GetVoxelForgeCoreDefaultCenterWorld(), nullptr, FVector::ZeroVector); + if (bTraceFrameTiming) + { + UpdateChunksCycles += FPlatformTime::Cycles64() - UpdateChunksStartCycles; + } } ReleasePawnCollisionGate(); if (APawn* PreviousPawn = PawnTickPrerequisite.Get()) @@ -7160,18 +7192,48 @@ void AVoxelWorld::Tick(float DeltaTime) GVoxelForgePendingTestModification = 1; } } + const uint64 PendingDrainStartCycles = bTraceFrameTiming + ? FPlatformTime::Cycles64() : 0; ProcessPendingChunks(); + if (bTraceFrameTiming) + { + PendingDrainCycles += FPlatformTime::Cycles64() - PendingDrainStartCycles; + } + const uint64 PostApplyCallbacksStartCycles = bTraceFrameTiming + ? FPlatformTime::Cycles64() : 0; + uint64 CallbackStartCycles = bTraceFrameTiming ? FPlatformTime::Cycles64() : 0; PollStep1SupportSweepProbes(); + if (bTraceFrameTiming) + { + CollisionProbeCycles += FPlatformTime::Cycles64() - CallbackStartCycles; + CallbackStartCycles = FPlatformTime::Cycles64(); + } ReconcileReadyTransitionVisibility(); + if (bTraceFrameTiming) + { + VisibilityReconcileCycles += FPlatformTime::Cycles64() - CallbackStartCycles; + CallbackStartCycles = FPlatformTime::Cycles64(); + } PollStep1VisibleApplyProbes(); + if (bTraceFrameTiming) + { + VisibleApplyProbeCycles += FPlatformTime::Cycles64() - CallbackStartCycles; + CallbackStartCycles = FPlatformTime::Cycles64(); + } // 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. 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: // 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 // includes the final submission; the separate collision_ready events carry cook latency. + const uint64 SteadyTraceStartCycles = bTraceFrameTiming ? FPlatformTime::Cycles64() : 0; if (VoxelForgeStartupTrace::IsActive() && bAllChunksLoaded && PendingTiles.Num() == 0 @@ -7265,12 +7327,17 @@ void AVoxelWorld::Tick(float DeltaTime) 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 // 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 // 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. + const uint64 ModificationStartCycles = bTraceFrameTiming ? FPlatformTime::Cycles64() : 0; FVector ModificationPosition = bHasPlayer ? PlayerLastPos : GetActorLocation(); FVoxelTileKey ModificationCenterTile( GetTileCoordAtLocalCm(WorldToLocalCm(ModificationPosition)), 0); @@ -7360,9 +7427,25 @@ void AVoxelWorld::Tick(float DeltaTime) ModificationCenterTile.Coord.X, ModificationCenterTile.Coord.Y, ModificationCenterTile.Coord.Z, bProofSurvivedCarve ? 1 : 0); } + if (bTraceFrameTiming) + { + ModificationCycles += FPlatformTime::Cycles64() - ModificationStartCycles; + } + const uint64 UnloadStartCycles = bTraceFrameTiming + ? FPlatformTime::Cycles64() : 0; ProcessUnloadQueue(); + if (bTraceFrameTiming) + { + UnloadCycles += FPlatformTime::Cycles64() - UnloadStartCycles; + } + const uint64 LifecycleAuditStartCycles = bTraceFrameTiming + ? FPlatformTime::Cycles64() : 0; UpdateVisualStalenessAudit(); MaybeFinishHeadlessStreamingTest(); + if (bTraceFrameTiming) + { + LifecycleAuditCycles += FPlatformTime::Cycles64() - LifecycleAuditStartCycles; + } if (bTestCeilingViewEnabled) { @@ -7531,6 +7614,37 @@ void AVoxelWorld::Tick(float DeltaTime) } } #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(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(); State->World = std::make_unique(std::move(*Snapshot)); State->FullResolutionLodCount = State->World->configuration().fullResolutionLodCount; + CoreRenderDistanceChunks = State->World->configuration().renderDistanceChunks; const bool bFarWorldRequired=State->World->configuration().maxLod >=State->FullResolutionLodCount; State->bFarWorldRequired.store(bFarWorldRequired,std::memory_order_release); @@ -7954,6 +8069,7 @@ void AVoxelWorld::FallBackToLegacyAfterCoreInitializationFailure(const FString& StrateManager->SetHardTransitionFallbackForAssembly(false); } CoreFallbackCenterLocalCm = FVector::ZeroVector; + CoreRenderDistanceChunks = 0; if (Mesher != nullptr) { Mesher->SetGeometryVoxelSizeCm(VOXEL_SIZE); @@ -8481,6 +8597,7 @@ void AVoxelWorld::RequestCollisionGateSupportTile(const FVoxelTileKey& SupportTi void AVoxelWorld::UpdatePawnCollisionGate(APawn* Pawn, const FVector& PlayerPosition, float DeltaTime) { + TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_UpdatePawnCollisionGate); if (!IsValid(Pawn) || bShuttingDown.load(std::memory_order_relaxed)) { return; @@ -9280,6 +9397,10 @@ void AVoxelWorld::HandleTileCollisionCookComplete( 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)) { return; @@ -9524,6 +9645,16 @@ void AVoxelWorld::HandleTileCollisionCookComplete( { 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(GFrameCounter), + Tile.Coord.X, Tile.Coord.Y, Tile.Coord.Z, + *FString::SanitizeFloat(HandlerMilliseconds))); + } } void AVoxelWorld::ProcessPendingChunks() @@ -10430,6 +10561,7 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility() const FVisualGapAuditState* GapAudit = GVoxelForgeVisualGapAudits.Find(this); const bool bUseLegacyVisualHandoff = GapAudit && GapAudit->bLegacyVisualHandoff; const bool bMeasure = bMeasureReadyTransitionVisibility; + const bool bTraceReconcile = VoxelForgeStartupTrace::IsActive(); const uint64 MeasureStartCycles = bMeasure ? FPlatformTime::Cycles64() : 0; const int32 ComponentCountAtStart = bMeasure ? TileComponents.Num() : 0; const int32 DesiredCountAtStart = bMeasure ? DesiredSorted.Num() : 0; @@ -10464,6 +10596,7 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility() // queue below. TArray ReadyToHide; ReadyToHide.Reserve(TileComponents.Num()); + uint64 CandidateScanCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0; auto GetAncestorAtLevel = [](const FVoxelTileKey& Tile, int32 AncestorLevel) { const int32 Divisor = VF_ClipLevelScale(AncestorLevel - Tile.Level); @@ -10529,11 +10662,16 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility() ReadyToHide.Add(OldTile); } } + const uint64 CandidateScanElapsedCycles = bTraceReconcile + ? FPlatformTime::Cycles64() - CandidateScanCycles : 0; + uint64 QueueUnloadCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0; for (const FVoxelTileKey& Tile : ReadyToHide) { QueuePendingUnload(Tile); } + const uint64 QueueUnloadElapsedCycles = bTraceReconcile + ? FPlatformTime::Cycles64() - QueueUnloadCycles : 0; // 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 @@ -10542,6 +10680,7 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility() TSet VisibleRetiredTiles; TSet VisibleRetiredAncestors; int32 MaxVisibleRetiredLevel = DesiredTransitionMaxLevel; + uint64 RetiredIndexCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0; for (const TPair& OldPair : TileComponents) { const FVoxelTileKey& OldTile = OldPair.Key; @@ -10558,7 +10697,10 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility() VisibleRetiredAncestors.Add(GetAncestorAtLevel(OldTile, Level)); } } + const uint64 RetiredIndexElapsedCycles = bTraceReconcile + ? FPlatformTime::Cycles64() - RetiredIndexCycles : 0; + uint64 RevealCycles = bTraceReconcile ? FPlatformTime::Cycles64() : 0; for (const TPair& NewPair : TileComponents) { const FVoxelTileKey& NewTile = NewPair.Key; @@ -10582,8 +10724,24 @@ void AVoxelWorld::ReconcileReadyTransitionVisibility() NewComp->SetVisibility(true); } } + const uint64 RevealElapsedCycles = bTraceReconcile + ? FPlatformTime::Cycles64() - RevealCycles : 0; 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(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. @@ -10688,6 +10846,21 @@ void AVoxelWorld::BuildCoreDesiredTiles(const FIntVector& Center, const FVector& APawn* PlayerPawn, const FVector& PlayerHeading, TArray& 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(); CriticalDesiredTiles.Reset(); OutLeavers.Reset(); @@ -10794,6 +10967,17 @@ void AVoxelWorld::BuildCoreDesiredTiles(const FIntVector& Center, const FVector& 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); FVoxelTileKey OccupiedTile = PlayerTile; FVoxelTileKey SupportTile; @@ -11724,15 +11908,8 @@ bool AVoxelWorld::IsTileInClipRange(const FVoxelTileKey& Tile, const FIntVector& int32 MaxLevel = MaxLevelBase, ROuter = R; if (bUseVoxelForgeCore) { - VoxelForgeCore::WorldConfiguration Configuration; - const TSharedPtr State = VoxelForgeCoreState; - if (State.IsValid()) - { - FReadScopeLock Lock(State->WorldLock); - if (State->World) Configuration = State->World->configuration(); - } VoxelClipmapDesiredTiles::FParameters Parameters; - Parameters.RenderDistanceChunks = Configuration.renderDistanceChunks; + Parameters.RenderDistanceChunks = CoreRenderDistanceChunks; VoxelClipmapDesiredTiles::OuterShell(Parameters, R, MaxLevelBase, MaxLevel, ROuter); } else @@ -11912,6 +12089,12 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw const uint64 ResultBacklogCapStopsAtUpdateEntry = StreamingResultBacklogCapStops.load(std::memory_order_relaxed); 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) { 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. //========================================================================= const bool bSubmissionLoopRan = !bAllChunksLoaded; + const uint64 TraceSubmitTilesStartCycles = bTraceStreamingScheduler && bSubmissionLoopRan + ? FPlatformTime::Cycles64() : 0; if (bSubmissionLoopRan) { 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, bool bPreferTravelDirection) { + const uint64 TraceLevelStartCycles = bTraceStreamingScheduler + ? FPlatformTime::Cycles64() : 0; if (GetGenerationAdmissionCount() >= AdmissionCap) { if (Level >= 0 && Level < 9) { ++SchedulerLevelCapReturns[Level]; } + if (bTraceStreamingScheduler) + { + SubmitLevelMilliseconds += FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceLevelStartCycles) * 1000.0; + } return; } TArray LevelTiles; + const uint64 TraceCandidateScanStartCycles = bTraceStreamingScheduler + ? FPlatformTime::Cycles64() : 0; for (const FVoxelTileKey& T : DesiredSorted) { if (T.Level == Level && !PendingTiles.Contains(T) && !LoadedTiles.Contains(T)) @@ -12657,25 +12851,16 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw LevelTiles.Add(T); } } - // Sort only outstanding keys; re-sorting loaded or pending tiles on every tick inflated game-thread work. - // Trier uniquement les cles restantes ; re-trier chaque tick les tuiles chargees ou en attente alourdissait le thread de jeu. - TMap PassageScores; - if(Level<=2&&CoreState.IsValid()&&CoreState->bReady.load(std::memory_order_acquire)) + if (bTraceStreamingScheduler) { - FReadScopeLock WorldReadLock(CoreState->WorldLock); - if(CoreState->World) - { - 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)); - } - } + LevelCandidateScanMilliseconds += FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceCandidateScanStartCycles) * 1000.0; } - const bool bSortForPassagePriority=Level<=2&&!PassageScores.IsEmpty(); - if ((bPreferTravelDirection||bSortForPassagePriority)&&LevelTiles.Num()>1) + // Keep admission work bounded. Recomputing passageOverlapScore for every outstanding + // near tile rescanned all resolved passage segments on every frame and could consume + // >120 ms on the game thread. DesiredSorted already has deterministic near/distance + // order; this optional sort only adds the current travel heading and distance. + if (bPreferTravelDirection && LevelTiles.Num() > 1) { FVector Heading=FVector::ZeroVector; FVector PlayerLocalCm=FVector::ZeroVector; @@ -12693,16 +12878,11 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw TileSizeCm=static_cast(VF_ClipLevelExtentVoxels(Level)) *GetActiveVoxelSizeCm(); } + const uint64 TraceLevelSortStartCycles = bTraceStreamingScheduler + ? FPlatformTime::Cycles64() : 0; std::stable_sort(LevelTiles.GetData(),LevelTiles.GetData()+LevelTiles.Num(), [&](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( (static_cast(A.Coord.X) + 0.5) * TileSizeCm, (static_cast(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; 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) { if (GetGenerationAdmissionCount() >= AdmissionCap) @@ -12736,6 +12923,13 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw SubmitTileWithTraceCount(T, Priority); ++Submitted; } + if (bTraceStreamingScheduler) + { + LevelAdmissionMilliseconds += FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceLevelAdmissionStartCycles) * 1000.0; + SubmitLevelMilliseconds += FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceLevelStartCycles) * 1000.0; + } }; const auto AreCriticalTilesReady = [this]() @@ -13003,6 +13197,11 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw bAllChunksLoaded = true; } } + if (TraceSubmitTilesStartCycles != 0) + { + SubmitTilesMilliseconds = FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceSubmitTilesStartCycles) * 1000.0; + } if (VoxelForgeStartupTrace::IsActive()) { @@ -13220,6 +13419,8 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition, APaw ? LastStreamingSchedulerSampleSeconds : StreamingUpdateStartSeconds; const double IntervalSeconds = FMath::Max(0.0, SchedulerTraceNow - IntervalStart); const double BusySeconds = FPlatformTime::ToSeconds64(WorkerCyclesDelta); + const double SchedulerUpdateMilliseconds = (SchedulerTraceNow + - StreamingUpdateStartSeconds) * 1000.0; VoxelForgeStartupTrace::RecordEvent(TEXT("scheduler_admission"), FString::Printf( TEXT("\"frame\":%llu,\"center\":[%d,%d,%d],\"desired_rebuilt\":%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," "\"region_independent_submissions\":%llu,\"region_dependent_declines\":%llu," "\"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," "\"submitted_by_lod\":%s,\"load_attempts_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(CoreRegionDependentDeclines), *FString::SanitizeFloat(BusySeconds), *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(PendingByLevel), *IntArrayJson(SchedulerSubmittedByLevel), *IntArrayJson(SchedulerLoadAttemptsByLevel), *IntArrayJson(AdmissionCapByLevel), @@ -14583,7 +14796,12 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result) TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_ApplyMeshToChunk); const bool bProfileApply = GVoxelForgeProfileTileGeneration != 0; + const bool bTraceRmcTiming = VoxelForgeStartupTrace::IsActive(); 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 // (ProcessPendingChunks skips empty tiles). This path is game-thread-CHEAP: material lookup + @@ -14704,10 +14922,19 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result) bool bComponentCreated = false; if (!MeshComp) { - MeshComp = AcquireTileComponent( - bProfileApply ? &ComponentCreationSeconds : nullptr, - bProfileApply ? &ComponentRegistrationSeconds : nullptr, - &bComponentCreated); + const uint64 TraceStartCycles = bTraceRmcTiming ? FPlatformTime::Cycles64() : 0; + { + TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CreateTileComponent); + MeshComp = AcquireTileComponent( + bProfileApply ? &ComponentCreationSeconds : nullptr, + bProfileApply ? &ComponentRegistrationSeconds : nullptr, + &bComponentCreated); + } + if (bTraceRmcTiming) + { + TraceComponentAcquireMilliseconds = FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceStartCycles) * 1000.0; + } TileComponents.Add(Tile, 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 // budget without modifying RealtimeMeshComponent. const uint64 StreamUploadStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0; - RTMesh->CreateSectionGroup(GroupKey, MoveTemp(Streams)); + const uint64 TraceSectionGroupStartCycles = bTraceRmcTiming + ? FPlatformTime::Cycles64() : 0; + { + TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CreateSectionGroup); + RTMesh->CreateSectionGroup(GroupKey, MoveTemp(Streams)); + } + if (bTraceRmcTiming) + { + TraceSectionGroupMilliseconds = FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceSectionGroupStartCycles) * 1000.0; + } const uint64 MeshSubmittedCycles = FPlatformTime::Cycles64(); const double StreamUploadSeconds = bProfileApply ? FPlatformTime::ToSeconds64(FPlatformTime::Cycles64() - StreamUploadStartCycles) @@ -14816,30 +15053,40 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result) // (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. const uint64 CollisionConfigStartCycles = bProfileApply ? FPlatformTime::Cycles64() : 0; + const uint64 TraceSectionConfigStartCycles = bTraceRmcTiming + ? FPlatformTime::Cycles64() : 0; const int32 NumIndices = Result.NumTriangles * 3; const int32 FirstCapIndex = FMath::Clamp( NumIndices - Result.NumCeilingTriangles * 3, 0, NumIndices); - if (bHasGroundTris) { - FRealtimeMeshSectionConfig GroundConfig(0); - GroundConfig.bCastsShadow = bCastShadow; - const FRealtimeMeshStreamRange GroundRange = - URealtimeMeshBlueprintFunctionLibrary::MakeStreamRange( - 0, Result.NumVertices, 0, FirstCapIndex); - RTMesh->CreateSection( - FRealtimeMeshSectionKey::CreateForPolyGroup(GroupKey, 0), - GroundConfig, GroundRange, /*bShouldCreateCollision*/ bWantsCollision); + TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CreateSections); + if (bHasGroundTris) + { + FRealtimeMeshSectionConfig GroundConfig(0); + GroundConfig.bCastsShadow = bCastShadow; + const FRealtimeMeshStreamRange GroundRange = + URealtimeMeshBlueprintFunctionLibrary::MakeStreamRange( + 0, Result.NumVertices, 0, FirstCapIndex); + RTMesh->CreateSection( + FRealtimeMeshSectionKey::CreateForPolyGroup(GroupKey, 0), + GroundConfig, GroundRange, /*bShouldCreateCollision*/ bWantsCollision); + } + if (bHasCeilingTris) + { + FRealtimeMeshSectionConfig CapConfig(1); + CapConfig.bCastsShadow = false; // the cap never casts (see above) + const FRealtimeMeshStreamRange CapRange = + URealtimeMeshBlueprintFunctionLibrary::MakeStreamRange( + 0, Result.NumVertices, FirstCapIndex, NumIndices); + RTMesh->CreateSection( + FRealtimeMeshSectionKey::CreateForPolyGroup(GroupKey, 1), + CapConfig, CapRange, /*bShouldCreateCollision*/ bWantsCollision); + } } - if (bHasCeilingTris) + if (bTraceRmcTiming) { - FRealtimeMeshSectionConfig CapConfig(1); - CapConfig.bCastsShadow = false; // the cap never casts (see above) - const FRealtimeMeshStreamRange CapRange = - URealtimeMeshBlueprintFunctionLibrary::MakeStreamRange( - 0, Result.NumVertices, FirstCapIndex, NumIndices); - RTMesh->CreateSection( - FRealtimeMeshSectionKey::CreateForPolyGroup(GroupKey, 1), - CapConfig, CapRange, /*bShouldCreateCollision*/ bWantsCollision); + TraceSectionConfigMilliseconds = FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceSectionConfigStartCycles) * 1000.0; } const double CollisionConfigSeconds = bProfileApply ? FPlatformTime::ToSeconds64(FPlatformTime::Cycles64() - CollisionConfigStartCycles) @@ -14888,21 +15135,30 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result) // 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 // future or an inline body-update event from racing the per-tile record. - TFuture CollisionFuture = - RTMesh->SetCollisionConfig(CollisionConfig); - TWeakObjectPtr WeakWorld(this); TWeakObjectPtr WeakMesh(RTMesh); - CollisionFuture.Next( - [WeakWorld, WeakMesh, Tile, SubmissionId](ERealtimeMeshCollisionUpdateResult CollisionResult) - { - if (AVoxelWorld* World = WeakWorld.Get()) + const uint64 TraceCollisionHandoffStartCycles = bTraceRmcTiming + ? FPlatformTime::Cycles64() : 0; + { + TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_RMC_CollisionHandoff); + TFuture CollisionFuture = + RTMesh->SetCollisionConfig(CollisionConfig); + CollisionFuture.Next( + [WeakWorld, WeakMesh, Tile, SubmissionId](ERealtimeMeshCollisionUpdateResult CollisionResult) { - World->HandleTileCollisionCookComplete( - Tile, SubmissionId, WeakMesh.Get(), static_cast(CollisionResult), - FPlatformTime::Cycles64()); - } - }); + if (AVoxelWorld* World = WeakWorld.Get()) + { + World->HandleTileCollisionCookComplete( + Tile, SubmissionId, WeakMesh.Get(), static_cast(CollisionResult), + FPlatformTime::Cycles64()); + } + }); + } + if (bTraceRmcTiming) + { + TraceCollisionHandoffMilliseconds = FPlatformTime::ToSeconds64( + FPlatformTime::Cycles64() - TraceCollisionHandoffStartCycles) * 1000.0; + } } if (bProfileApply) @@ -14931,6 +15187,20 @@ bool AVoxelWorld::ApplyMeshToTile(FChunkResult& Result) 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(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, // driven from Tick), so it renders at every LOD and to the horizon with no per-tile gaps. return true; diff --git a/Source/VoxelForge/Public/VoxelStartupTrace.h b/Source/VoxelForge/Public/VoxelStartupTrace.h index a187f94..6b10f55 100644 --- a/Source/VoxelForge/Public/VoxelStartupTrace.h +++ b/Source/VoxelForge/Public/VoxelStartupTrace.h @@ -69,11 +69,20 @@ namespace VoxelForgeStartupTrace TStaticArray ApplySecondsByLevel{}; }; + struct VOXELFORGE_API FWriteMetrics + { + double JsonWriteMilliseconds = 0.0; + double ArchiveSerializeMilliseconds = 0.0; + }; + /** Starts when -voxel.StartupTraceFile= is present. */ VOXELFORGE_API void BeginFromCommandLine(); 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. */ VOXELFORGE_API void RecordEvent(const TCHAR* Type, const FString& FieldsJson = FString()); diff --git a/Source/VoxelForge/Public/VoxelWorld.h b/Source/VoxelForge/Public/VoxelWorld.h index 50c444e..78bebd8 100644 --- a/Source/VoxelForge/Public/VoxelWorld.h +++ b/Source/VoxelForge/Public/VoxelWorld.h @@ -790,6 +790,7 @@ private: FString VoxelForgeCoreResolvedLayoutJson; FString VoxelForgeCoreResolvedLayoutIdentity; FVector CoreFallbackCenterLocalCm = FVector::ZeroVector; + int32 CoreRenderDistanceChunks = 0; bool bCoreRegionCompilePending = false; TArray PendingCoreRegionTiles; TSet PendingCoreRegionTileSet; diff --git a/Source/VoxelForgeEditor/Private/VoxelForgeExploreCommandlet.cpp b/Source/VoxelForgeEditor/Private/VoxelForgeExploreCommandlet.cpp index 6f6ff8b..9e03c23 100644 --- a/Source/VoxelForgeEditor/Private/VoxelForgeExploreCommandlet.cpp +++ b/Source/VoxelForgeEditor/Private/VoxelForgeExploreCommandlet.cpp @@ -18172,11 +18172,60 @@ bool RunCoreWorldActorIntegrationTest(const FExploreArguments& Arguments, FStrin TArray SpawnTickMilliseconds; TArray WalkTickMilliseconds; TArray> 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; double InitialSetReadySeconds = -1.0; while (FPlatformTime::Seconds() - ActorBeginSeconds < RunDurationSeconds) { const double TickStartSeconds = FPlatformTime::Seconds(); + const uint64 TickFrame = GFrameCounter; + WorldPreActorMilliseconds = 0.0; + WorldActorPhaseMilliseconds = 0.0; + WorldPostActorMilliseconds = 0.0; TestWorld->Tick(LEVELTICK_All, 0.016f); const double TickMilliseconds = (FPlatformTime::Seconds() - TickStartSeconds) * 1000.0; @@ -18184,6 +18233,7 @@ bool RunCoreWorldActorIntegrationTest(const FExploreArguments& Arguments, FStrin const double ElapsedSeconds = FPlatformTime::Seconds() - ActorBeginSeconds; TickSamples.Emplace(ElapsedSeconds, TickMilliseconds); + const double ReadinessCheckStartSeconds = FPlatformTime::Seconds(); if (!bInitialSetReady && Actor->IsVoxelForgeCoreReady() && Actor->bAllChunksLoaded && Actor->PendingTiles.IsEmpty() && Actor->PendingCollisionCooks.IsEmpty() && Actor->PendingUnload.IsEmpty() @@ -18198,8 +18248,30 @@ bool RunCoreWorldActorIntegrationTest(const FExploreArguments& Arguments, FStrin Actor->LoadedTiles.Num(), Actor->CollisionDesiredTiles.Num(), Actor->CollisionReadyTiles.Num())); } + const double ReadinessCheckMilliseconds = + (FPlatformTime::Seconds() - ReadinessCheckStartSeconds) * 1000.0; + const double SleepStartSeconds = FPlatformTime::Seconds(); 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(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& Sample : TickSamples) { diff --git a/Standalone/Research/WorldAssemblerM3/Linux96/REPORT.md b/Standalone/Research/WorldAssemblerM3/Linux96/REPORT.md new file mode 100644 index 0000000..1419d77 --- /dev/null +++ b/Standalone/Research/WorldAssemblerM3/Linux96/REPORT.md @@ -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. diff --git a/Standalone/Research/WorldAssemblerM3/Linux96/RunL96UnrealArrival.py b/Standalone/Research/WorldAssemblerM3/Linux96/RunL96UnrealArrival.py new file mode 100644 index 0000000..645aa53 --- /dev/null +++ b/Standalone/Research/WorldAssemblerM3/Linux96/RunL96UnrealArrival.py @@ -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())