From 2c2060248d340ef6a56631c2475a1653a9bd63f7 Mon Sep 17 00:00:00 2001 From: zilmar Date: Thu, 17 Apr 2025 17:06:17 +0930 Subject: [PATCH] RSP: Fix up profiling tasks --- Source/Project64-rsp-core/Hle/HleTask.cpp | 14 +++- .../Recompiler/RspProfiling.cpp | 81 ++++++++++++++----- .../Recompiler/RspProfiling.h | 9 +-- .../Recompiler/RspRecompilerCPU-x64.cpp | 38 ++++++--- .../Recompiler/RspRecompilerCPU-x64.h | 2 +- .../cpu/RSPiInstruction.cpp | 4 +- Source/Project64-rsp-core/cpu/RspLog.cpp | 2 +- .../Project64-rsp/Debugger/RSPDebuggerUI.cpp | 2 +- 8 files changed, 103 insertions(+), 49 deletions(-) diff --git a/Source/Project64-rsp-core/Hle/HleTask.cpp b/Source/Project64-rsp-core/Hle/HleTask.cpp index 0e71cb710..fd260d82d 100644 --- a/Source/Project64-rsp-core/Hle/HleTask.cpp +++ b/Source/Project64-rsp-core/Hle/HleTask.cpp @@ -1,4 +1,5 @@ #include +#include #include #include #include @@ -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 = *(JumpTable + ((FuncAddress & 0xFFF) >> 2)); + void * FuncPtr = m_Recompiler.CompileHLETask(FuncAddress); 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__); diff --git a/Source/Project64-rsp-core/Recompiler/RspProfiling.cpp b/Source/Project64-rsp-core/Recompiler/RspProfiling.cpp index 91d5cc2f5..f35dc24a5 100644 --- a/Source/Project64-rsp-core/Recompiler/RspProfiling.cpp +++ b/Source/Project64-rsp-core/Recompiler/RspProfiling.cpp @@ -5,9 +5,17 @@ #include #include #include +#include +#include #include +#include +#include #include +#include #include +#ifdef WIN32 +#include +#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(end_time - start_time).count(); + uint64_t elapsed_cycles = end_cycles - start_cycles; + return static_cast(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[count]->second / (double)TotalTime) * 100); + float CpuUsage = (float)(((double)ItemList[i]->second / (double)TotalTime) * 100); - if (CpuUsage <= 0.2) - { - continue; - } - sprintf(Buffer, "Function 0x%08X", ItemList[count]->first); + stdstr_f name("Function 0x%08X", ItemList[i]->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(); diff --git a/Source/Project64-rsp-core/Recompiler/RspProfiling.h b/Source/Project64-rsp-core/Recompiler/RspProfiling.h index b27913d14..b2d6d144a 100644 --- a/Source/Project64-rsp-core/Recompiler/RspProfiling.h +++ b/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 = -5, - Timer_RefreshScreen = -6, - Timer_UpdateScreen = -7, - Timer_UpdateFPS = -9, - Timer_Idel = -10, - Timer_FuncLookup = -11, - Timer_Done = -13, + Timer_RDP_Running = -3, }; void ResetTimerList(void); diff --git a/Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.cpp b/Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.cpp index 6c93f36e5..7b80598a5 100644 --- a/Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.cpp +++ b/Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.cpp @@ -3,6 +3,7 @@ #include "RspRecompilerCPU-x64.h" #include #include +#include #include #include #include @@ -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() { - m_Assembler->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, ...) diff --git a/Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.h b/Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.h index ad0369572..f9258b305 100644 --- a/Source/Project64-rsp-core/Recompiler/RspRecompilerCPU-x64.h +++ b/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: diff --git a/Source/Project64-rsp-core/cpu/RSPiInstruction.cpp b/Source/Project64-rsp-core/cpu/RSPiInstruction.cpp index a56eff361..29866ec99 100644 --- a/Source/Project64-rsp-core/cpu/RSPiInstruction.cpp +++ b/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)); - memcpy(m_Param, e.m_Param, sizeof(m_Param)); + m_Name[0] = '\0'; + m_Param[0] = '\0'; return *this; } diff --git a/Source/Project64-rsp-core/cpu/RspLog.cpp b/Source/Project64-rsp-core/cpu/RspLog.cpp index 666f85c68..ca1b590c2 100644 --- a/Source/Project64-rsp-core/cpu/RspLog.cpp +++ b/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) { diff --git a/Source/Project64-rsp/Debugger/RSPDebuggerUI.cpp b/Source/Project64-rsp/Debugger/RSPDebuggerUI.cpp index 4a7441789..3719522ee 100644 --- a/Source/Project64-rsp/Debugger/RSPDebuggerUI.cpp +++ b/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); } }