RSP: Fix up profiling tasks

Source/Project64-rsp-core/Hle/HleTask.cpp

@@ -1,4 +1,5 @@
 #include <Project64-rsp-core/Hle/HleTask.h>
+#include <Project64-rsp-core/Recompiler/RspProfiling.h>
 #include <Project64-rsp-core/cpu/RSPRegisterHandlerPlugin.h>
 #include <Project64-rsp-core/cpu/RspMemory.h>
 #include <Project64-rsp-core/cpu/RspSystem.h>
@@ -62,6 +63,10 @@ void CHleTask::SetupCommandList(const TASK_INFO & TaskInfo)
         return;
     }
 
+    if (Profiling)
+    {
+        StartTimer((uint32_t)Timer_Compiling);
+    }
     if (m_FunctionMap.size() > 0)
     {
         g_Notify->BreakPoint(__FILE__, __LINE__);
@@ -74,8 +79,7 @@ void CHleTask::SetupCommandList(const TASK_INFO & TaskInfo)
         uint16_t FuncAddress = *((uint16_t *)(m_DMEM + (((i << 1) + JumpTablePos) ^ 2)));
         if (FuncAddress != 0x1118)
         {
-            m_Recompiler.CompileHLETask(FuncAddress);
+            void * FuncPtr = m_Recompiler.CompileHLETask(FuncAddress);
-            void * FuncPtr = *(JumpTable + ((FuncAddress & 0xFFF) >> 2));
             JumpFunctions.emplace_back(TaskFunctionAddress(FuncAddress, FuncPtr));
         }
         else
@@ -91,6 +95,10 @@ void CHleTask::SetupCommandList(const TASK_INFO & TaskInfo)
         return;
     }
     m_TaskFunctions = &itr->second;
+    if (Profiling)
+    {
+        StopTimer();
+    }
 }
 
 void CHleTask::ExecuteTask_1a13a51a(const TASK_INFO & TaskInfo)
@@ -145,7 +153,7 @@ void CHleTask::ExecuteTask_1a13a51a(const TASK_INFO & TaskInfo)
             RSPSystem.SyncSystem()->ExecuteOps(0x10000, 0x118);
         }
         typedef void (*FuncPtr)();
-        FuncPtr func = (FuncPtr)(*(JumpTable + ((*m_SP_PC_REG & 0xFFF) >> 2)));
+        FuncPtr func = (FuncPtr)FunctionAddress.second;
         if (func == nullptr)
         {
             g_Notify->BreakPoint(__FILE__, __LINE__);

Source/Project64-rsp-core/Recompiler/RspProfiling.cpp

@@ -5,9 +5,17 @@
 #include <Common/File.h>
 #include <Common/Log.h>
 #include <Common/StdString.h>
+#include <Common/path.h>
+#include <Project64-rsp-core/Settings/RspSettings.h>
 #include <Settings/Settings.h>
+#include <chrono>
+#include <intrin.h>
 #include <map>
+#include <thread>
 #include <vector>
+#ifdef WIN32
+#include <Windows.h>
+#endif
 
 class CRspProfiling
 {
@@ -21,16 +29,28 @@ class CRspProfiling
     } TIMER_NAME;
 
     uint32_t m_CurrentTimerAddr, CurrentDisplayCount;
+#if defined(_M_IX86) && defined(_MSC_VER)
     uint32_t m_StartTimeHi, m_StartTimeLo; // The current timer start time
+#else
+    uint64_t m_StartTime;
+#endif
     PROFILE_ENRTIES m_Entries;
+    double m_CpuFrequencyGHz;
 
 public:
     CRspProfiling()
     {
         m_CurrentTimerAddr = Timer_None;
+#ifdef WIN32
+        LARGE_INTEGER frequency;
+        QueryPerformanceFrequency(&frequency);
+        m_CpuFrequencyGHz = MeasureCpuFrequencyGHz();
+#else
+        g_Notify->BreakPoint(__FILE__, __LINE__);
+        m_CpuFrequencyGHz = 0;
+#endif
     }
 
-    // Recording timing against current timer, returns the address of the timer stopped
     uint32_t StartTimer(uint32_t Address)
     {
         uint32_t OldTimerAddr = StopTimer();
@@ -48,7 +68,9 @@ public:
         m_StartTimeHi = HiValue;
         m_StartTimeLo = LoValue;
 #else
-        g_Notify->BreakPoint(__FILE__, __LINE__);
+        _mm_lfence();
+        m_StartTime = __rdtsc();
+        _mm_lfence();
 #endif
         return OldTimerAddr;
     }
@@ -72,7 +94,12 @@ public:
         int64_t StopTime = ((uint64_t)HiValue << 32) + (uint64_t)LoValue;
         int64_t StartTime = ((uint64_t)m_StartTimeHi << 32) + (uint64_t)m_StartTimeLo;
         int64_t TimeTaken = StopTime - StartTime;
-
+#else
+        _mm_lfence();
+        uint64_t currentTime = __rdtsc();
+        _mm_lfence();
+        int64_t TimeTaken = currentTime - m_StartTime;
+#endif
         PROFILE_ENRTY Entry = m_Entries.find(m_CurrentTimerAddr);
         if (Entry != m_Entries.end())
         {
@@ -82,28 +109,44 @@ public:
         {
             m_Entries.insert(PROFILE_ENRTIES::value_type(m_CurrentTimerAddr, TimeTaken));
         }
-#else
-        g_Notify->BreakPoint(__FILE__, __LINE__);
-#endif
 
         uint32_t OldTimerAddr = m_CurrentTimerAddr;
         m_CurrentTimerAddr = Timer_None;
         return OldTimerAddr;
     }
 
-    // Reset all the counters back to 0
     void ResetCounters(void)
     {
         m_Entries.clear();
     }
 
-    // Generate a log file with the current results, this will also reset the counters
+    double ConvertCyclesToMilliseconds(uint64_t cycles, double cpuFreqGHz)
+    {
+        return (cycles / (cpuFreqGHz * 1e9)) * 1000.0;
+    }
+
+    double MeasureCpuFrequencyGHz()
+    {
+        DWORD_PTR oldMask = SetThreadAffinityMask(GetCurrentThread(), 1);
+        auto start_time = std::chrono::high_resolution_clock::now();
+        uint64_t start_cycles = __rdtsc();
+        std::this_thread::sleep_for(std::chrono::milliseconds(500));
+        uint64_t end_cycles = __rdtsc();
+        auto end_time = std::chrono::high_resolution_clock::now();
+        SetThreadAffinityMask(GetCurrentThread(), oldMask);
+        double elapsed_seconds = std::chrono::duration<double>(end_time - start_time).count();
+        uint64_t elapsed_cycles = end_cycles - start_cycles;
+        return static_cast<double>(elapsed_cycles) / (elapsed_seconds * 1e9);
+    }
     void GenerateLog(void)
     {
         stdstr LogFileName;
         {
+            char LogDir[260];
+            CPath LogFilePath(GetSystemSettingSz(Set_DirectoryLog, LogDir, sizeof(LogDir)), "RSP_Profiling.txt");
+
             CLog Log;
-            Log.Open("RSP Profiling.txt");
+            Log.Open(LogFilePath);
             LogFileName = Log.FileName();
 
             // Get the total time
@@ -138,31 +181,25 @@ public:
             }
 
             TIMER_NAME TimerNames[] = {
-                {Timer_Compiling, "RSP: Compiling"},
+                {Timer_Compiling, "Compiling"},
                 {Timer_RSP_Running, "RSP: Running"},
-                {Timer_R4300_Running, "R4300i: Running"},
                 {Timer_RDP_Running, "RDP: Running"},
             };
 
-            for (size_t count = 0; count < ItemList.size(); count++)
+            for (size_t i = 0; i < ItemList.size(); i++)
             {
-                char Buffer[255];
+                float CpuUsage = (float)(((double)ItemList[i]->second / (double)TotalTime) * 100);
-                float CpuUsage = (float)(((double)ItemList[count]->second / (double)TotalTime) * 100);
 
-                if (CpuUsage <= 0.2)
+                stdstr_f name("Function 0x%08X", ItemList[i]->first);
-                {
-                    continue;
-                }
-                sprintf(Buffer, "Function 0x%08X", ItemList[count]->first);
                 for (int NameID = 0; NameID < (sizeof(TimerNames) / sizeof(TIMER_NAME)); NameID++)
                 {
-                    if (ItemList[count]->first == (uint32_t)TimerNames[NameID].Timer)
+                    if (ItemList[i]->first == (uint32_t)TimerNames[NameID].Timer)
                     {
-                        strcpy(Buffer, TimerNames[NameID].Name);
+                        name = TimerNames[NameID].Name;
                         break;
                     }
                 }
-                Log.LogF("%s\t%2.2f", Buffer, CpuUsage);
+                Log.LogF("%s\t%2.2f\t%llu\t%2.2f\n", name.c_str(), CpuUsage, ItemList[i]->second, ConvertCyclesToMilliseconds(ItemList[i]->second, m_CpuFrequencyGHz));
             }
         }
         ResetCounters();

Source/Project64-rsp-core/Recompiler/RspProfiling.h

@@ -6,14 +6,7 @@ enum SPECIAL_TIMERS
     Timer_None = 0,
     Timer_Compiling = -1,
     Timer_RSP_Running = -2,
-    Timer_R4300_Running = -3,
+    Timer_RDP_Running = -3,
-    Timer_RDP_Running = -5,
-    Timer_RefreshScreen = -6,
-    Timer_UpdateScreen = -7,
-    Timer_UpdateFPS = -9,
-    Timer_Idel = -10,
-    Timer_FuncLookup = -11,
-    Timer_Done = -13,
 };
 
 void ResetTimerList(void);

Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.cpp

@@ -3,6 +3,7 @@
 #include "RspRecompilerCPU-x64.h"
 #include <Common/Log.h>
 #include <Project64-rsp-core/Recompiler/RspAssembler.h>
+#include <Project64-rsp-core/Recompiler/RspProfiling.h>
 #include <Project64-rsp-core/Settings/RspSettings.h>
 #include <Project64-rsp-core/cpu/RspMemory.h>
 #include <Project64-rsp-core/cpu/RspSystem.h>
@@ -18,11 +19,6 @@ CRSPRecompiler::CRSPRecompiler(CRSPSystem & System) :
     m_Assembler(nullptr)
 {
     m_Environment = asmjit::Environment::host();
-    m_CodeHolder.init(m_Environment);
-    m_CodeHolder.setErrorHandler(this);
-    m_CodeHolder.setLogger(nullptr);
-
-    m_Assembler = new RspAssembler(&m_CodeHolder, m_CodeLog);
 }
 
 CRSPRecompiler::~CRSPRecompiler()
@@ -36,35 +32,54 @@ CRSPRecompiler::~CRSPRecompiler()
 
 void CRSPRecompiler::Reset()
 {
+    if (m_Assembler != nullptr)
+    {
         m_Assembler->Reset();
+    }
 }
 
-void CRSPRecompiler::CompileHLETask(uint32_t Address)
+void * CRSPRecompiler::CompileHLETask(uint32_t Address)
 {
+    void * funcPtr = RecompPos;
     Log("====== Block %d ======", m_BlockID++);
-    Log("asm code at: %016llX", (uint64_t)RecompPos);
+    Log("asm code at: %016llX", (uint64_t)funcPtr);
     Log("Jump table: %X", Table);
     Log("Start of block: %X", Address);
     Log("====== Recompiled code ======");
 
-    *(JumpTable + ((Address & 0xFFF) >> 2)) = RecompPos;
+    if (m_Assembler != nullptr)
+    {
+        delete m_Assembler;
+        m_Assembler = nullptr;
+    }
 
+    m_CodeHolder.reset();
+    m_CodeHolder.init(m_Environment);
+    m_CodeHolder.setErrorHandler(this);
+    m_CodeHolder.setLogger(nullptr);
+
+    m_Assembler = new RspAssembler(&m_CodeHolder, m_CodeLog);
     m_Assembler->push(asmjit::x86::rbp);
     m_Assembler->mov(asmjit::x86::rbp, asmjit::x86::rsp);
     m_Assembler->sub(asmjit::x86::rsp, 0x30);
+    m_Assembler->mov(asmjit::x86::rcx, asmjit::imm((uintptr_t)Address));
+    m_Assembler->mov(asmjit::x86::rax, asmjit::imm(AddressOf(&StartTimer)));
+    m_Assembler->call(asmjit::x86::rax);
     m_Assembler->mov(asmjit::x86::rcx, asmjit::imm((uintptr_t)&m_System));
     m_Assembler->mov(asmjit::x86::edx, asmjit::imm(0x10000));
     m_Assembler->mov(asmjit::x86::r8d, asmjit::imm(0x118));
     m_Assembler->mov(asmjit::x86::rax, asmjit::imm(AddressOf(&CRSPSystem::ExecuteOps)));
     m_Assembler->call(asmjit::x86::rax);
+    m_Assembler->mov(asmjit::x86::rax, asmjit::imm(AddressOf(&StopTimer)));
+    m_Assembler->call(asmjit::x86::rax);
     m_Assembler->add(asmjit::x86::rsp, 0x30);
     m_Assembler->pop(asmjit::x86::rbp);
     m_Assembler->ret();
     m_Assembler->finalize();
 
-    m_CodeHolder.relocateToBase((uint64_t)RecompPos);
+    m_CodeHolder.relocateToBase((uint64_t)funcPtr);
     size_t codeSize = m_CodeHolder.codeSize();
-    m_CodeHolder.copyFlattenedData(RecompPos, codeSize);
+    m_CodeHolder.copyFlattenedData(funcPtr, codeSize);
     RecompPos += codeSize;
 
     if (LogAsmCode && !m_CodeLog.empty() && CPULog != nullptr)
@@ -74,6 +89,7 @@ void CRSPRecompiler::CompileHLETask(uint32_t Address)
         CPULog->Flush();
         m_CodeLog.clear();
     }
+    return funcPtr;
 }
 
 void CRSPRecompiler::Log(_Printf_format_string_ const char * Text, ...)

Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.h

@@ -14,7 +14,7 @@ public:
     ~CRSPRecompiler();
 
     void Reset();
-    void CompileHLETask(uint32_t Address);
+    void * CompileHLETask(uint32_t Address);
     void Log(_Printf_format_string_ const char * Text, ...);
 
 private:

Source/Project64-rsp-core/cpu/RSPiInstruction.cpp

@@ -15,8 +15,8 @@ RSPInstruction & RSPInstruction::operator=(const RSPInstruction & e)
 {
     m_Address = e.m_Address;
     m_Instruction.Value = e.m_Instruction.Value;
-    memcpy(m_Name, e.m_Name, sizeof(m_Name));
+    m_Name[0] = '\0';
-    memcpy(m_Param, e.m_Param, sizeof(m_Param));
+    m_Param[0] = '\0';
     return *this;
 }
 

Source/Project64-rsp-core/cpu/RspLog.cpp

@@ -19,7 +19,7 @@ void StartCPULog(void)
         return;
     }
     char LogDir[260];
-    CPath LogFilePath(GetSystemSettingSz(Set_DirectoryLog, LogDir, sizeof(LogDir)), "RSP_x86Log.txt");
+    CPath LogFilePath(GetSystemSettingSz(Set_DirectoryLog, LogDir, sizeof(LogDir)), "RSP_asm.txt");
     CPULog = new CLog;
     if (CPULog != nullptr)
     {

Source/Project64-rsp/Debugger/RSPDebuggerUI.cpp

@@ -48,7 +48,7 @@ void RSPDebuggerUI::RspCyclesStop(void)
 {
     if (Profiling && !IndvidualBlock)
     {
-        StartTimer((DWORD)Timer_R4300_Running);
+        StartTimer((DWORD)Timer_None);
     }
 }