diff --git a/Android/res/menu/game_activity.xml b/Android/res/menu/game_activity.xml index 9b7643bea..10b33377f 100644 --- a/Android/res/menu/game_activity.xml +++ b/Android/res/menu/game_activity.xml @@ -31,6 +31,14 @@ + + + + + + diff --git a/Android/res/values/strings.xml b/Android/res/values/strings.xml index d89f2dae7..628ac407d 100644 --- a/Android/res/values/strings.xml +++ b/Android/res/values/strings.xml @@ -19,6 +19,9 @@ Slot 9 Slot 10 Reset + Debugging Options + Reset Function Times + Dump Function Times Search @@ -167,6 +170,8 @@ Display lists per second Percentage of full speed Vertical interrupts per second + Record Execution Times + Record how long each block executes for Reset GFX Plugin Always reload GFX plugin Button scale diff --git a/Android/res/xml/settings_advanced.xml b/Android/res/xml/settings_advanced.xml index 62e5ead88..189024c8c 100644 --- a/Android/res/xml/settings_advanced.xml +++ b/Android/res/xml/settings_advanced.xml @@ -22,6 +22,10 @@ android:key="Debugger_CpuUsage" android:summary="@string/CpuUsage_summary" android:title="@string/CpuUsage_title" /> + LoadStringVal(Game_GameName).c_str(), Control + 1); CPath MempakPath(g_Settings->LoadStringVal(Directory_NativeSave).c_str(), stdstr_f("%s.mpk", MempakName.c_str()).c_str()); - if (g_Settings->LoadBool(Setting_UniqueSaveDir)) { MempakPath.AppendDirectory(g_Settings->LoadStringVal(Game_UniqueSaveDir).c_str()); diff --git a/Source/Project64-core/N64System/Mips/SystemEvents.cpp b/Source/Project64-core/N64System/Mips/SystemEvents.cpp index be32b8b9a..badc893bf 100644 --- a/Source/Project64-core/N64System/Mips/SystemEvents.cpp +++ b/Source/Project64-core/N64System/Mips/SystemEvents.cpp @@ -71,12 +71,12 @@ void CSystemEvents::ExecuteEvents() case SysEvent_ResetCPU_Hard: m_System->Reset(true, true); break; - case SysEvent_Profile_GenerateLogs: - m_System->m_Profile.GenerateLog(); - break; case SysEvent_Profile_StartStop: case SysEvent_Profile_ResetLogs: - m_System->m_Profile.ResetCounters(); + if (g_Recompiler) + { + g_Recompiler->ResetFunctionTimes(); + } break; case SysEvent_ExecuteInterrupt: g_Reg->DoIntrException(false); @@ -121,6 +121,12 @@ void CSystemEvents::ExecuteEvents() case SysEvent_ChangePlugins: ChangePluginFunc(); break; + case SysEvent_DumpFunctionTimes: + if (g_Recompiler) + { + g_Recompiler->DumpFunctionTimes(); + } + break; case SysEvent_ChangingFullScreen: g_Notify->ChangeFullScreen(); break; diff --git a/Source/Project64-core/N64System/Mips/SystemEvents.h b/Source/Project64-core/N64System/Mips/SystemEvents.h index d7f399b22..8fe969d91 100644 --- a/Source/Project64-core/N64System/Mips/SystemEvents.h +++ b/Source/Project64-core/N64System/Mips/SystemEvents.h @@ -51,7 +51,8 @@ enum SystemEvent SysEvent_Interrupt_DP, SysEvent_Profile_StartStop, SysEvent_Profile_ResetLogs, - SysEvent_Profile_GenerateLogs, + SysEvent_ResetFunctionTimes, + SysEvent_DumpFunctionTimes, }; class CN64System; diff --git a/Source/Project64-core/N64System/N64Class.cpp b/Source/Project64-core/N64System/N64Class.cpp index e179cc0f2..f96498938 100644 --- a/Source/Project64-core/N64System/N64Class.cpp +++ b/Source/Project64-core/N64System/N64Class.cpp @@ -95,7 +95,7 @@ CN64System::CN64System(CPlugins * Plugins, bool SavesReadOnly, bool SyncSystem) if (CpuType == CPU_Recompiler || CpuType == CPU_SyncCores) { - m_Recomp = new CRecompiler(m_Reg, m_Profile, m_EndEmulation); + m_Recomp = new CRecompiler(m_Reg, m_EndEmulation); } } WriteTrace(TraceN64System, TraceDebug, "Done"); @@ -149,7 +149,6 @@ void CN64System::ExternalEvent(SystemEvent action) switch (action) { - case SysEvent_Profile_GenerateLogs: case SysEvent_Profile_StartStop: case SysEvent_Profile_ResetLogs: case SysEvent_ExecuteInterrupt: @@ -169,6 +168,7 @@ void CN64System::ExternalEvent(SystemEvent action) case SysEvent_CloseCPU: case SysEvent_ChangePlugins: case SysEvent_PauseCPU_FromMenu: + case SysEvent_DumpFunctionTimes: QueueEvent(action); break; case SysEvent_PauseCPU_AppLostFocus: @@ -1892,9 +1892,11 @@ bool CN64System::LoadState(const char * FileName) WriteTrace(TraceN64System, TraceDebug, "5"); m_TLB.Reset(false); WriteTrace(TraceN64System, TraceDebug, "6"); - m_CPU_Usage.ResetCounters(); - WriteTrace(TraceN64System, TraceDebug, "7"); - m_Profile.ResetCounters(); + if (m_Recomp) + { + m_Recomp->ResetFunctionTimes(); + } + m_CPU_Usage.ResetTimers(); WriteTrace(TraceN64System, TraceDebug, "8"); m_FPS.Reset(true); WriteTrace(TraceN64System, TraceDebug, "9"); @@ -1943,7 +1945,7 @@ void CN64System::RunRSP() { if ((m_Reg.SP_STATUS_REG & SP_STATUS_BROKE) == 0) { - SPECIAL_TIMERS CPU_UsageAddr = Timer_None/*, ProfileAddr = Timer_None*/; + HighResTimeStamp StartTime; uint32_t Task = 0; if (m_RspBroke) @@ -1976,14 +1978,9 @@ void CN64System::RunRSP() { DisplayRSPListCount(); } - if (bShowCPUPer()) + if (bRecordExecutionTimes() || bShowCPUPer()) { - switch (Task) - { - case 1: CPU_UsageAddr = m_CPU_Usage.StartTimer(Timer_RSP_Dlist); break; - case 2: CPU_UsageAddr = m_CPU_Usage.StartTimer(Timer_RSP_Alist); break; - default: CPU_UsageAddr = m_CPU_Usage.StartTimer(Timer_RSP_Unknown); break; - } + StartTime.SetToNow(); } } @@ -2004,8 +2001,22 @@ void CN64System::RunRSP() g_SystemTimer->SetTimer(CSystemTimer::RSPTimerDlist, 0x1000, false); m_Reg.m_GfxIntrReg &= ~MI_INTR_DP; } - if (bShowCPUPer()) { m_CPU_Usage.StartTimer(CPU_UsageAddr); } - //if (bProfiling) { m_Profile.StartTimer(ProfileAddr); } + if (bRecordExecutionTimes() || bShowCPUPer()) + { + HighResTimeStamp EndTime; + EndTime.SetToNow(); + uint32_t TimeTaken = (uint32_t)(EndTime.GetMicroSeconds() - StartTime.GetMicroSeconds()); + + if (bShowCPUPer()) + { + switch (Task) + { + case 1: m_CPU_Usage.RecordTime(Timer_RSP_Dlist, TimeTaken); break; + case 2: m_CPU_Usage.RecordTime(Timer_RSP_Alist, TimeTaken); break; + default: m_CPU_Usage.RecordTime(Timer_RSP_Unknown, TimeTaken); break; + } + } + } if ((m_Reg.SP_STATUS_REG & SP_STATUS_HALT) == 0 && (m_Reg.SP_STATUS_REG & SP_STATUS_BROKE) == 0 && @@ -2031,9 +2042,11 @@ void CN64System::SyncToAudio() { return; } - SPECIAL_TIMERS CPU_UsageAddr = Timer_None; - - if (bShowCPUPer()) { CPU_UsageAddr = m_CPU_Usage.StartTimer(Timer_Idel); } + PROFILE_TIMERS PreviousTimer = Timer_None; + if (bShowCPUPer()) + { + PreviousTimer = m_CPU_Usage.StartTimer(Timer_Idel); + } for (int i = 0; i < 50; i++) { @@ -2046,13 +2059,13 @@ void CN64System::SyncToAudio() } if (bShowCPUPer()) { - m_CPU_Usage.StartTimer(CPU_UsageAddr != Timer_None ? CPU_UsageAddr : Timer_R4300); + m_CPU_Usage.StartTimer(PreviousTimer); } } void CN64System::RefreshScreen() { - SPECIAL_TIMERS CPU_UsageAddr = Timer_None/*, ProfilingAddr = Timer_None*/; + PROFILE_TIMERS CPU_UsageAddr = Timer_None/*, ProfilingAddr = Timer_None*/; uint32_t VI_INTR_TIME = 500000; if (bShowCPUPer()) { CPU_UsageAddr = m_CPU_Usage.StartTimer(Timer_RefreshScreen); } diff --git a/Source/Project64-core/N64System/N64Class.h b/Source/Project64-core/N64System/N64Class.h index b1b841c52..370f0ad5b 100644 --- a/Source/Project64-core/N64System/N64Class.h +++ b/Source/Project64-core/N64System/N64Class.h @@ -51,7 +51,6 @@ public: CN64System(CPlugins * Plugins, bool SavesReadOnly, bool SyncSystem); virtual ~CN64System(void); - CProfiling m_Profile; CCheats m_Cheats; bool m_EndEmulation; SAVE_CHIP_TYPE m_SaveUsing; diff --git a/Source/Project64-core/N64System/N64Types.h b/Source/Project64-core/N64System/N64Types.h index ed64221c7..f65c0e2ac 100644 --- a/Source/Project64-core/N64System/N64Types.h +++ b/Source/Project64-core/N64System/N64Types.h @@ -75,14 +75,18 @@ enum Country UnknownCountry = 0 }; -enum SPECIAL_TIMERS +enum PROFILE_TIMERS { - Timer_None = 0, Timer_R4300 = -1, Timer_RSP_Dlist = -2, - Timer_RSP_Alist = -3, Timer_RSP_Unknown = -5, Timer_RefreshScreen = -6, - Timer_UpdateScreen = -7, Timer_UpdateFPS = -9, Timer_Idel = -10, - Timer_FuncLookup = -11, Timer_Done = -13, Timer_GetBlockInfo = -14, - Timer_AnalyseBlock = -15, Timer_CompileBlock = -17, Timer_CompileDone = -18, - Timer_InheritParentInfo = -19, Timer_AddX86Code = -20, + Timer_None = 0, + Timer_R4300 = 1, + Timer_RSP_Dlist = 2, + Timer_RSP_Alist = 3, + Timer_RSP_Unknown = 4, + Timer_RefreshScreen = 5, + Timer_UpdateScreen = 6, + Timer_UpdateFPS = 7, + Timer_Idel = 8, + Timer_Max = 9, }; enum STEP_TYPE diff --git a/Source/Project64-core/N64System/ProfilingClass.cpp b/Source/Project64-core/N64System/ProfilingClass.cpp index f86f34487..365214558 100644 --- a/Source/Project64-core/N64System/ProfilingClass.cpp +++ b/Source/Project64-core/N64System/ProfilingClass.cpp @@ -17,197 +17,61 @@ enum { MAX_FRAMES = 13 }; CProfiling::CProfiling() : -m_CurrentTimerAddr(Timer_None), m_CurrentDisplayCount(MAX_FRAMES), -m_StartTimeHi(0), -m_StartTimeLo(0) +m_CurrentTimerType(Timer_None) { + memset(m_Timers, 0, sizeof(m_Timers)); } -SPECIAL_TIMERS CProfiling::StartTimer(SPECIAL_TIMERS Address) +void CProfiling::RecordTime(PROFILE_TIMERS timer, uint32_t TimeTaken) { - SPECIAL_TIMERS OldTimerAddr = StopTimer(); - m_CurrentTimerAddr = Address; - -#ifdef _M_IX86 - uint32_t HiValue, LoValue; - _asm - { - pushad; - rdtsc; - mov HiValue, edx; - mov LoValue, eax; - popad; - } - m_StartTimeHi = HiValue; - m_StartTimeLo = LoValue; -#elif !defined(_WIN32) - struct timespec now; - clock_gettime(CLOCK_MONOTONIC, &now); - m_StartTimeLo = (now.tv_sec * 1000) + (now.tv_nsec / 1000000); -#else - g_Notify->BreakPoint(__FILE__, __LINE__); -#endif - return OldTimerAddr; + m_Timers[timer] += TimeTaken; } -SPECIAL_TIMERS CProfiling::StopTimer() +PROFILE_TIMERS CProfiling::StartTimer(PROFILE_TIMERS TimerType) { - uint32_t HiValue, LoValue; + PROFILE_TIMERS PreviousType = StopTimer(); + m_CurrentTimerType = TimerType; + m_StartTime.SetToNow(); + return PreviousType; +} - if (m_CurrentTimerAddr == Timer_None) { return m_CurrentTimerAddr; } +PROFILE_TIMERS CProfiling::StopTimer() +{ + if (m_CurrentTimerType == Timer_None) { return m_CurrentTimerType; } + HighResTimeStamp EndTime; + EndTime.SetToNow(); + uint64_t TimeTaken = EndTime.GetMicroSeconds() - m_StartTime.GetMicroSeconds(); + m_Timers[m_CurrentTimerType] += TimeTaken; -#ifdef _M_IX86 - _asm { - pushad; - rdtsc; - mov HiValue, edx; - mov LoValue, eax; - popad; - } -#elif !defined(_WIN32) - struct timespec now; - clock_gettime(CLOCK_MONOTONIC, &now); - LoValue = (now.tv_sec * 1000) + (now.tv_nsec / 1000000); -#else - g_Notify->BreakPoint(__FILE__, __LINE__); -#endif - - 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; - - PROFILE_ENRTY Entry = m_Entries.find(m_CurrentTimerAddr); - if (Entry != m_Entries.end()) { - Entry->second += TimeTaken; - } - else { - m_Entries.insert(PROFILE_ENRTIES::value_type(m_CurrentTimerAddr, TimeTaken)); - } - - SPECIAL_TIMERS OldTimerAddr = m_CurrentTimerAddr; - m_CurrentTimerAddr = Timer_None; - return OldTimerAddr; + PROFILE_TIMERS CurrentTimerType = m_CurrentTimerType; + m_CurrentTimerType = Timer_None; + return CurrentTimerType; } void CProfiling::ShowCPU_Usage() { - int64_t TotalTime, CPU = 0, Alist = 0, Dlist = 0, Idle = 0; - PROFILE_ENRTY Entry; + uint64_t TotalTime = m_Timers[Timer_R4300] + m_Timers[Timer_RSP_Dlist] + m_Timers[Timer_RSP_Alist] + m_Timers[Timer_Idel]; - if (m_CurrentDisplayCount > 0) { m_CurrentDisplayCount -= 1; return; } - m_CurrentDisplayCount = MAX_FRAMES; - - Entry = m_Entries.find(Timer_R4300); - if (Entry != m_Entries.end()) { CPU = Entry->second; } - - Entry = m_Entries.find(Timer_RefreshScreen); - if (Entry != m_Entries.end()) { CPU += Entry->second; } - - Entry = m_Entries.find(Timer_RSP_Dlist); - if (Entry != m_Entries.end()) { Dlist = Entry->second; } - - Entry = m_Entries.find(Timer_UpdateScreen); - if (Entry != m_Entries.end()) { Dlist += Entry->second; } - - Entry = m_Entries.find(Timer_RSP_Alist); - if (Entry != m_Entries.end()) { Alist = Entry->second; } - - Entry = m_Entries.find(Timer_Idel); - if (Entry != m_Entries.end()) { Idle = Entry->second; } - - TotalTime = CPU + Alist + Dlist + Idle; - - g_Notify->DisplayMessage(0, stdstr_f("r4300i: %0.1f%c GFX: %0.1f%c Alist: %0.1f%c Idle: %0.1f%c", - (float)(((double)CPU / (double)TotalTime) * 100), '%', - (float)(((double)Dlist / (double)TotalTime) * 100), '%', - (float)(((double)Alist / (double)TotalTime) * 100), '%', - (float)(((double)Idle / (double)TotalTime) * 100), '%').c_str()); - - ResetCounters(); -} - -void CProfiling::ResetCounters() -{ - m_Entries.clear(); -} - -struct TIMER_NAME -{ - SPECIAL_TIMERS Timer; - const char * Name; -}; - -void CProfiling::GenerateLog() -{ - stdstr LogFileName; + if (m_CurrentDisplayCount > 0) { - CLog Log; - Log.Open("Profiling.txt"); - LogFileName = Log.FileName(); - - //Get the total time - int64_t TotalTime = 0; - for (PROFILE_ENRTY itemTime = m_Entries.begin(); itemTime != m_Entries.end(); itemTime++) - { - TotalTime += itemTime->second; - } - - //Create a sortable list of items - std::vector ItemList; - for (PROFILE_ENRTY Entry = m_Entries.begin(); Entry != m_Entries.end(); Entry++) - { - ItemList.push_back(&(*Entry)); - } - - //sort the list with a basic bubble sort - for (size_t OuterPass = 0; OuterPass < (ItemList.size() - 1); OuterPass++) - { - for (size_t InnerPass = 0; InnerPass < (ItemList.size() - 1); InnerPass++) - { - if (ItemList[InnerPass]->second < ItemList[InnerPass + 1]->second) - { - PROFILE_VALUE * TempPtr = ItemList[InnerPass]; - ItemList[InnerPass] = ItemList[InnerPass + 1]; - ItemList[InnerPass + 1] = TempPtr; - } - } - } - - TIMER_NAME TimerNames[] = - { - { Timer_R4300, "R4300" }, - { Timer_RSP_Dlist, "RSP: Dlist" }, - { Timer_RSP_Alist, "RSP: Alist" }, - { Timer_RSP_Unknown, "RSP: Unknown" }, - { Timer_RefreshScreen, "Refresh Screen" }, - { Timer_UpdateScreen, "Update Screen" }, - { Timer_UpdateFPS, "Update FPS" }, - { Timer_FuncLookup, "Function Lookup" }, - { Timer_Done, "Timer_Done" }, - { Timer_GetBlockInfo, "Timer_GetBlockInfo" }, - { Timer_AnalyseBlock, "Timer_AnalyseBlock" }, - { Timer_CompileBlock, "Timer_CompileBlock" }, - { Timer_CompileDone, "Timer_CompileDone" }, - }; - - for (size_t count = 0; count < ItemList.size(); count++) - { - char Buffer[255]; - double CpuUsage = ((double)ItemList[count]->second / (double)TotalTime) * 100; - if (CpuUsage <= 0.2) { continue; } - sprintf(Buffer, "Func 0x%08X", ItemList[count]->first); - for (int NameID = 0; NameID < (sizeof(TimerNames) / sizeof(TIMER_NAME)); NameID++) - { - if (ItemList[count]->first == TimerNames[NameID].Timer) - { - strcpy(Buffer, TimerNames[NameID].Name); - break; - } - } - Log.LogF("%s\t%2.2f", Buffer, CpuUsage); - } + m_CurrentDisplayCount -= 1; + return; } - ResetCounters(); + uint32_t R4300 = (uint32_t)(m_Timers[Timer_R4300] * 10000 / TotalTime); + uint32_t RSP_Dlist = (uint32_t)(m_Timers[Timer_RSP_Dlist] * 10000 / TotalTime); + uint32_t RSP_Alist = (uint32_t)(m_Timers[Timer_RSP_Alist] * 10000 / TotalTime); + uint32_t Idel = (uint32_t)(m_Timers[Timer_Idel] * 10000 / TotalTime); + + m_CurrentDisplayCount = MAX_FRAMES; + g_Notify->DisplayMessage(0, stdstr_f("r4300i: %d.%02d%% GFX: %d.%02d%% Alist: %d.%02d%% Idle: %d.%02d%%", + R4300 / 100, R4300 % 100,RSP_Dlist / 100, RSP_Dlist % 100,RSP_Alist / 100, RSP_Alist % 100,Idel / 100, Idel % 100).c_str()); + + ResetTimers(); +} + +void CProfiling::ResetTimers() +{ + memset(m_Timers, 0, sizeof(m_Timers)); } \ No newline at end of file diff --git a/Source/Project64-core/N64System/ProfilingClass.h b/Source/Project64-core/N64System/ProfilingClass.h index 29799180d..e1ffa76dc 100644 --- a/Source/Project64-core/N64System/ProfilingClass.h +++ b/Source/Project64-core/N64System/ProfilingClass.h @@ -10,35 +10,31 @@ ****************************************************************************/ #pragma once #include - -typedef std::map PROFILE_ENRTIES; -typedef PROFILE_ENRTIES::iterator PROFILE_ENRTY; -typedef PROFILE_ENRTIES::value_type PROFILE_VALUE; +#include class CProfiling { public: CProfiling(); + void RecordTime(PROFILE_TIMERS timer, uint32_t time); + uint64_t TimerTime(PROFILE_TIMERS timer); + //recording timing against current timer, returns the address of the timer stopped - SPECIAL_TIMERS StartTimer(SPECIAL_TIMERS Address); - SPECIAL_TIMERS StopTimer(); + PROFILE_TIMERS StartTimer(PROFILE_TIMERS TimerType); + PROFILE_TIMERS StopTimer(); //Display the CPU Usage void ShowCPU_Usage(); - //Reset all the counters back to 0 - void ResetCounters(); - - //Generate a log file with the current results, this will also reset the counters - void GenerateLog(); + void ResetTimers(void); private: CProfiling(const CProfiling&); // Disable copy constructor CProfiling& operator=(const CProfiling&); // Disable assignment - SPECIAL_TIMERS m_CurrentTimerAddr; uint32_t m_CurrentDisplayCount; - uint32_t m_StartTimeHi, m_StartTimeLo; //The Current Timer start time - PROFILE_ENRTIES m_Entries; + PROFILE_TIMERS m_CurrentTimerType; + HighResTimeStamp m_StartTime; + uint64_t m_Timers[Timer_Max]; }; diff --git a/Source/Project64-core/N64System/Recompiler/FunctionMapClass.h b/Source/Project64-core/N64System/Recompiler/FunctionMapClass.h index 97c180fb1..531031f83 100644 --- a/Source/Project64-core/N64System/Recompiler/FunctionMapClass.h +++ b/Source/Project64-core/N64System/Recompiler/FunctionMapClass.h @@ -10,7 +10,6 @@ ****************************************************************************/ #pragma once #include -#include class CFunctionMap : private CGameSettings diff --git a/Source/Project64-core/N64System/Recompiler/RecompilerClass.cpp b/Source/Project64-core/N64System/Recompiler/RecompilerClass.cpp index 711cfbb2c..de1766f23 100644 --- a/Source/Project64-core/N64System/Recompiler/RecompilerClass.cpp +++ b/Source/Project64-core/N64System/Recompiler/RecompilerClass.cpp @@ -16,11 +16,10 @@ #include #include -CRecompiler::CRecompiler(CRegisters & Registers, CProfiling & Profile, bool & EndEmulation) : - m_Registers(Registers), - m_Profile(Profile), - m_EndEmulation(EndEmulation), - PROGRAM_COUNTER(Registers.m_PROGRAM_COUNTER) +CRecompiler::CRecompiler(CRegisters & Registers, bool & EndEmulation) : +m_Registers(Registers), +m_EndEmulation(EndEmulation), +PROGRAM_COUNTER(Registers.m_PROGRAM_COUNTER) { CFunctionMap::AllocateMemory(); if (g_MMU != NULL) @@ -695,7 +694,29 @@ void CRecompiler::RecompilerMain_Lookup_validate_TLB() continue; } } - (info->Function())(); + + if (bRecordExecutionTimes()) + { + HighResTimeStamp StartTime, EndTime; + StartTime.SetToNow(); + (info->Function())(); + EndTime.SetToNow(); + uint64_t TimeTaken = EndTime.GetMicroSeconds() - StartTime.GetMicroSeconds(); + FUNCTION_PROFILE::iterator itr = m_BlockProfile.find(info->Function()); + if (itr == m_BlockProfile.end()) + { + FUNCTION_PROFILE_DATA data = { 0 }; + data.Address = info->EnterPC(); + std::pair res = m_BlockProfile.insert(FUNCTION_PROFILE::value_type(info->Function(), data)); + itr = res.first; + } + WriteTrace(TraceN64System, TraceNotice, "EndTime: %X StartTime: %X TimeTaken: %X", (uint32_t)EndTime.GetMicroSeconds(), (uint32_t)StartTime.GetMicroSeconds(), (uint32_t)TimeTaken); + itr->second.TimeTaken += TimeTaken; + } + else + { + (info->Function())(); + } } else { @@ -1108,4 +1129,22 @@ void CRecompiler::ResetMemoryStackPos() WriteTrace(TraceRecompiler, TraceError, "Failed to translate SP address (%s)", m_Registers.m_GPR[29].UW[0]); g_Notify->BreakPoint(__FILE__, __LINE__); } -} \ No newline at end of file +} + +void CRecompiler::DumpFunctionTimes() +{ + CPath LogFileName(g_Settings->LoadStringVal(Directory_Log).c_str(), "FunctionTimes.csv"); + + CLog Log; + Log.Open(LogFileName); + + for (FUNCTION_PROFILE::iterator itr = m_BlockProfile.begin(); itr != m_BlockProfile.end(); itr++) + { + Log.LogF("%X,0x%X,%d\r\n", (uint32_t)itr->first, itr->second.Address, (uint32_t)itr->second.TimeTaken); + } +} + +void CRecompiler::ResetFunctionTimes() +{ + m_BlockProfile.clear(); +} diff --git a/Source/Project64-core/N64System/Recompiler/RecompilerClass.h b/Source/Project64-core/N64System/Recompiler/RecompilerClass.h index 8abe1fd27..627a981e4 100644 --- a/Source/Project64-core/N64System/Recompiler/RecompilerClass.h +++ b/Source/Project64-core/N64System/Recompiler/RecompilerClass.h @@ -40,7 +40,7 @@ public: typedef void(*DelayFunc)(); public: - CRecompiler(CRegisters & Registers, CProfiling & Profile, bool & EndEmulation); + CRecompiler(CRegisters & Registers, bool & EndEmulation); ~CRecompiler(); void Run(); @@ -52,6 +52,8 @@ public: void ClearRecompCode_Phys(uint32_t PhysicalAddress, int32_t length, REMOVE_REASON Reason); void ResetMemoryStackPos(); + void ResetFunctionTimes(); + void DumpFunctionTimes(); uint32_t& MemoryStackPos() { return m_MemoryStack; } @@ -62,6 +64,14 @@ private: CCompiledFunc * CompileCode(); + typedef struct + { + uint32_t Address; + uint64_t TimeTaken; + } FUNCTION_PROFILE_DATA; + + typedef std::map FUNCTION_PROFILE; + // Main loops for the different look up methods void RecompilerMain_VirtualTable(); void RecompilerMain_VirtualTable_validate(); @@ -73,9 +83,9 @@ private: CCompiledFuncList m_Functions; CRegisters & m_Registers; - CProfiling & m_Profile; bool & m_EndEmulation; uint32_t m_MemoryStack; + FUNCTION_PROFILE m_BlockProfile; //Quick access to registers uint32_t & PROGRAM_COUNTER; diff --git a/Source/Project64-core/Settings/DebugSettings.cpp b/Source/Project64-core/Settings/DebugSettings.cpp index 7112c9055..a023c8091 100644 --- a/Source/Project64-core/Settings/DebugSettings.cpp +++ b/Source/Project64-core/Settings/DebugSettings.cpp @@ -18,6 +18,7 @@ bool CDebugSettings::m_bLogX86Code = false; bool CDebugSettings::m_bShowTLBMisses = false; bool CDebugSettings::m_bShowDivByZero = false; bool CDebugSettings::m_Registered = false; +bool CDebugSettings::m_RecordExecutionTimes = false; CDebugSettings::CDebugSettings() { @@ -29,6 +30,7 @@ CDebugSettings::CDebugSettings() g_Settings->RegisterChangeCB(Debugger_GenerateLogFiles, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); g_Settings->RegisterChangeCB(Debugger_ShowTLBMisses, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); g_Settings->RegisterChangeCB(Debugger_ShowDivByZero, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); + g_Settings->RegisterChangeCB(Debugger_RecordExecutionTimes, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); RefreshSettings(); } @@ -43,6 +45,7 @@ CDebugSettings::~CDebugSettings() g_Settings->UnregisterChangeCB(Debugger_GenerateLogFiles, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); g_Settings->UnregisterChangeCB(Debugger_ShowTLBMisses, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); g_Settings->UnregisterChangeCB(Debugger_ShowDivByZero, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); + g_Settings->UnregisterChangeCB(Debugger_RecordExecutionTimes, this, (CSettings::SettingChangedFunc)StaticRefreshSettings); } } @@ -52,4 +55,5 @@ void CDebugSettings::RefreshSettings() m_bLogX86Code = m_bHaveDebugger && g_Settings->LoadBool(Debugger_GenerateLogFiles); m_bShowTLBMisses = m_bHaveDebugger && g_Settings->LoadBool(Debugger_ShowTLBMisses); m_bShowDivByZero = m_bHaveDebugger && g_Settings->LoadBool(Debugger_ShowDivByZero); + m_RecordExecutionTimes = g_Settings->LoadBool(Debugger_RecordExecutionTimes); } \ No newline at end of file diff --git a/Source/Project64-core/Settings/DebugSettings.h b/Source/Project64-core/Settings/DebugSettings.h index ee3a7eef6..c7d74770f 100644 --- a/Source/Project64-core/Settings/DebugSettings.h +++ b/Source/Project64-core/Settings/DebugSettings.h @@ -22,6 +22,7 @@ public: static inline bool bLogX86Code(void) { return m_bLogX86Code; } static inline bool bShowTLBMisses(void) { return m_bShowTLBMisses; } static inline bool bShowDivByZero(void) { return m_bShowDivByZero; } + static inline bool bRecordExecutionTimes(void) { return m_RecordExecutionTimes; } private: static void StaticRefreshSettings(CDebugSettings * _this) @@ -36,6 +37,7 @@ private: static bool m_bLogX86Code; static bool m_bShowTLBMisses; static bool m_bShowDivByZero; + static bool m_RecordExecutionTimes; static int32_t m_RefCount; static bool m_Registered; diff --git a/Source/Project64-core/Settings/Settings.h b/Source/Project64-core/Settings/Settings.h index 502b0f606..5c2e509e2 100644 --- a/Source/Project64-core/Settings/Settings.h +++ b/Source/Project64-core/Settings/Settings.h @@ -221,6 +221,7 @@ enum SettingID Debugger_ShowDListAListCount, Debugger_ShowRecompMemSize, Debugger_DebugLanguage, + Debugger_RecordExecutionTimes, //Trace Debugger_TraceMD5, diff --git a/Source/Project64-core/Settings/SettingsClass.cpp b/Source/Project64-core/Settings/SettingsClass.cpp index 33302664b..5dda2ec97 100644 --- a/Source/Project64-core/Settings/SettingsClass.cpp +++ b/Source/Project64-core/Settings/SettingsClass.cpp @@ -309,6 +309,7 @@ void CSettings::AddHowToHandleSetting(const char * BaseDirectory) AddHandler(Debugger_DisableGameFixes, new CSettingTypeApplication("Debugger", "Disable Game Fixes", false)); AddHandler(Debugger_ShowDListAListCount, new CSettingTypeApplication("Debugger", "Show Dlist Alist Count", false)); AddHandler(Debugger_ShowRecompMemSize, new CSettingTypeApplication("Debugger", "Show Recompiler Memory size", false)); + AddHandler(Debugger_RecordExecutionTimes, new CSettingTypeApplication("Debugger", "Record Execution Times", false)); AddHandler(Debugger_DebugLanguage, new CSettingTypeApplication("Debugger", "Debug Language", false)); AddHandler(Debugger_ShowDivByZero, new CSettingTypeApplication("Debugger", "Show Div by zero", false)); AddHandler(Debugger_ProfileCode, new CSettingTypeApplication("Debugger", "Profile Code", (uint32_t)false)); diff --git a/Source/Project64/Project64.vcxproj.filters b/Source/Project64/Project64.vcxproj.filters index 74c85c08d..67dabf236 100644 --- a/Source/Project64/Project64.vcxproj.filters +++ b/Source/Project64/Project64.vcxproj.filters @@ -162,6 +162,12 @@ Source Files\Settings Files + + Source Files\User Interface Source + + + Source Files\User Interface Source + @@ -293,6 +299,12 @@ Header Files\Settings + + Header Files\User Interface Headers + + + Header Files\User Interface Headers + diff --git a/Source/Project64/UserInterface/MainMenuClass.cpp b/Source/Project64/UserInterface/MainMenuClass.cpp index 8339b52a5..a1ed50037 100644 --- a/Source/Project64/UserInterface/MainMenuClass.cpp +++ b/Source/Project64/UserInterface/MainMenuClass.cpp @@ -483,7 +483,7 @@ bool CMainMenu::ProcessMessage(HWND hWnd, DWORD /*FromAccelerator*/, DWORD MenuI g_BaseSystem->ExternalEvent(SysEvent_Profile_StartStop); break; case ID_PROFILE_RESETCOUNTER: g_BaseSystem->ExternalEvent(SysEvent_Profile_ResetLogs); break; - case ID_PROFILE_GENERATELOG: g_BaseSystem->ExternalEvent(SysEvent_Profile_GenerateLogs); break; + case ID_PROFILE_GENERATELOG: g_BaseSystem->ExternalEvent(SysEvent_DumpFunctionTimes); break; case ID_DEBUG_SHOW_TLB_MISSES: g_Settings->SaveBool(Debugger_ShowTLBMisses, !g_Settings->LoadBool(Debugger_ShowTLBMisses)); break;