diff --git a/Source/Windows/ARM64EC/Module.cpp b/Source/Windows/ARM64EC/Module.cpp index 633f252c34..d4e80d2132 100644 --- a/Source/Windows/ARM64EC/Module.cpp +++ b/Source/Windows/ARM64EC/Module.cpp @@ -37,6 +37,7 @@ desc: Implements the ARM64EC BT module API using FEXCore #include "Common/Exception.h" #include "Common/ImageTracker.h" #include "Common/InvalidationTracker.h" +#include "Common/SMCDiagnostics.h" #include "Common/Threads.h" #include "Common/OvercommitTracker.h" #include "Common/TSOHandlerConfig.h" @@ -761,8 +762,22 @@ bool ResetToConsistentStateImpl(const ThreadCPUArea CPUArea, EXCEPTION_RECORD* E return true; } + const bool MeasureSMC = AppConfigName == "SlayTheSpire.exe"; + FEX::Windows::SMCDiagnostics::Event Timing; + if (MeasureSMC) { + Timing.Start = FEX::Windows::SMCDiagnostics::Ticks(); + } std::scoped_lock Lock(ThreadCreationMutex); - if (InvalidationTracker && InvalidationTracker->HandleRWXAccessViolation(Thread, NativeContext->Pc, FaultAddress)) { + if (MeasureSMC) { + Timing.Stages[0] = FEX::Windows::SMCDiagnostics::Ticks() - Timing.Start; + } + if (InvalidationTracker && InvalidationTracker->HandleRWXAccessViolation(Thread, NativeContext->Pc, FaultAddress, + MeasureSMC ? &Timing : nullptr)) { + if (MeasureSMC) { + const auto End = FEX::Windows::SMCDiagnostics::Ticks(); + static FEX::Windows::SMCDiagnostics::Summary Summary; + Summary.Record(Timing, End); + } FEXCORE_PROFILE_INSTANT_INCREMENT(Thread, AccumulatedSMCCount, 1); if (CTX->IsAddressInCodeBuffer(Thread, NativeContext->Pc) && !CTX->IsCurrentBlockSingleInst(CPUArea.ThreadState()) && CTX->IsAddressInCurrentBlock(Thread, FaultAddress & FEXCore::Utils::FEX_PAGE_MASK, FEXCore::Utils::FEX_PAGE_SIZE)) { diff --git a/Source/Windows/Common/InvalidationTracker.cpp b/Source/Windows/Common/InvalidationTracker.cpp index 155403d35b..96924a5d52 100644 --- a/Source/Windows/Common/InvalidationTracker.cpp +++ b/Source/Windows/Common/InvalidationTracker.cpp @@ -7,6 +7,7 @@ #include #include #include "InvalidationTracker.h" +#include "SMCDiagnostics.h" #include #include @@ -216,7 +217,9 @@ void InvalidationTracker::ReprotectRWXIntervals(uint64_t Address, uint64_t Size) ProtectRWXIntervalsInternal(Address, Size, false); } -bool InvalidationTracker::HandleRWXAccessViolation(FEXCore::Core::InternalThreadState* Thread, uint64_t HostPc, uint64_t FaultAddress) { +bool InvalidationTracker::HandleRWXAccessViolation(FEXCore::Core::InternalThreadState* Thread, uint64_t HostPc, uint64_t FaultAddress, + SMCDiagnostics::Event* Timing) { + const auto LookupStart = Timing ? SMCDiagnostics::Ticks() : 0; const auto [NeedsInvalidate, UntrapProt] = [&](uint64_t Address) -> std::pair { std::shared_lock Lock(IntervalsLock); if (!RWXIntervals.Query(Address).Enclosed) { @@ -225,18 +228,30 @@ bool InvalidationTracker::HandleRWXAccessViolation(FEXCore::Core::InternalThread return {true, GetUntrapProt(Address)}; }(FaultAddress); + const auto LookupEnd = Timing ? SMCDiagnostics::Ticks() : 0; + if (Timing) { + Timing->Stages[1] = LookupEnd - LookupStart; + } + if (NeedsInvalidate) { // IntervalsLock cannot be held during invalidation { std::scoped_lock Lock(CTX.GetCodeInvalidationMutex()); + if (Timing) { + Timing->Stages[2] = SMCDiagnostics::Ticks() - LookupEnd; + } - InvalidateIntervalInternalLocked(FaultAddress & FEXCore::Utils::FEX_PAGE_MASK, FEXCore::Utils::FEX_PAGE_SIZE); + InvalidateIntervalInternalLocked(FaultAddress & FEXCore::Utils::FEX_PAGE_MASK, FEXCore::Utils::FEX_PAGE_SIZE, Timing); // Invalidate, then unprotect the faulting page with the compilation lock held to ensure that any racing invalidations are not dropped. ULONG TmpProt; void* TmpAddress = reinterpret_cast(FaultAddress); SIZE_T TmpSize = 1; + const auto ProtectStart = Timing ? SMCDiagnostics::Ticks() : 0; NtProtectVirtualMemory(NtCurrentProcess(), &TmpAddress, &TmpSize, UntrapProt, &TmpProt); + if (Timing) { + Timing->Stages[5] = SMCDiagnostics::Ticks() - ProtectStart; + } } DetectMonoBackpatcherBlock(Thread, HostPc); return true; @@ -330,12 +345,18 @@ void InvalidationTracker::InvalidateIntervalInternal(uint64_t Address, uint64_t InvalidateIntervalInternalLocked(Address, Size); } -void InvalidationTracker::InvalidateIntervalInternalLocked(uint64_t Address, uint64_t Size) { +void InvalidationTracker::InvalidateIntervalInternalLocked(uint64_t Address, uint64_t Size, SMCDiagnostics::Event* Timing) { // NOTE: This assumes CodeInvalidationMutex is locked by the caller + const auto BufferStart = Timing ? SMCDiagnostics::Ticks() : 0; CTX.InvalidateCodeBuffersCodeRange(Address, Size); + const auto CacheStart = Timing ? SMCDiagnostics::Ticks() : 0; for (auto Thread : Threads) { CTX.InvalidateThreadCachedCodeRange(Thread.second, Address, Size); } + if (Timing) { + Timing->Stages[3] = CacheStart - BufferStart; + Timing->Stages[4] = SMCDiagnostics::Ticks() - CacheStart; + } } bool InvalidationTracker::ProtectRWXIntervalsInternal(uint64_t Address, uint64_t Size, bool ForWriteLocked) { diff --git a/Source/Windows/Common/InvalidationTracker.h b/Source/Windows/Common/InvalidationTracker.h index d2a80bcaaa..1932555749 100644 --- a/Source/Windows/Common/InvalidationTracker.h +++ b/Source/Windows/Common/InvalidationTracker.h @@ -17,6 +17,9 @@ class Context; } namespace FEX::Windows { +namespace SMCDiagnostics { +struct Event; +} /** * @brief Handles SMC and regular code invalidation */ @@ -33,7 +36,8 @@ class InvalidationTracker { InvalidateContainingSectionResult InvalidateContainingSection(uint64_t Address, bool Free); void InvalidateAlignedInterval(uint64_t Address, uint64_t Size, bool Free); void ReprotectRWXIntervals(uint64_t Address, uint64_t Size); - bool HandleRWXAccessViolation(FEXCore::Core::InternalThreadState* Thread, uint64_t HostPC, uint64_t FaultAddress); + bool HandleRWXAccessViolation(FEXCore::Core::InternalThreadState* Thread, uint64_t HostPC, uint64_t FaultAddress, + SMCDiagnostics::Event* Timing = nullptr); // Unprotects any RWX intervals in the input interval and invalidates code // NOTE: CodeInvalidationMutex must be locked when calling this, and if true is returned, kept locked until the write ends. @@ -46,7 +50,7 @@ class InvalidationTracker { void DisableSMCDetection(); void InvalidateIntervalInternal(uint64_t Address, uint64_t Size); // NOTE: This assumed CodeInvalidationMutex is locked by the caller - void InvalidateIntervalInternalLocked(uint64_t Address, uint64_t Size); + void InvalidateIntervalInternalLocked(uint64_t Address, uint64_t Size, SMCDiagnostics::Event* Timing = nullptr); // NOTE: If ForWriteLocked is true then this assumes CodeInvalidationMutex is locked by the caller, // and any code in the range will be invalidated before protection as RWX, otherwise protects as RX if false. diff --git a/Source/Windows/Common/SMCDiagnostics.h b/Source/Windows/Common/SMCDiagnostics.h new file mode 100644 index 0000000000..7d2a128723 --- /dev/null +++ b/Source/Windows/Common/SMCDiagnostics.h @@ -0,0 +1,70 @@ +// SPDX-License-Identifier: MIT +#pragma once + +#include +#include +#include +#include +#include + +namespace FEX::Windows::SMCDiagnostics { +inline uint64_t Ticks() { + LARGE_INTEGER Counter {}; + QueryPerformanceCounter(&Counter); + return Counter.QuadPart; +} + +struct Event { + uint64_t Start {}; + // ThreadCreationMutex wait, interval lookup, code mutex wait, shared code + // invalidation, thread cache/return-stack invalidation, page unprotection. + std::array Stages {}; +}; + +// The ARM64EC caller holds ThreadCreationMutex for both sampling and reporting. +// This intentionally bypasses SILENTLOG: component cards need no logging env +// override, and enabling the existing per-fault debug stream perturbs this test. +class Summary { +public: + void Record(const Event& Sample, uint64_t End) { + ++Count; + ++TotalCount; + TotalTicks += End - Sample.Start; + MaxTicks = std::max(MaxTicks, End - Sample.Start); + for (size_t i = 0; i < Sum.size(); ++i) { + Sum[i] += Sample.Stages[i]; + Max[i] = std::max(Max[i], Sample.Stages[i]); + } + + if (LastReport && End - LastReport < Frequency) { + return; + } + const auto Ms = [this](uint64_t Value) { return static_cast(Value) * 1000.0 / Frequency; }; + if (Output) { + const auto Line = fextl::fmt::format( + "FEX-SMC-TIMING pid={} qpc_ms={:.3f} window_ms={:.3f} count={} total_count={} total_ms={:.3f} max_ms={:.3f} " + "thread_wait_ms={:.3f}/{:.3f} lookup_ms={:.3f}/{:.3f} code_wait_ms={:.3f}/{:.3f} " + "buffers_ms={:.3f}/{:.3f} caches_ms={:.3f}/{:.3f} protect_ms={:.3f}/{:.3f} (sum/max)\n", + GetCurrentProcessId(), Ms(End), LastReport ? Ms(End - LastReport) : 0.0, Count, TotalCount, Ms(TotalTicks), Ms(MaxTicks), + Ms(Sum[0]), Ms(Max[0]), Ms(Sum[1]), Ms(Max[1]), Ms(Sum[2]), Ms(Max[2]), Ms(Sum[3]), Ms(Max[3]), + Ms(Sum[4]), Ms(Max[4]), Ms(Sum[5]), Ms(Max[5])); + Output(Line.c_str()); + } + LastReport = End; + Count = TotalTicks = MaxTicks = 0; + Sum.fill(0); + Max.fill(0); + } + +private: + uint64_t Frequency = [] { + LARGE_INTEGER Value {}; + QueryPerformanceFrequency(&Value); + return static_cast(Value.QuadPart ? Value.QuadPart : 1); + }(); + void (*Output)(const char*) = reinterpret_cast( + GetProcAddress(GetModuleHandleW(L"ntdll.dll"), "__wine_dbg_output")); + uint64_t LastReport {}, Count {}, TotalCount {}, TotalTicks {}, MaxTicks {}; + std::array Sum {}, Max {}; +}; +} // namespace FEX::Windows::SMCDiagnostics