Slay the Spire: time ARM64EC SMC invalidation stages

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)) {

Source/Windows/Common/InvalidationTracker.cpp

@@ -7,6 +7,7 @@
 #include <FEXCore/Config/Config.h>
 #include <FEXCore/Debug/InternalThreadState.h>
 #include "InvalidationTracker.h"
+#include "SMCDiagnostics.h"
 #include <windef.h>
 #include <winternl.h>
 
@@ -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<bool, ULONG> {
     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<void*>(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) {

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.

Source/Windows/Common/SMCDiagnostics.h

@@ -0,0 +1,70 @@
+// SPDX-License-Identifier: MIT
+#pragma once
+
+#include <FEXCore/fextl/fmt.h>
+#include <array>
+#include <algorithm>
+#include <cstdint>
+#include <windows.h>
+
+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<uint64_t, 6> 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<double>(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<uint64_t>(Value.QuadPart ? Value.QuadPart : 1);
+  }();
+  void (*Output)(const char*) = reinterpret_cast<void (*)(const char*)>(
+    GetProcAddress(GetModuleHandleW(L"ntdll.dll"), "__wine_dbg_output"));
+  uint64_t LastReport {}, Count {}, TotalCount {}, TotalTicks {}, MaxTicks {};
+  std::array<uint64_t, 6> Sum {}, Max {};
+};
+} // namespace FEX::Windows::SMCDiagnostics