VoxelForge/Source/VoxelForge/Private/VoxelStartupTrace.cpp

#include "VoxelStartupTrace.h"

#include "HAL/FileManager.h"
#include "HAL/PlatformTime.h"
#include "Misc/CommandLine.h"
#include "Misc/Parse.h"

#include <atomic>

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;
        int32 ApplyFrameRecords = 0;
        TArray<FTileSample> Samples;
        TMap<FString, double> StageStarts;
        TMap<FString, double> StageTotals;
        TArray<FString> StageOrder;
        bool bActive = false;
    };

    FCriticalSection GTraceLock;
    TUniquePtr<FState> GState;
    std::atomic<bool> GTraceActive{false};

    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<ANSICHAR*>(Utf8.Get()), Utf8.Length());
        // 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)
    {
        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<double> Values, double Fraction)
    {
        if (Values.Num() == 0) return 0.0;
        Values.Sort();
        const int32 Index = FMath::Clamp(
            FMath::CeilToInt(Fraction * static_cast<double>(Values.Num() - 1)),
            0,
            Values.Num() - 1);
        return Values[Index];
    }

    double Maximum(const TArray<double>& Values)
    {
        double Result = 0.0;
        for (const double Value : Values)
        {
            Result = FMath::Max(Result, Value);
        }
        return Result;
    }

    FString BuildTileGroupJson(const TArray<FTileSample>& Samples, int32 Level)
    {
        TArray<double> Request, Queue, WorkerTask, Generation, Classify, Mesh, Apply;
        int32 Count = 0;
        int32 Empty = 0;
        int32 AllAir = 0;
        int32 AllSolid = 0;
        int32 Mixed = 0;
        int64 Vertices = 0;
        int64 Triangles = 0;
        uint64 GeometryBytes = 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;
            Vertices += Sample.Vertices;
            Triangles += Sample.Triangles;
            GeometryBytes += Sample.GeometryBytes;
            Request.Add(Sample.RequestToApplySeconds);
            Queue.Add(Sample.QueueWaitSeconds);
            WorkerTask.Add(Sample.WorkerTaskSeconds);
            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,\"vertices\":%lld,\"triangles\":%lld,\"geometry_bytes\":%llu,"
                 "\"request_apply_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s},"
                 "\"queue_s\":{\"p50\":%s,\"p95\":%s,\"max\":%s},"
                 "\"worker_task_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,
            static_cast<long long>(Vertices), static_cast<long long>(Triangles),
            static_cast<unsigned long long>(GeometryBytes),
            *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(WorkerTask, 0.50)), *Number(Percentile(WorkerTask, 0.95)), *Number(Maximum(WorkerTask)),
            *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<int32> 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,\"apply_frame_records\":%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, State.ApplyFrameRecords, *Stages, *Groups);
    }
}

void BeginFromCommandLine()
{
    FScopeLock Lock(&GTraceLock);
    if (GState.IsValid()) return;

    FString Path;
    if (!FParse::Value(FCommandLine::Get(), TEXT("voxel.StartupTraceFile="), Path)) return;
    Path.TrimQuotesInline();
    if (Path.IsEmpty()) return;

    TUniquePtr<FState> NewState = MakeUnique<FState>();
    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);
    GTraceActive.store(true, std::memory_order_release);
    WriteEventLocked(*GState, TEXT("header"), FString::Printf(
        TEXT("\"schema\":1,\"path\":\"%s\",\"tile_record_cap\":%d"),
        *JsonEscape(GState->Path), GState->TileRecordCap));
}

bool IsActive()
{
    return GTraceActive.load(std::memory_order_acquire);
}

void RecordEvent(const TCHAR* Type, const FString& FieldsJson)
{
    FScopeLock Lock(&GTraceLock);
    if (!GState.IsValid() || !GState->bActive) return;
    WriteEventLocked(*GState, Type, FieldsJson);
}

void RecordRequest(const FTileSample& Sample, uint32 Epoch)
{
    FScopeLock Lock(&GTraceLock);
    if (!GState.IsValid() || !GState->bActive) return;
    WriteEventLocked(*GState, TEXT("request"), FString::Printf(
        TEXT("\"tile\":[%d,%d,%d],\"level\":%d,\"priority\":%d,"
             "\"request_ordinal\":%llu,\"epoch\":%u,\"resident_at_request\":%d"),
        Sample.TileX, Sample.TileY, Sample.TileZ, Sample.Level, Sample.WorkPriority,
        static_cast<unsigned long long>(Sample.RequestOrdinal), Epoch,
        Sample.bResidentAtRequest ? 1 : 0));
}

void StageBegin(const TCHAR* Name)
{
    if (Name == nullptr) return;
    FScopeLock Lock(&GTraceLock);
    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(&GTraceLock);
    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(&GTraceLock);
    if (!GState.IsValid() || !GState->bActive) return;
    ++GState->TileRecordsSeen;
    if (GState->TileRecordsWritten >= GState->TileRecordCap)
    {
        ++GState->TileRecordsSuppressed;
        return;
    }

    GState->Samples.Add(Sample);
    ++GState->TileRecordsWritten;
    const double TraceNowSeconds = FPlatformTime::Seconds() - GState->StartSeconds;
    const double SubmittedAtSeconds = Sample.RequestStartCycles != 0
        ? TraceNowSeconds - Sample.RequestToApplySeconds : -1.0;
    const double WorkerStartedAtSeconds = Sample.WorkerTaskStartCycles != 0
        ? SubmittedAtSeconds + Sample.WorkerQueueSeconds : -1.0;
    const double WorkerEndedAtSeconds = Sample.WorkerTaskEndCycles != 0
        ? WorkerStartedAtSeconds + Sample.WorkerTaskSeconds : -1.0;
    WriteEventLocked(*GState, TEXT("tile"), FString::Printf(
        TEXT("\"tile\":[%d,%d,%d],\"level\":%d,\"priority\":%d,"
             "\"request_ordinal\":%llu,\"generation_ordinal\":%llu,\"resident_at_request\":%d,"
             "\"submitted_t_s\":%s,\"worker_start_t_s\":%s,\"worker_end_t_s\":%s,\"worker_thread_id\":%u,"
             "\"verdict\":%d,\"proof\":%d,\"empty\":%d,\"vertices\":%d,\"triangles\":%d,\"geometry_bytes\":%llu,"
             "\"request_to_apply_s\":%s,\"queue_wait_s\":%s,\"worker_queue_s\":%s,\"result_queue_s\":%s,\"worker_task_s\":%s,"
             "\"generation_s\":%s,\"classify_s\":%s,\"mesh_s\":%s,\"stream_s\":%s,\"apply_s\":%s"),
        Sample.TileX, Sample.TileY, Sample.TileZ,
        Sample.Level, Sample.WorkPriority,
        static_cast<unsigned long long>(Sample.RequestOrdinal),
        static_cast<unsigned long long>(Sample.GenerationOrdinal),
        Sample.bResidentAtRequest ? 1 : 0,
        *Number(SubmittedAtSeconds),
        *Number(WorkerStartedAtSeconds),
        *Number(WorkerEndedAtSeconds),
        Sample.WorkerThreadId,
        Sample.Verdict, Sample.bSealedSolidProof ? 1 : 0,
        Sample.bEmpty ? 1 : 0, Sample.Vertices, Sample.Triangles,
        static_cast<unsigned long long>(Sample.GeometryBytes),
        *Number(Sample.RequestToApplySeconds), *Number(Sample.QueueWaitSeconds),
        *Number(Sample.WorkerQueueSeconds), *Number(Sample.ResultQueueSeconds),
        *Number(Sample.WorkerTaskSeconds),
        *Number(Sample.GenerationSeconds), *Number(Sample.ClassifySeconds),
        *Number(Sample.MeshSeconds), *Number(Sample.StreamSeconds), *Number(Sample.ApplySeconds)));
}

void RecordApplyFrame(const FApplyFrameSample& Sample)
{
    FScopeLock Lock(&GTraceLock);
    if (!GState.IsValid() || !GState->bActive) return;

    FString PendingByLevel = TEXT("[");
    FString ApplyResultsByLevel = TEXT("[");
    FString MeshesByLevel = TEXT("[");
    FString ApplyMillisecondsByLevel = TEXT("[");
    for (int32 Level = 0; Level < 9; ++Level)
    {
        if (Level > 0)
        {
            PendingByLevel += TEXT(",");
            ApplyResultsByLevel += TEXT(",");
            MeshesByLevel += TEXT(",");
            ApplyMillisecondsByLevel += TEXT(",");
        }
        PendingByLevel += FString::FromInt(Sample.PendingByLevel[Level]);
        ApplyResultsByLevel += FString::FromInt(Sample.ApplyResultsByLevel[Level]);
        MeshesByLevel += FString::FromInt(Sample.MeshesAppliedByLevel[Level]);
        ApplyMillisecondsByLevel += Number(Sample.ApplySecondsByLevel[Level] * 1000.0);
    }
    PendingByLevel += TEXT("]");
    ApplyResultsByLevel += TEXT("]");
    MeshesByLevel += TEXT("]");
    ApplyMillisecondsByLevel += TEXT("]");

    ++GState->ApplyFrameRecords;
    WriteEventLocked(*GState, TEXT("apply_frame"), FString::Printf(
        TEXT("\"frame\":%llu,\"frame_ms\":%s,\"speed_cm_s\":%s,\"apply_ms\":%s,\"drain_ms\":%s,"
             "\"active_tasks\":%d,\"running_workers\":%d,\"task_cap\":%d,"
             "\"pending_tiles\":%d,\"pending_results_estimate\":%d,"
             "\"results_drained\":%d,\"apply_results\":%d,\"meshes_applied\":%d,\"max_applies\":%d,"
             "\"apply_budget_ms\":%s,\"count_limit_reached\":%d,\"time_limit_reached\":%d,"
             "\"pending_by_lod\":%s,\"apply_results_by_lod\":%s,"
             "\"meshes_by_lod\":%s,\"apply_ms_by_lod\":%s"),
        static_cast<unsigned long long>(Sample.Frame),
        *Number(Sample.FrameSeconds * 1000.0), *Number(Sample.SpeedCmPerSecond),
        *Number(Sample.ApplySeconds * 1000.0), *Number(Sample.DrainSeconds * 1000.0), Sample.ActiveTasks,
        Sample.RunningWorkerTasks, Sample.TaskCap, Sample.PendingTiles,
        Sample.PendingResultsEstimate, Sample.ResultsDrained, Sample.ApplyResultsByLevelTotal,
        Sample.MeshesApplied,
        Sample.MaxApplies, *Number(Sample.ApplyBudgetMilliseconds),
        Sample.bCountLimitReached ? 1 : 0, Sample.bTimeLimitReached ? 1 : 0,
        *PendingByLevel, *ApplyResultsByLevel, *MeshesByLevel, *ApplyMillisecondsByLevel));
}

void Finish(const TCHAR* Reason)
{
    FScopeLock Lock(&GTraceLock);
    if (!GState.IsValid() || !GState->bActive) return;
    GTraceActive.store(false, std::memory_order_release);

    // Close any stage left open by an abnormal early exit so the summary remains useful.
    const double Now = FPlatformTime::Seconds();
    for (const TPair<FString, double>& 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<ANSICHAR*>(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);
}
}