From aa629710474bdbd1255e5700936ed9439a3dfd11 Mon Sep 17 00:00:00 2001 From: Fr0zka Date: Fri, 11 Sep 2026 20:03:24 +0200 Subject: [PATCH] tools(trace): Play-to-steady-state timeline -- startup is 83ms, the other 8.2s is tiles MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Measurement only, no optimisation, per the instruction. First time anyone has looked at the path BEFORE LoadTile, and first time any measurement has used the owner's REAL assets instead of the commandlet's synthetic strates. Trace: Saved/StartupTraceRealFinalTrace.startup.jsonl -- 873 JSONL records, 268 KB, 841 tile records, bounded at 4096 with zero suppressed. Structured, own file, stream-parseable; the 13 GB log pile taught that lesson twice. TIMELINE BeginPlay 45.585 ms StrateManager.Initialize 29.018 ms GeneratePassages 6.628 ms (5 passages) first BuildDesiredTiles 2.710 ms ------------------------------------------ all startup stages ~83 ms BeginPlay -> steady state 8.216 s process launch -> stop 20.164 s ⚠️ My hypothesis was wrong: I expected layout resolution or GeneratePassages to be a hidden one-off cost. They are 83 ms combined. **The 8.2 seconds is tiles, all of it.** A further ~2.05 s sits between BeginPlay finishing and the first desired-set build, and the trace attributes that to engine/map/player startup, not to us. REAL ASSET RESOLUTION -- two things worth the owner's attention settings /Game/VoxelForge/DA_Settings, seed 0 ⭐ five slots, ALL resolving to /Game/VoxelForge/DA_Strate3 InterStrateGapChunks 2 MaxClipLevel 4, ClipRadius 3, RenderDistanceChunks 0 bFarSheetRing true, but NO sheet tiles exist because render distance is 0 ⭐ bEnableDensityVolume FALSE -- already off, no volume object, no GPU upload DA_Strate1 (the 10.7 KB surface strate) and DA_Strate2 (rooms + water) are not in play at all. Every strate in the world is Strate3. THE DESIRED SET -- 841 tiles, and the shape is the story LOD0 343 tiles 8 m each 56 x 56 x 56 m LOD1 218 16 m 112 x 112 x 80 m LOD2 120 32 m 224 x 224 x 96 m LOD3 80 64 m 448 x 448 x 128 m LOD4 80 128 m 896 x 896 x 256 m ⭐ LOD4 covers 896 x 896 x 256 m -- about 205 MILLION cubic metres of cave -- and its verdicts are 0 AllAir / 0 AllSolid / 80 Mixed. Not one LOD4 tile can be skipped, and each costs 127.5 ms p50 / 291.6 ms max to generate. That is roughly 12 s of CPU spent on geometry nobody can see from inside a cave. TILE DISTRIBUTIONS (p50 / p95 / max ms) LOD tiles verdicts A/S/M req->ready generation mesh 0 343 98/123/122 44.9/420.8/819.5 9.6/358.2/767.6 0/341.6/726.1 1 218 49/83/86 31.1/148.9/188.6 8.7/134.3/164.2 0/117.8/151.1 2 120 0/39/81 34.0/61.6/76.9 10.9/43.6/63.7 9.9/40.4/60.5 3 80 0/2/78 46.4/85.9/96.3 38.5/80.7/87.8 31.0/67.5/70.7 4 80 0/0/80 148.2/272.8/304.2 127.5/253.8/291.6 127.4/253.8/291.5 totals: 147 AllAir, 247 AllSolid, 447 Mixed, 669,834 triangles apply never exceeds 0.43 ms at any level zero classifier-cache and region-cache hits on a fresh process, as expected ⇒ The two costs are LOD0's 122 meshed tiles (~360 ms p95 each) and LOD4's 80 unskippable tiles (~150 ms each). Apply, queue and startup are all noise beside them. VERIFIED BY ME: build 0 errors; export 1.034 / 1.089 s (5ddd966 was 1.013-1.075, so the instrumentation does not distort); geometry SHA-256 b3e5f4c3..9b377 UNCHANGED. Game peak RSS 2.07 GB. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_012aheo2crrZmHuYtPpdY2Cb --- .../VoxelForge/Private/VoxelStartupTrace.cpp | 320 ++++++++++++++++++ .../VoxelForge/Private/VoxelStrateManager.cpp | 34 +- Source/VoxelForge/Private/VoxelWorld.cpp | 274 +++++++++++++-- Source/VoxelForge/Public/VoxelStartupTrace.h | 59 ++++ Source/VoxelForge/Public/VoxelWorld.h | 3 +- 5 files changed, 660 insertions(+), 30 deletions(-) create mode 100644 Source/VoxelForge/Private/VoxelStartupTrace.cpp create mode 100644 Source/VoxelForge/Public/VoxelStartupTrace.h 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.