diff --git a/Source/VoxelForge/Private/VoxelStartupTrace.cpp b/Source/VoxelForge/Private/VoxelStartupTrace.cpp new file mode 100644 index 0000000..d0f9f39 --- /dev/null +++ b/Source/VoxelForge/Private/VoxelStartupTrace.cpp @@ -0,0 +1,320 @@ +#include "VoxelStartupTrace.h" + +#include "HAL/FileManager.h" +#include "HAL/PlatformTime.h" +#include "Misc/CommandLine.h" +#include "Misc/Parse.h" + +namespace VoxelForgeStartupTrace +{ +namespace +{ + struct FState + { + FArchive* Archive = nullptr; + FString Path; + double StartSeconds = 0.0; + int32 TileRecordCap = 4096; + int32 TileRecordsSeen = 0; + int32 TileRecordsWritten = 0; + int32 TileRecordsSuppressed = 0; + TArray Samples; + TMap StageStarts; + TMap StageTotals; + TArray StageOrder; + bool bActive = false; + }; + + FCriticalSection GTraceLock; + TUniquePtr GState; + + FString JsonEscape(const FString& In) + { + FString Out = In; + Out.ReplaceInline(TEXT("\\"), TEXT("\\\\")); + Out.ReplaceInline(TEXT("\""), TEXT("\\\"")); + Out.ReplaceInline(TEXT("\r"), TEXT("\\r")); + Out.ReplaceInline(TEXT("\n"), TEXT("\\n")); + return Out; + } + + FString Number(double Value) + { + return FString::SanitizeFloat(Value); + } + + void WriteLineLocked(FState& State, const FString& Line) + { + if (State.Archive == nullptr) return; + const FString WithNewline = Line + TEXT("\n"); + FTCHARToUTF8 Utf8(*WithNewline); + State.Archive->Serialize(const_cast(Utf8.Get()), Utf8.Length()); + // The trace is intended to remain readable if a harness terminates the editor after + // the steady-state record. This is bounded I/O (startup only), not the shared UE log. + State.Archive->Flush(); + } + + void WriteEventLocked(FState& State, const TCHAR* Type, const FString& FieldsJson) + { + FString Line = FString::Printf( + TEXT("{\"type\":\"%s\",\"t_s\":%s"), + Type, + *Number(FPlatformTime::Seconds() - State.StartSeconds)); + if (!FieldsJson.IsEmpty()) + { + Line += TEXT(","); + Line += FieldsJson; + } + Line += TEXT("}"); + WriteLineLocked(State, Line); + } + + double Percentile(TArray Values, double Fraction) + { + if (Values.Num() == 0) return 0.0; + Values.Sort(); + const int32 Index = FMath::Clamp( + FMath::CeilToInt(Fraction * static_cast(Values.Num() - 1)), + 0, + Values.Num() - 1); + return Values[Index]; + } + + double Maximum(const TArray& Values) + { + double Result = 0.0; + for (const double Value : Values) + { + Result = FMath::Max(Result, Value); + } + return Result; + } + + FString BuildTileGroupJson(const TArray& Samples, int32 Level) + { + TArray Request, Queue, Generation, Classify, Mesh, Apply; + int32 Count = 0; + int32 Empty = 0; + int32 AllAir = 0; + int32 AllSolid = 0; + int32 Mixed = 0; + int32 CacheHits = 0; + int32 RegionHits = 0; + int64 Triangles = 0; + + for (const FTileSample& Sample : Samples) + { + if (Level >= 0 && Sample.Level != Level) continue; + ++Count; + if (Sample.bEmpty) ++Empty; + if (Sample.Verdict == 0) ++Mixed; + else if (Sample.Verdict == 1) ++AllSolid; + else if (Sample.Verdict == 2) ++AllAir; + if (Sample.bCacheHit) ++CacheHits; + if (Sample.bRegionHit) ++RegionHits; + Triangles += Sample.Triangles; + Request.Add(Sample.RequestToReadySeconds); + Queue.Add(Sample.QueueWaitSeconds); + Generation.Add(Sample.GenerationSeconds); + Classify.Add(Sample.ClassifySeconds); + Mesh.Add(Sample.MeshSeconds); + Apply.Add(Sample.ApplySeconds); + } + + return FString::Printf( + TEXT("{\"count\":%d,\"empty\":%d,\"all_air\":%d,\"all_solid\":%d,\"mixed\":%d,\"cache_hits\":%d,\"region_hits\":%d,\"triangles\":%lld," + "\"request_ready_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s}," + "\"queue_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s}," + "\"generation_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s}," + "\"classify_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s}," + "\"mesh_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s}," + "\"apply_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s}}"), + Count, Empty, AllAir, AllSolid, Mixed, CacheHits, RegionHits, static_cast(Triangles), + *Number(Percentile(Request, 0.50)), *Number(Percentile(Request, 0.95)), *Number(Maximum(Request)), + *Number(Percentile(Queue, 0.50)), *Number(Percentile(Queue, 0.95)), *Number(Maximum(Queue)), + *Number(Percentile(Generation, 0.50)), *Number(Percentile(Generation, 0.95)), *Number(Maximum(Generation)), + *Number(Percentile(Classify, 0.50)), *Number(Percentile(Classify, 0.95)), *Number(Maximum(Classify)), + *Number(Percentile(Mesh, 0.50)), *Number(Percentile(Mesh, 0.95)), *Number(Maximum(Mesh)), + *Number(Percentile(Apply, 0.50)), *Number(Percentile(Apply, 0.95)), *Number(Maximum(Apply))); + } + + FString BuildSummaryFieldsLocked(const FState& State, const TCHAR* Reason) + { + FString Stages = TEXT("{"); + for (int32 Index = 0; Index < State.StageOrder.Num(); ++Index) + { + if (Index > 0) Stages += TEXT(","); + const FString& Name = State.StageOrder[Index]; + const double* Total = State.StageTotals.Find(Name); + Stages += FString::Printf( + TEXT("\"%s\":%s"), *JsonEscape(Name), *Number(Total ? *Total : 0.0)); + } + Stages += TEXT("}"); + + TArray Levels; + for (const FTileSample& Sample : State.Samples) + { + if (Sample.Level >= 0 && !Levels.Contains(Sample.Level)) Levels.Add(Sample.Level); + } + Levels.Sort(); + + FString Groups = FString::Printf( + TEXT("\"all\":%s"), *BuildTileGroupJson(State.Samples, -1)); + for (const int32 Level : Levels) + { + Groups += FString::Printf( + TEXT(",\"lod%d\":%s"), Level, *BuildTileGroupJson(State.Samples, Level)); + } + + return FString::Printf( + TEXT("\"reason\":\"%s\",\"wall_s\":%s,\"tile_records_seen\":%d," + "\"tile_records_written\":%d,\"tile_records_suppressed\":%d," + "\"tile_record_cap\":%d,\"stage_seconds\":%s,\"tile_percentiles\":{%s}"), + *JsonEscape(Reason ? FString(Reason) : FString(TEXT("unknown"))), + *Number(FPlatformTime::Seconds() - State.StartSeconds), + State.TileRecordsSeen, State.TileRecordsWritten, State.TileRecordsSuppressed, + State.TileRecordCap, *Stages, *Groups); + } +} + +void BeginFromCommandLine() +{ + FScopeLock Lock(>raceLock); + if (GState.IsValid()) return; + + FString Path; + if (!FParse::Value(FCommandLine::Get(), TEXT("voxel.StartupTraceFile="), Path)) return; + Path.TrimQuotesInline(); + if (Path.IsEmpty()) return; + + TUniquePtr NewState = MakeUnique(); + NewState->Path = Path; + FParse::Value(FCommandLine::Get(), TEXT("voxel.StartupTraceMaxTiles="), NewState->TileRecordCap); + NewState->TileRecordCap = FMath::Clamp(NewState->TileRecordCap, 64, 16384); + NewState->Samples.Reserve(NewState->TileRecordCap); + NewState->Archive = IFileManager::Get().CreateFileWriter(*Path); + if (NewState->Archive == nullptr) + { + return; + } + + NewState->StartSeconds = FPlatformTime::Seconds(); + NewState->bActive = true; + GState = MoveTemp(NewState); + WriteEventLocked(*GState, TEXT("header"), FString::Printf( + TEXT("\"schema\":1,\"path\":\"%s\",\"tile_record_cap\":%d"), + *JsonEscape(GState->Path), GState->TileRecordCap)); +} + +bool IsActive() +{ + FScopeLock Lock(>raceLock); + return GState.IsValid() && GState->bActive; +} + +void RecordEvent(const TCHAR* Type, const FString& FieldsJson) +{ + FScopeLock Lock(>raceLock); + if (!GState.IsValid() || !GState->bActive) return; + WriteEventLocked(*GState, Type, FieldsJson); +} + +void StageBegin(const TCHAR* Name) +{ + if (Name == nullptr) return; + FScopeLock Lock(>raceLock); + if (!GState.IsValid() || !GState->bActive) return; + const FString StageName(Name); + if (!GState->StageStarts.Contains(StageName)) + { + GState->StageOrder.Add(StageName); + } + GState->StageStarts.Add(StageName, FPlatformTime::Seconds()); + WriteEventLocked(*GState, TEXT("stage_begin"), FString::Printf( + TEXT("\"name\":\"%s\""), *JsonEscape(StageName))); +} + +void StageEnd(const TCHAR* Name) +{ + if (Name == nullptr) return; + FScopeLock Lock(>raceLock); + if (!GState.IsValid() || !GState->bActive) return; + const FString StageName(Name); + const double Now = FPlatformTime::Seconds(); + const double* Start = GState->StageStarts.Find(StageName); + const double Duration = Start ? FMath::Max(0.0, Now - *Start) : 0.0; + GState->StageTotals.FindOrAdd(StageName) += Duration; + GState->StageStarts.Remove(StageName); + WriteEventLocked(*GState, TEXT("stage_end"), FString::Printf( + TEXT("\"name\":\"%s\",\"duration_s\":%s"), + *JsonEscape(StageName), *Number(Duration))); +} + +void RecordTile(const FTileSample& Sample) +{ + FScopeLock Lock(>raceLock); + if (!GState.IsValid() || !GState->bActive) return; + ++GState->TileRecordsSeen; + if (GState->TileRecordsWritten >= GState->TileRecordCap) + { + ++GState->TileRecordsSuppressed; + return; + } + + GState->Samples.Add(Sample); + ++GState->TileRecordsWritten; + WriteEventLocked(*GState, TEXT("tile"), FString::Printf( + TEXT("\"level\":%d,\"verdict\":%d,\"empty\":%d,\"cache_hit\":%d,\"region_hit\":%d,\"triangles\":%d," + "\"request_to_ready_s\":%s,\"queue_wait_s\":%s,\"worker_queue_s\":%s,\"result_queue_s\":%s," + "\"generation_s\":%s,\"classify_s\":%s,\"mesh_s\":%s,\"stream_s\":%s,\"apply_s\":%s"), + Sample.Level, Sample.Verdict, Sample.bEmpty ? 1 : 0, + Sample.bCacheHit ? 1 : 0, Sample.bRegionHit ? 1 : 0, Sample.Triangles, + *Number(Sample.RequestToReadySeconds), *Number(Sample.QueueWaitSeconds), + *Number(Sample.WorkerQueueSeconds), *Number(Sample.ResultQueueSeconds), + *Number(Sample.GenerationSeconds), *Number(Sample.ClassifySeconds), + *Number(Sample.MeshSeconds), *Number(Sample.StreamSeconds), *Number(Sample.ApplySeconds))); +} + +void Finish(const TCHAR* Reason) +{ + FScopeLock Lock(>raceLock); + if (!GState.IsValid() || !GState->bActive) return; + + // Close any stage left open by an abnormal early exit so the summary remains useful. + const double Now = FPlatformTime::Seconds(); + for (const TPair& Pair : GState->StageStarts) + { + GState->StageTotals.FindOrAdd(Pair.Key) += FMath::Max(0.0, Now - Pair.Value); + } + GState->StageStarts.Reset(); + WriteEventLocked(*GState, TEXT("summary"), BuildSummaryFieldsLocked(*GState, Reason)); + GState->Archive->Flush(); + delete GState->Archive; + GState->Archive = nullptr; + GState->bActive = false; + + // The harness polls this tiny sentinel instead of opening the live JSONL. Unreal's file + // writer does not allow a concurrent reader on Windows; create it only after the trace is + // closed so the summary is safe to consume. + const FString DonePath = GState->Path + TEXT(".done"); + if (FArchive* DoneArchive = IFileManager::Get().CreateFileWriter(*DonePath)) + { + const ANSICHAR DoneText[] = "summary_complete\n"; + DoneArchive->Serialize(const_cast(DoneText), UE_ARRAY_COUNT(DoneText) - 1); + DoneArchive->Flush(); + delete DoneArchive; + } +} + +FStageScope::FStageScope(const TCHAR* InName) + : Name(InName ? InName : TEXT("unnamed")) + , bActive(IsActive()) +{ + if (bActive) StageBegin(*Name); +} + +FStageScope::~FStageScope() +{ + if (bActive) StageEnd(*Name); +} +} diff --git a/Source/VoxelForge/Private/VoxelStrateManager.cpp b/Source/VoxelForge/Private/VoxelStrateManager.cpp index 4f15b7b..e998bce 100644 --- a/Source/VoxelForge/Private/VoxelStrateManager.cpp +++ b/Source/VoxelForge/Private/VoxelStrateManager.cpp @@ -9,6 +9,7 @@ #include "VoxelCaveMorphology.h" // For VoxelSDF and VoxelHash #include "VoxelDensityPrimitives.h" // Shared passage carve polarity/strength #include "VoxelDensityProfile.h" // Opt-in targeted per-voxel attribution +#include "VoxelStartupTrace.h" #include "VoxelTerrainOpDefinition.h" // For UVoxelTerrainOpDefinition::ApplyTo #include "VoxelBiomeDefinition.h" // For UVoxelBiomeDefinition (biome context flatten) #include "Misc/CommandLine.h" @@ -803,6 +804,7 @@ static bool VF_IsAnyPassageFloorAt( bool UVoxelStrateManager::Initialize(UVoxelSettings* Settings, int32 WorldSeed) { + VoxelForgeStartupTrace::FStageScope StartupTraceStage(TEXT("StrateManager.Initialize")); if (!Settings) { UE_LOG(LogTemp, Error, TEXT("[StrateManager] No settings provided!")); @@ -1009,6 +1011,23 @@ bool UVoxelStrateManager::Initialize(UVoxelSettings* Settings, int32 WorldSeed) StrateLayout.Add(Slot); + if (VoxelForgeStartupTrace::IsActive()) + { + FString DefinitionPath = Slot.Definition ? Slot.Definition->GetPathName() : FString(); + DefinitionPath.ReplaceInline(TEXT("\\"), TEXT("\\\\")); + DefinitionPath.ReplaceInline(TEXT("\""), TEXT("\\\"")); + const UEnum* ArchetypeEnum = StaticEnum(); + const FString ArchetypeName = ArchetypeEnum + ? ArchetypeEnum->GetNameStringByValue(static_cast(Slot.Definition->GeneratorType)) + : FString::Printf(TEXT("Value_%d"), static_cast(Slot.Definition->GeneratorType)); + VoxelForgeStartupTrace::RecordEvent(TEXT("strate_slot"), FString::Printf( + TEXT("\"index\":%d,\"definition\":\"%s\",\"archetype\":\"%s\",\"top_chunk_z\":%d," + "\"bottom_chunk_z\":%d,\"height_chunks\":%d,\"operator_stack\":%d"), + Slot.StrateIndex, *DefinitionPath, *ArchetypeName, + Slot.TopChunkZ, Slot.BottomChunkZ, Slot.HeightInChunks, + Slot.Definition->bUseOperatorStack ? 1 : 0)); + } + UE_LOG(LogTemp, Log, TEXT("[StrateManager] Strate %d: '%s' | Z chunks [%d to %d] | %d chunks tall"), i, *Slot.Definition->StrateName.ToString(), @@ -1125,6 +1144,10 @@ bool UVoxelStrateManager::Initialize(UVoxelSettings* Settings, int32 WorldSeed) UE_LOG(LogTemp, Log, TEXT("[StrateManager] Initialized %d strates (seed=%d)"), StrateLayout.Num(), WorldSeed); + VoxelForgeStartupTrace::RecordEvent(TEXT("strate_layout_ready"), FString::Printf( + TEXT("\"strates\":%d,\"seed\":%d,\"inter_strate_gap_chunks\":%d,\"season\":%d"), + StrateLayout.Num(), WorldSeed, InterStrateGapChunks, bUseSeason ? 1 : 0)); + // Generate passages between consecutive strates GeneratePassages(); return bUseSeason ? IsUsingSeason() : true; @@ -1323,9 +1346,14 @@ bool UVoxelStrateManager::GetRecipeForChunk( void UVoxelStrateManager::GeneratePassages() { + VoxelForgeStartupTrace::FStageScope StartupTraceStage(TEXT("GeneratePassages")); Passages.Empty(); - if (StrateLayout.Num() < 1) return; + if (StrateLayout.Num() < 1) + { + VoxelForgeStartupTrace::RecordEvent(TEXT("passages_ready"), TEXT("\"passages\":0")); + return; + } // Deterministic per-value hashes from the world seed. Every draw is keyed by its boundary // strate index, connection index, and a unique salt, so one passage cannot shift another. @@ -2183,6 +2211,10 @@ void UVoxelStrateManager::GeneratePassages() // Invalidate any thread_local per-chunk passage shortlists (see EvaluateModifierSDF). ++PassagesVersion; + + VoxelForgeStartupTrace::RecordEvent(TEXT("passages_ready"), FString::Printf( + TEXT("\"passages\":%d,\"passages_version\":%u,\"upper_source_fit\":%d,\"lower_source_fit\":%d"), + Passages.Num(), PassagesVersion, NumAimedAtUpperPlayerFit, NumAimedAtLowerPlayerFit)); } //============================================================================= diff --git a/Source/VoxelForge/Private/VoxelWorld.cpp b/Source/VoxelForge/Private/VoxelWorld.cpp index f50eb86..1dafd8b 100644 --- a/Source/VoxelForge/Private/VoxelWorld.cpp +++ b/Source/VoxelForge/Private/VoxelWorld.cpp @@ -13,6 +13,7 @@ #include "VoxelDensityVolume.h" #include "VoxelDensityOpStack.h" #include "VoxelDensityProfile.h" +#include "VoxelStartupTrace.h" #include "VoxelStats.h" // IWYU (FPSemantics = Precise ⇒ plus de PCH partagé) : GetPlayerPosition déréférence le pawn, donc // APawn doit être COMPLET — `Casts.h` n'en donne qu'une déclaration avant. APlayerController était @@ -976,11 +977,18 @@ void AVoxelWorld::EndPlay(const EEndPlayReason::Type EndPlayReason) } #endif + if (VoxelForgeStartupTrace::IsActive()) + { + VoxelForgeStartupTrace::Finish(TEXT("end_play_before_steady_state")); + } + Super::EndPlay(EndPlayReason); } void AVoxelWorld::BeginPlay() { + VoxelForgeStartupTrace::BeginFromCommandLine(); + VoxelForgeStartupTrace::FStageScope StartupTraceStage(TEXT("BeginPlay")); Super::BeginPlay(); bShuttingDown.store(false, std::memory_order_relaxed); @@ -1023,6 +1031,27 @@ void AVoxelWorld::BeginPlay() return; } + if (VoxelForgeStartupTrace::IsActive()) + { + FString SettingsPath = Settings->GetPathName(); + SettingsPath.ReplaceInline(TEXT("\\"), TEXT("\\\\")); + SettingsPath.ReplaceInline(TEXT("\""), TEXT("\\\"")); + VoxelForgeStartupTrace::RecordEvent(TEXT("settings_resolved"), FString::Printf( + TEXT("\"asset\":\"%s\",\"seed\":%d,\"total_strates\":%d,\"inter_strate_gap_chunks\":%d," + "\"strate_pool\":%d,\"max_clip_level\":%d,\"clip_radius\":%d," + "\"render_distance_chunks\":%d,\"far_sheet_ring\":%d,\"far_sheet_span_levels\":%d," + "\"enable_density_volume\":%d,\"density_volume_resolution\":%d,\"density_volume_levels\":%d," + "\"density_volume_max_tasks\":%d,\"density_volume_gpu_upload\":%d"), + *SettingsPath, + Settings->GetEffectiveWorldSeed(), Settings->TotalStrates, + Settings->InterStrateGapChunks, Settings->StratePool.Num(), Settings->MaxClipLevel, + Settings->ClipRadius, Settings->RenderDistanceChunks, + Settings->bFarSheetRing ? 1 : 0, Settings->FarSheetSpanLevels, + Settings->bEnableDensityVolume ? 1 : 0, Settings->DensityVolumeResolution, + Settings->DensityVolumeLevels, Settings->DensityVolumeMaxTasks, + Settings->bDensityVolumeGPUUpload ? 1 : 0)); + } + // Tiles never move once generated, so make the actor root STATIC. RMC already requests the // cached static DRAW path (section group DrawType defaults to Static), but a Movable parent // forces every child back to Movable — which also defeats Virtual Shadow Map caching (Movable @@ -1072,6 +1101,11 @@ void AVoxelWorld::BeginPlay() Mesher->LODOctaveDrop = Settings->LODOctaveDrop; // T2.b — 0 = off Mesher->bUseBlockEarlyOut = true; + VoxelForgeStartupTrace::RecordEvent(TEXT("generator_mesher_constructed"), FString::Printf( + TEXT("\"generator\":1,\"mesher\":1,\"generate_skirts\":%d,\"full_res_clip_levels\":%d,\"coarse_tile_cells\":%d"), + Settings->bGenerateSkirts ? 1 : 0, + Settings->FullResClipLevels, Settings->CoarseTileCells)); + // Système de strates — a cooked season takes precedence; otherwise the authored pool path is // exactly the legacy one. if (!Settings->Season.IsNull() || Settings->StratePool.Num() > 0) @@ -1115,6 +1149,12 @@ void AVoxelWorld::BeginPlay() DensityVolume->Initialize(this, Generator, Settings); } + VoxelForgeStartupTrace::RecordEvent(TEXT("density_volume_resolved"), FString::Printf( + TEXT("\"enabled\":%d,\"created\":%d,\"gpu_upload\":%d,\"resolution\":%d,\"levels\":%d"), + Settings->bEnableDensityVolume ? 1 : 0, DensityVolume != nullptr ? 1 : 0, + Settings->bDensityVolumeGPUUpload ? 1 : 0, + Settings->DensityVolumeResolution, Settings->DensityVolumeLevels)); + #if WITH_EDITOR // Listen for data asset edits during PIE so live edit can detect // strate definition changes (PostEditChangeProperty only fires for @@ -1181,6 +1221,57 @@ void AVoxelWorld::Tick(float DeltaTime) } ProcessPendingChunks(); + // 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-ready + // includes the final apply. + if (VoxelForgeStartupTrace::IsActive() + && bAllChunksLoaded + && PendingTiles.Num() == 0 + && bStartupTraceDesiredRecorded) + { + TMap SteadyLevelCounts; + TMap SteadyLevelMins; + TMap SteadyLevelMaxs; + for (const FVoxelTileKey& Key : DesiredSorted) + { + ++SteadyLevelCounts.FindOrAdd(Key.Level); + FIntVector& Min = SteadyLevelMins.FindOrAdd(Key.Level, FIntVector(MAX_int32, MAX_int32, MAX_int32)); + FIntVector& Max = SteadyLevelMaxs.FindOrAdd(Key.Level, FIntVector(MIN_int32, MIN_int32, MIN_int32)); + Min.X = FMath::Min(Min.X, Key.Coord.X); + Min.Y = FMath::Min(Min.Y, Key.Coord.Y); + Min.Z = FMath::Min(Min.Z, Key.Coord.Z); + Max.X = FMath::Max(Max.X, Key.Coord.X); + Max.Y = FMath::Max(Max.Y, Key.Coord.Y); + Max.Z = FMath::Max(Max.Z, Key.Coord.Z); + } + VoxelForgeStartupTrace::RecordEvent(TEXT("steady_state"), FString::Printf( + TEXT("\"desired_tiles\":%d,\"loaded_tiles\":%d,\"pending_tiles\":%d,\"pending_unload\":%d,\"generation_epoch\":%u"), + DesiredSorted.Num(), LoadedTiles.Num(), PendingTiles.Num(), PendingUnload.Num(), GenerationEpoch)); + TArray SteadyLevels; + SteadyLevelCounts.GetKeys(SteadyLevels); + SteadyLevels.Sort(); + for (const int32 Level : SteadyLevels) + { + const FIntVector Min = SteadyLevelMins.FindChecked(Level); + const FIntVector Max = SteadyLevelMaxs.FindChecked(Level); + const int32 ExtentVoxels = CHUNK_SIZE << Level; + const double TileExtentMetres = static_cast(ExtentVoxels) * VOXEL_SIZE / 100.0; + const double SpanX = static_cast(Max.X - Min.X + 1) * TileExtentMetres; + const double SpanY = static_cast(Max.Y - Min.Y + 1) * TileExtentMetres; + const double SpanZ = static_cast(Max.Z - Min.Z + 1) * TileExtentMetres; + VoxelForgeStartupTrace::RecordEvent(TEXT("steady_desired_level"), FString::Printf( + TEXT("\"level\":%d,\"tiles\":%d,\"min_coord\":[%d,%d,%d],\"max_coord\":[%d,%d,%d]," + "\"tile_extent_m\":%s,\"coverage_extent_m\":[%s,%s,%s],\"sheet\":%d"), + Level, SteadyLevelCounts.FindChecked(Level), + Min.X, Min.Y, Min.Z, Max.X, Max.Y, Max.Z, + *FString::SanitizeFloat(TileExtentMetres), + *FString::SanitizeFloat(SpanX), *FString::SanitizeFloat(SpanY), *FString::SanitizeFloat(SpanZ), + Settings && Level > Settings->MaxClipLevel ? 1 : 0)); + } + VoxelForgeStartupTrace::Finish(TEXT("desired_set_satisfied_and_queue_drained")); + } + // Complete the one-shot diagnostic request only after the player's level-0 centre tile is // loaded and idle. Waiting for any coarse tile would take the async-neighbour branch and would // not measure the normal synchronous centre remesh that makes a local edit feel expensive. @@ -1378,11 +1469,14 @@ bool AVoxelWorld::ApplyTileResult(FChunkResult& Result) // dequeued. This makes request-to-ready include component setup, stream/buffer submission, // and collision configuration—the point at which the chunk is actually visible/collidable. const bool bResultEmpty = Result.bEmpty || !Result.Streams; - const uint64 ApplyStartCycles = GVoxelForgeProfileTileGeneration != 0 + const bool bTraceTile = VoxelForgeStartupTrace::IsActive(); + const bool bTelemetry = GVoxelForgeProfileTileGeneration != 0 || bTraceTile; + const uint64 ApplyStartCycles = bTelemetry ? FPlatformTime::Cycles64() : 0; const auto LogTileReady = [&]() { - if (GVoxelForgeProfileTileGeneration != 0 && Result.RequestStartCycles != 0) + if ((GVoxelForgeProfileTileGeneration != 0 || bTraceTile) + && Result.RequestStartCycles != 0) { const uint64 ReadyCycles = FPlatformTime::Cycles64(); const bool bHaveWorkerTiming = Result.GenerationStartCycles != 0 @@ -1399,15 +1493,39 @@ bool AVoxelWorld::ApplyTileResult(FChunkResult& Result) Result.GenerationStartCycles - Result.RequestStartCycles) : 0.0; const double ResultQueueSeconds = bHaveWorkerTiming ? FMath::Max(0.0, RequestToReady - WorkerQueueSeconds - - GenerationSeconds - ApplySeconds) : 0.0; - UE_LOG(LogTemp, Display, - TEXT("[VoxelForgeTileReady] tile=(%d,%d,%d) level=%d empty=%d " - "request_to_ready=%.6f worker_queue=%.6f generation=%.6f " - "result_queue=%.6f apply=%.6f"), - Result.Tile.Coord.X, Result.Tile.Coord.Y, Result.Tile.Coord.Z, - Result.Tile.Level, bResultEmpty ? 1 : 0, - RequestToReady, WorkerQueueSeconds, GenerationSeconds, - ResultQueueSeconds, ApplySeconds); + - GenerationSeconds - ApplySeconds) + : FMath::Max(0.0, RequestToReady - ApplySeconds); + if (GVoxelForgeProfileTileGeneration != 0) + { + UE_LOG(LogTemp, Display, + TEXT("[VoxelForgeTileReady] tile=(%d,%d,%d) level=%d empty=%d " + "request_to_ready=%.6f worker_queue=%.6f generation=%.6f " + "result_queue=%.6f apply=%.6f"), + Result.Tile.Coord.X, Result.Tile.Coord.Y, Result.Tile.Coord.Z, + Result.Tile.Level, bResultEmpty ? 1 : 0, + RequestToReady, WorkerQueueSeconds, GenerationSeconds, + ResultQueueSeconds, ApplySeconds); + } + if (bTraceTile) + { + VoxelForgeStartupTrace::FTileSample Sample; + Sample.Level = Result.Tile.Level; + Sample.Verdict = Result.ClassifyVerdict; + Sample.bEmpty = bResultEmpty; + Sample.bCacheHit = Result.bClassifierCacheHit; + Sample.bRegionHit = Result.bClassifierRegionHit; + Sample.Triangles = Result.NumTriangles; + Sample.RequestToReadySeconds = RequestToReady; + Sample.WorkerQueueSeconds = WorkerQueueSeconds; + Sample.ResultQueueSeconds = ResultQueueSeconds; + Sample.QueueWaitSeconds = WorkerQueueSeconds + ResultQueueSeconds; + Sample.GenerationSeconds = GenerationSeconds; + Sample.ClassifySeconds = Result.ClassifySeconds; + Sample.MeshSeconds = Result.MeshSeconds; + Sample.StreamSeconds = Result.StreamSeconds; + Sample.ApplySeconds = ApplySeconds; + VoxelForgeStartupTrace::RecordTile(Sample); + } } }; @@ -1977,7 +2095,79 @@ void AVoxelWorld::UpdateChunksAroundPosition(const FVector& CenterPosition) // finissent hors desired sont capturées à l'apply (ProcessPendingChunks → TransitionHold), // et le settled cull (tout chargé) reste le filet de sécurité plein-scan. TArray Leavers; + const bool bTraceFirstDesired = VoxelForgeStartupTrace::IsActive() + && !bStartupTraceDesiredRecorded; + if (bTraceFirstDesired) + { + VoxelForgeStartupTrace::StageBegin(TEXT("BuildDesiredTiles.first")); + } BuildDesiredTiles(CenterChunk, Leavers); + if (bTraceFirstDesired) + { + VoxelForgeStartupTrace::StageEnd(TEXT("BuildDesiredTiles.first")); + + struct FDesiredLevelSummary + { + int32 Level = -1; + int32 Count = 0; + FIntVector Min = FIntVector(MAX_int32, MAX_int32, MAX_int32); + FIntVector Max = FIntVector(MIN_int32, MIN_int32, MIN_int32); + }; + TArray LevelSummaries; + for (const FVoxelTileKey& Key : DesiredSorted) + { + int32 SummaryIndex = INDEX_NONE; + for (int32 Index = 0; Index < LevelSummaries.Num(); ++Index) + { + if (LevelSummaries[Index].Level == Key.Level) + { + SummaryIndex = Index; + break; + } + } + if (SummaryIndex == INDEX_NONE) + { + SummaryIndex = LevelSummaries.AddDefaulted(); + LevelSummaries[SummaryIndex].Level = Key.Level; + } + FDesiredLevelSummary& Summary = LevelSummaries[SummaryIndex]; + ++Summary.Count; + Summary.Min.X = FMath::Min(Summary.Min.X, Key.Coord.X); + Summary.Min.Y = FMath::Min(Summary.Min.Y, Key.Coord.Y); + Summary.Min.Z = FMath::Min(Summary.Min.Z, Key.Coord.Z); + Summary.Max.X = FMath::Max(Summary.Max.X, Key.Coord.X); + Summary.Max.Y = FMath::Max(Summary.Max.Y, Key.Coord.Y); + Summary.Max.Z = FMath::Max(Summary.Max.Z, Key.Coord.Z); + } + LevelSummaries.Sort([](const FDesiredLevelSummary& A, const FDesiredLevelSummary& B) + { + return A.Level < B.Level; + }); + + VoxelForgeStartupTrace::RecordEvent(TEXT("desired_set"), FString::Printf( + TEXT("\"center_chunk\":[%d,%d,%d],\"total\":%d,\"levels\":%d,\"leavers\":%d," + "\"collision_only\":%d"), + CenterChunk.X, CenterChunk.Y, CenterChunk.Z, DesiredSorted.Num(), + LevelSummaries.Num(), Leavers.Num(), CollisionOnlyTiles.Num())); + for (const FDesiredLevelSummary& Summary : LevelSummaries) + { + const int32 ExtentVoxels = CHUNK_SIZE << Summary.Level; + const double TileExtentMetres = static_cast(ExtentVoxels) * VOXEL_SIZE / 100.0; + const double SpanX = static_cast(Summary.Max.X - Summary.Min.X + 1) * TileExtentMetres; + const double SpanY = static_cast(Summary.Max.Y - Summary.Min.Y + 1) * TileExtentMetres; + const double SpanZ = static_cast(Summary.Max.Z - Summary.Min.Z + 1) * TileExtentMetres; + VoxelForgeStartupTrace::RecordEvent(TEXT("desired_level"), FString::Printf( + TEXT("\"level\":%d,\"tiles\":%d,\"min_coord\":[%d,%d,%d],\"max_coord\":[%d,%d,%d]," + "\"tile_extent_m\":%s,\"coverage_extent_m\":[%s,%s,%s],\"sheet\":%d"), + Summary.Level, Summary.Count, + Summary.Min.X, Summary.Min.Y, Summary.Min.Z, + Summary.Max.X, Summary.Max.Y, Summary.Max.Z, + *FString::SanitizeFloat(TileExtentMetres), + *FString::SanitizeFloat(SpanX), *FString::SanitizeFloat(SpanY), *FString::SanitizeFloat(SpanZ), + Settings && Summary.Level > Settings->MaxClipLevel ? 1 : 0)); + } + bStartupTraceDesiredRecorded = true; + } // §9.4 — toggle visibility on already-loaded tiles that flipped render↔collision-only this // crossing (a CollisionOnly cluster the player just walked toward/away from). No-op w/o anchors. @@ -2271,7 +2461,9 @@ void AVoxelWorld::LoadTile(const FVoxelTileKey& Tile, bool bHighPriority) return; // Budget full — wait for a task to finish. } PendingTiles.Add(Tile); - const uint64 RequestStartCycles = GVoxelForgeProfileTileGeneration != 0 + const bool bTelemetry = GVoxelForgeProfileTileGeneration != 0 + || VoxelForgeStartupTrace::IsActive(); + const uint64 RequestStartCycles = bTelemetry ? FPlatformTime::Cycles64() : 0; const FIntVector OriginVoxels = Tile.OriginVoxels(); // min corner, voxel coords @@ -2379,7 +2571,7 @@ void AVoxelWorld::LoadTile(const FVoxelTileKey& Tile, bool bHighPriority) UE::Tasks::Launch(TEXT("ChunkGen"), [this, Tile, OriginVoxels, Step, Cells, TaskEpoch, bWantCapture, BandVoxLo, BandVoxHi, BandChunkLo, BandChunkHi, bSheetTile, SheetChunkZ, HoleMinX, HoleMinY, HoleMaxX, HoleMaxY, - RequestStartCycles]() + RequestStartCycles, bTelemetry]() { // RAII: decrement the counter on every exit path. struct FTaskGuard @@ -2391,7 +2583,7 @@ void AVoxelWorld::LoadTile(const FVoxelTileKey& Tile, bool bHighPriority) if (ShouldAbortWork()) return; FChunkResult Result; - const uint64 GenerationStartCycles = GVoxelForgeProfileTileGeneration != 0 + const uint64 GenerationStartCycles = bTelemetry ? FPlatformTime::Cycles64() : 0; Result.GenerationStartCycles = GenerationStartCycles; GenerateTileResult(Tile, OriginVoxels, Step, Cells, TaskEpoch, bWantCapture, @@ -2417,29 +2609,30 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector int32 HoleMinX, int32 HoleMinY, int32 HoleMaxX, int32 HoleMaxY, FChunkResult& Result) { - const bool bProfileTile = GVoxelForgeProfileTileGeneration != 0; - const double TileStartSeconds = bProfileTile ? FPlatformTime::Seconds() : 0.0; + const bool bLogTileProfile = GVoxelForgeProfileTileGeneration != 0; + const bool bMeasureTile = bLogTileProfile || VoxelForgeStartupTrace::IsActive(); + const double TileStartSeconds = bMeasureTile ? FPlatformTime::Seconds() : 0.0; double ClassifySeconds = 0.0; double MeshSeconds = 0.0; double StreamSeconds = 0.0; int32 ClassifyVerdict = -1; // Mixed = 0, AllSolid = 1, AllAir = 2 FVoxelTileClassificationStats ClassifierStats; - const bool bProfileOps = bProfileTile + const bool bProfileOps = bLogTileProfile && VoxelDensityProfile::GetMode() == VoxelDensityProfile::EMode::Full; - const VoxelDensityProfile::FSnapshot TileProfileStart = bProfileTile + const VoxelDensityProfile::FSnapshot TileProfileStart = bMeasureTile ? VoxelDensityProfile::SnapshotCurrentThread() : VoxelDensityProfile::FSnapshot(); auto EmitTileProfile = [&]() { - if (bProfileTile) + if (bLogTileProfile) { - const VoxelDensityProfile::FSnapshot TileProfileEnd = bProfileTile + const VoxelDensityProfile::FSnapshot TileProfileEnd = bMeasureTile ? VoxelDensityProfile::SnapshotCurrentThread() : VoxelDensityProfile::FSnapshot(); const auto CounterDelta = [&](VoxelDensityProfile::ECounter Counter) -> uint64 { const int32 Index = static_cast(Counter); - return bProfileTile && TileProfileEnd.Counters[Index] >= TileProfileStart.Counters[Index] + return bMeasureTile && TileProfileEnd.Counters[Index] >= TileProfileStart.Counters[Index] ? TileProfileEnd.Counters[Index] - TileProfileStart.Counters[Index] : 0; }; UE_LOG(LogTemp, Display, @@ -2528,6 +2721,13 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector Result.Epoch = Epoch; Result.bAborted = false; Result.bEmpty = true; + Result.ClassifyVerdict = -1; + Result.bClassifierCacheHit = false; + Result.bClassifierRegionHit = false; + Result.ClassifySeconds = 0.0; + Result.MeshSeconds = 0.0; + Result.StreamSeconds = 0.0; + Result.NumTriangles = 0; Result.Streams.Reset(); Result.CaptureGrid.Reset(); Result.BandChunkLo = BandChunkLo; // strate content cut (MIN/MAX = uncut) @@ -2561,11 +2761,25 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector { TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_ClassifyTile); INC_DWORD_STAT(STAT_VoxelForgeTilesClassified); - const double ClassifyStartSeconds = bProfileTile ? FPlatformTime::Seconds() : 0.0; + const double ClassifyStartSeconds = bMeasureTile ? FPlatformTime::Seconds() : 0.0; const EVoxelTileClass Verdict = Generator->ClassifyTile( - OriginVoxels, Step, Cells, bProfileTile ? &ClassifierStats : nullptr); - ClassifySeconds = bProfileTile ? FPlatformTime::Seconds() - ClassifyStartSeconds : 0.0; + OriginVoxels, Step, Cells, bMeasureTile ? &ClassifierStats : nullptr); + ClassifySeconds = bMeasureTile ? FPlatformTime::Seconds() - ClassifyStartSeconds : 0.0; + if (bMeasureTile) + { + const VoxelDensityProfile::FSnapshot ClassifyProfileEnd = + VoxelDensityProfile::SnapshotCurrentThread(); + const int32 CacheHitIndex = static_cast( + VoxelDensityProfile::ECounter::TileVerdictCacheHits); + const int32 RegionHitIndex = static_cast( + VoxelDensityProfile::ECounter::TileVerdictRegionHits); + Result.bClassifierCacheHit = + ClassifyProfileEnd.Counters[CacheHitIndex] > TileProfileStart.Counters[CacheHitIndex]; + Result.bClassifierRegionHit = + ClassifyProfileEnd.Counters[RegionHitIndex] > TileProfileStart.Counters[RegionHitIndex]; + } ClassifyVerdict = static_cast(Verdict); + Result.ClassifyVerdict = ClassifyVerdict; if (ShouldAbortWork()) { AbortResult(); @@ -2592,14 +2806,14 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector if (!bTrivialEmpty) { TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_GenerateMesh); - const double MeshStartSeconds = bProfileTile ? FPlatformTime::Seconds() : 0.0; + const double MeshStartSeconds = bMeasureTile ? FPlatformTime::Seconds() : 0.0; MeshData = bSheetTile ? Mesher->GenerateSheetMesh(OriginVoxels, Step, Cells, SheetChunkZ, HoleMinX, HoleMinY, HoleMaxX, HoleMaxY) : Mesher->GenerateMesh(OriginVoxels, Step, Cells, bWantCapture ? &Result.CaptureGrid : nullptr, BandVoxLo, BandVoxHi); - MeshSeconds = bProfileTile ? FPlatformTime::Seconds() - MeshStartSeconds : 0.0; + MeshSeconds = bMeasureTile ? FPlatformTime::Seconds() - MeshStartSeconds : 0.0; INC_DWORD_STAT(STAT_VoxelForgeTilesMeshed); if (ShouldAbortWork()) { @@ -2614,10 +2828,10 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector if (!MeshData.IsEmpty()) { TRACE_CPUPROFILER_EVENT_SCOPE(VoxelForge_BuildStreams); - const double StreamStartSeconds = bProfileTile ? FPlatformTime::Seconds() : 0.0; + const double StreamStartSeconds = bMeasureTile ? FPlatformTime::Seconds() : 0.0; Result.Streams = MakeShared(); BuildTileStreamSet(*Result.Streams, MeshData); - StreamSeconds = bProfileTile ? FPlatformTime::Seconds() - StreamStartSeconds : 0.0; + StreamSeconds = bMeasureTile ? FPlatformTime::Seconds() - StreamStartSeconds : 0.0; if (ShouldAbortWork()) { AbortResult(); @@ -2632,10 +2846,14 @@ void AVoxelWorld::GenerateTileResult(const FVoxelTileKey& Tile, const FIntVector // (Replaces the whole-tile normal VOTE, which painted mixed coarse tiles — terrain // AND cap in one tile — entirely with the winner's material.) const int32 NumTris = MeshData.Triangles.Num() / 3; + Result.NumTriangles = NumTris; Result.bHasCeilingTris = MeshData.NumCeilingTriangles > 0; Result.bHasGroundTris = NumTris > MeshData.NumCeilingTriangles; } + Result.ClassifySeconds = ClassifySeconds; + Result.MeshSeconds = MeshSeconds; + Result.StreamSeconds = StreamSeconds; EmitTileProfile(); } diff --git a/Source/VoxelForge/Public/VoxelStartupTrace.h b/Source/VoxelForge/Public/VoxelStartupTrace.h new file mode 100644 index 0000000..34e0cbe --- /dev/null +++ b/Source/VoxelForge/Public/VoxelStartupTrace.h @@ -0,0 +1,59 @@ +// Bounded, opt-in startup trace for the complete streaming path. +// The trace is deliberately independent of the shared Unreal log: callers provide an +// absolute output path and every record is one JSON object per line. +#pragma once + +#include "CoreMinimal.h" + +namespace VoxelForgeStartupTrace +{ + struct VOXELFORGE_API FTileSample + { + int32 Level = -1; + int32 Verdict = -1; // Mixed=0, AllSolid=1, AllAir=2, -1=not classified (sheet/early path) + bool bEmpty = true; + bool bCacheHit = false; + bool bRegionHit = false; + int32 Triangles = 0; + double RequestToReadySeconds = 0.0; + double QueueWaitSeconds = 0.0; + double WorkerQueueSeconds = 0.0; + double ResultQueueSeconds = 0.0; + double GenerationSeconds = 0.0; + double ClassifySeconds = 0.0; + double MeshSeconds = 0.0; + double StreamSeconds = 0.0; + double ApplySeconds = 0.0; + }; + + /** Starts when -voxel.StartupTraceFile= is present. */ + VOXELFORGE_API void BeginFromCommandLine(); + + VOXELFORGE_API bool IsActive(); + + /** 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 StageBegin(const TCHAR* Name); + VOXELFORGE_API void StageEnd(const TCHAR* Name); + + VOXELFORGE_API void RecordTile(const FTileSample& Sample); + + /** Writes the final bounded summary and closes the file. Safe to call more than once. */ + VOXELFORGE_API void Finish(const TCHAR* Reason); + + /** RAII helper for stages which have early-return failure paths. */ + class VOXELFORGE_API FStageScope + { + public: + explicit FStageScope(const TCHAR* InName); + ~FStageScope(); + + FStageScope(const FStageScope&) = delete; + FStageScope& operator=(const FStageScope&) = delete; + + private: + FString Name; + bool bActive = false; + }; +} diff --git a/Source/VoxelForge/Public/VoxelWorld.h b/Source/VoxelForge/Public/VoxelWorld.h index e81b56c..b0441a5 100644 --- a/Source/VoxelForge/Public/VoxelWorld.h +++ b/Source/VoxelForge/Public/VoxelWorld.h @@ -90,7 +90,7 @@ struct FChunkResult // Worker timing boundaries for separating scheduler wait from generation and result/apply wait. // These are telemetry-only and remain zero when tile profiling is disabled. uint64 GenerationStartCycles = 0; - uint64 GenerationEndCycles = 0; + uint64 GenerationEndCycles = 0; int32 ClassifyVerdict = -1; bool bClassifierCacheHit = false; bool bClassifierRegionHit = false; double ClassifySeconds = 0.0; double MeshSeconds = 0.0; double StreamSeconds = 0.0; int32 NumTriangles = 0; bool bAborted = false; // Worker observed shutdown; never mark this tile loaded bool bEmpty = true; // true ⇒ all-air tile (Streams null); still marked loaded so we don't re-submit // F17 — the mesher classifies every triangle semantically (sky-cap = down-facing near the @@ -797,6 +797,7 @@ public: // tile is streamed in — so a stationary player costs ~nothing per frame. FIntVector LastUpdateCenter = FIntVector(INT32_MAX, INT32_MAX, INT32_MAX); bool bAllChunksLoaded = false; + bool bStartupTraceDesiredRecorded = false; TArray DesiredSorted; // desired tiles, nearest-first // Desired-set membership STAMPÉE : clé → numéro du dernier crossing où la tuile était désirée.