From 9499870cc993f39d8c25f5e434a4d25d9a24b556 Mon Sep 17 00:00:00 2001 From: Exzap <13877693+Exzap@users.noreply.github.com> Date: Sun, 25 Jun 2023 08:38:25 +0200 Subject: [PATCH] Debugging: Add minimalist PPC profiler --- src/Cafe/OS/RPL/rpl_symbol_storage.cpp | 14 ++ src/Cafe/OS/RPL/rpl_symbol_storage.h | 1 + src/Cafe/OS/libs/coreinit/coreinit_Thread.cpp | 10 +- src/Cafe/OS/libs/coreinit/coreinit_Thread.h | 3 + src/gui/components/wxProgressDialogManager.h | 118 ++++++++++++ .../DebugPPCThreadsWindow.cpp | 169 ++++++++++++++---- .../PPCThreadsViewer/DebugPPCThreadsWindow.h | 9 +- 7 files changed, 281 insertions(+), 43 deletions(-) create mode 100644 src/gui/components/wxProgressDialogManager.h diff --git a/src/Cafe/OS/RPL/rpl_symbol_storage.cpp b/src/Cafe/OS/RPL/rpl_symbol_storage.cpp index f4797c97..accb7d53 100644 --- a/src/Cafe/OS/RPL/rpl_symbol_storage.cpp +++ b/src/Cafe/OS/RPL/rpl_symbol_storage.cpp @@ -83,6 +83,20 @@ RPLStoredSymbol* rplSymbolStorage_getByAddress(MPTR address) return rplSymbolStorage.map_symbolByAddress[address]; } +RPLStoredSymbol* rplSymbolStorage_getByClosestAddress(MPTR address) +{ + // highly inefficient but doesn't matter for now + std::unique_lock lck(rplSymbolStorage.m_symbolStorageMutex); + for(uint32 i=0; i<4096; i++) + { + RPLStoredSymbol* symbol = rplSymbolStorage.map_symbolByAddress[address]; + if(symbol) + return symbol; + address -= 4; + } + return nullptr; +} + void rplSymbolStorage_remove(RPLStoredSymbol* storedSymbol) { std::unique_lock lck(rplSymbolStorage.m_symbolStorageMutex); diff --git a/src/Cafe/OS/RPL/rpl_symbol_storage.h b/src/Cafe/OS/RPL/rpl_symbol_storage.h index 0f179f59..d940186a 100644 --- a/src/Cafe/OS/RPL/rpl_symbol_storage.h +++ b/src/Cafe/OS/RPL/rpl_symbol_storage.h @@ -12,6 +12,7 @@ RPLStoredSymbol* rplSymbolStorage_store(const char* libName, const char* symbolN void rplSymbolStorage_remove(RPLStoredSymbol* storedSymbol); void rplSymbolStorage_removeRange(MPTR address, sint32 length); RPLStoredSymbol* rplSymbolStorage_getByAddress(MPTR address); +RPLStoredSymbol* rplSymbolStorage_getByClosestAddress(MPTR address); void rplSymbolStorage_createJumpProxySymbol(MPTR jumpAddress, MPTR destAddress); std::unordered_map& rplSymbolStorage_lockSymbolMap(); diff --git a/src/Cafe/OS/libs/coreinit/coreinit_Thread.cpp b/src/Cafe/OS/libs/coreinit/coreinit_Thread.cpp index 34a614bc..b97f896e 100644 --- a/src/Cafe/OS/libs/coreinit/coreinit_Thread.cpp +++ b/src/Cafe/OS/libs/coreinit/coreinit_Thread.cpp @@ -812,17 +812,21 @@ namespace coreinit return suspendCounter > 0; } + bool OSIsThreadRunningNoLock(OSThread_t* thread) + { + cemu_assert_debug(__OSHasSchedulerLock()); + return thread->state == OSThread_t::THREAD_STATE::STATE_RUNNING; + } + bool OSIsThreadRunning(OSThread_t* thread) { bool isRunning = false; __OSLockScheduler(); - if (thread->state == OSThread_t::THREAD_STATE::STATE_RUNNING) - isRunning = true; + isRunning = OSIsThreadRunningNoLock(thread); __OSUnlockScheduler(); return isRunning; } - void OSCancelThread(OSThread_t* thread) { __OSLockScheduler(); diff --git a/src/Cafe/OS/libs/coreinit/coreinit_Thread.h b/src/Cafe/OS/libs/coreinit/coreinit_Thread.h index a2fa2a80..7c1e618b 100644 --- a/src/Cafe/OS/libs/coreinit/coreinit_Thread.h +++ b/src/Cafe/OS/libs/coreinit/coreinit_Thread.h @@ -538,6 +538,7 @@ namespace coreinit bool OSIsThreadTerminated(OSThread_t* thread); bool OSIsThreadSuspended(OSThread_t* thread); + bool OSIsThreadRunningNoLock(OSThread_t* thread); bool OSIsThreadRunning(OSThread_t* thread); // OSThreadQueue @@ -603,6 +604,8 @@ namespace coreinit void __OSAddReadyThreadToRunQueue(OSThread_t* thread); bool __OSCoreShouldSwitchToThread(OSThread_t* currentThread, OSThread_t* newThread); void __OSQueueThreadDeallocation(OSThread_t* thread); + + bool __OSIsThreadActive(OSThread_t* thread); } #pragma pack() diff --git a/src/gui/components/wxProgressDialogManager.h b/src/gui/components/wxProgressDialogManager.h new file mode 100644 index 00000000..93b6c316 --- /dev/null +++ b/src/gui/components/wxProgressDialogManager.h @@ -0,0 +1,118 @@ +#pragma once + +#include +#include +#include +#include "util/helpers/Semaphore.h" + +wxDEFINE_EVENT(wxEVT_CREATE_PROGRESS_DIALOG, wxThreadEvent); +wxDEFINE_EVENT(wxEVT_DESTROY_PROGRESS_DIALOG, wxThreadEvent); +wxDEFINE_EVENT(wxEVT_UPDATE_PROGRESS_DIALOG, wxThreadEvent); + +// wrapper for wxGenericProgressDialog which can be used from any thread +class wxProgressDialogManager : public wxEvtHandler +{ +public: + wxProgressDialogManager(wxWindow* parent) : m_parent(parent), m_dialog(nullptr) + { + Bind(wxEVT_CREATE_PROGRESS_DIALOG, &wxProgressDialogManager::OnCreateProgressDialog, this); + Bind(wxEVT_DESTROY_PROGRESS_DIALOG, &wxProgressDialogManager::OnDestroyProgressDialog, this); + Bind(wxEVT_UPDATE_PROGRESS_DIALOG, &wxProgressDialogManager::OnUpdateProgressDialog, this); + } + + ~wxProgressDialogManager() + { + if (m_dialog) + Destroy(); + } + + void Create(const wxString& title, const wxString& message, int maximum, int style = wxPD_APP_MODAL | wxPD_ELAPSED_TIME | wxPD_REMAINING_TIME) + { + m_instanceSemaphore.increment(); + m_isCancelled = false; + m_isSkipped = false; + wxThreadEvent event(wxEVT_CREATE_PROGRESS_DIALOG); + event.SetString(title); + event.SetInt(maximum); + event.SetExtraLong(style); + wxQueueEvent(this, event.Clone()); + } + + void Destroy() + { + wxThreadEvent event(wxEVT_DESTROY_PROGRESS_DIALOG); + wxQueueEvent(this, event.Clone()); + m_instanceSemaphore.waitUntilZero(); // wait until destruction is complete + } + + // this also updates the cancel and skip state + void Update(int value, const wxString& newmsg = wxEmptyString) + { + wxThreadEvent event(wxEVT_UPDATE_PROGRESS_DIALOG); + event.SetInt(value); + event.SetString(newmsg); + wxQueueEvent(this, event.Clone()); + } + + bool IsCancelled() const + { + return m_isCancelled; + } + + bool IsSkipped() const + { + return m_isSkipped; + } + + bool IsCancelledOrSkipped() const + { + return m_isCancelled || m_isSkipped; + } + +private: + void OnCreateProgressDialog(wxThreadEvent& event) + { + if (m_dialog) + { + m_dialog->Destroy(); + m_instanceSemaphore.waitUntilZero(); + } + m_maximum = event.GetInt(); + m_dialog = new wxGenericProgressDialog(event.GetString(), "Please wait...", m_maximum, m_parent, event.GetExtraLong()); + } + + void OnDestroyProgressDialog(wxThreadEvent& event) + { + if (m_dialog) + { + m_dialog->Destroy(); + m_dialog = nullptr; + m_instanceSemaphore.decrement(); + } + } + + void OnUpdateProgressDialog(wxThreadEvent& event) + { + if (m_dialog) + { + // make sure that progress is never >= maximum + // because wxGenericProgressDialog seems to become crashy on destruction otherwise + int progress = event.GetInt(); + if(progress >= m_maximum) + progress = m_maximum - 1; + bool wasSkipped = false; + bool r = m_dialog->Update(progress, event.GetString(), &wasSkipped); + if(!r) + m_isCancelled = true; + if(wasSkipped) + m_isSkipped = true; + } + } + + wxWindow* m_parent; + wxGenericProgressDialog* m_dialog; + bool m_isCancelled{false}; + bool m_isSkipped{false}; + int m_maximum{0}; + CounterSemaphore m_instanceSemaphore; // used to synchronize destruction of the dialog +}; \ No newline at end of file diff --git a/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.cpp b/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.cpp index 0f3a8aec..1cbe1f8e 100644 --- a/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.cpp +++ b/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.cpp @@ -5,6 +5,8 @@ #include "Cafe/OS/RPL/rpl.h" #include "Cafe/OS/RPL/rpl_symbol_storage.h" +#include "gui/components/wxProgressDialogManager.h" + #include enum @@ -23,17 +25,18 @@ enum THREADLIST_MENU_SUSPEND, THREADLIST_MENU_RESUME, THREADLIST_MENU_DUMP_STACK_TRACE, + THREADLIST_MENU_PROFILE_THREAD, }; wxBEGIN_EVENT_TABLE(DebugPPCThreadsWindow, wxFrame) - EVT_BUTTON(CLOSE_ID,DebugPPCThreadsWindow::OnCloseButton) - EVT_BUTTON(REFRESH_ID,DebugPPCThreadsWindow::OnRefreshButton) - - EVT_CLOSE(DebugPPCThreadsWindow::OnClose) + EVT_BUTTON(CLOSE_ID, DebugPPCThreadsWindow::OnCloseButton) + EVT_BUTTON(REFRESH_ID, DebugPPCThreadsWindow::OnRefreshButton) + EVT_CLOSE(DebugPPCThreadsWindow::OnClose) wxEND_EVENT_TABLE() DebugPPCThreadsWindow::DebugPPCThreadsWindow(wxFrame& parent) - : wxFrame(&parent, wxID_ANY, _("PPC threads"), wxDefaultPosition, wxSize(930, 280), wxCLOSE_BOX | wxCLIP_CHILDREN | wxCAPTION | wxRESIZE_BORDER) + : wxFrame(&parent, wxID_ANY, _("PPC threads"), wxDefaultPosition, wxSize(930, 280), + wxCLOSE_BOX | wxCLIP_CHILDREN | wxCAPTION | wxRESIZE_BORDER) { wxFrame::SetBackgroundColour(*wxWHITE); @@ -158,7 +161,6 @@ void DebugPPCThreadsWindow::OnTimer(wxTimerEvent& event) RefreshThreadList(); } - #define _r(__idx) _swapEndianU32(cafeThread->context.gpr[__idx]) void DebugPPCThreadsWindow::RefreshThreadList() @@ -278,30 +280,126 @@ void DebugLogStackTrace(OSThread_t* thread, MPTR sp); void DebugPPCThreadsWindow::DumpStackTrace(OSThread_t* thread) { - cemuLog_log(LogType::Force, fmt::format("Dumping stack trace for thread {0:08x} LR: {1:08x}", memory_getVirtualOffsetFromPointer(thread), _swapEndianU32(thread->context.lr))); + cemuLog_log(LogType::Force, fmt::format("Dumping stack trace for thread {0:08x} LR: {1:08x}", + memory_getVirtualOffsetFromPointer(thread), + _swapEndianU32(thread->context.lr))); DebugLogStackTrace(thread, _swapEndianU32(thread->context.gpr[1])); } +void DebugPPCThreadsWindow::PresentProfileResults(OSThread_t* thread, const std::unordered_map& samples) +{ + std::vector> sortedSamples; + // count samples + uint32 totalSampleCount = 0; + for (auto& sample : samples) + totalSampleCount += sample.second; + cemuLog_log(LogType::Force, "--- Thread {:08x} profile results with {:} samples captured ---", + MEMPTR(thread).GetMPTR(), totalSampleCount); + cemuLog_log(LogType::Force, "Exclusive time, grouped by function:"); + // print samples grouped by function + sortedSamples.clear(); + for (auto& sample : samples) + { + RPLStoredSymbol* symbol = rplSymbolStorage_getByClosestAddress(sample.first); + VAddr sampleAddr = sample.first; + if (symbol) + sampleAddr = symbol->address; + auto it = std::find_if(sortedSamples.begin(), sortedSamples.end(), + [sampleAddr](const std::pair& a) { return a.first == sampleAddr; }); + if (it != sortedSamples.end()) + it->second += sample.second; + else + sortedSamples.push_back(std::make_pair(sampleAddr, sample.second)); + } + std::sort(sortedSamples.begin(), sortedSamples.end(), + [](const std::pair& a, const std::pair& b) { return a.second > b.second; }); + for (auto& sample : sortedSamples) + { + if (sample.second < 3) + continue; + VAddr sampleAddr = sample.first; + RPLStoredSymbol* symbol = rplSymbolStorage_getByClosestAddress(sample.first); + std::string strName; + if (symbol) + { + strName = fmt::format("{}.{}+0x{:x}", (const char*)symbol->libName, (const char*)symbol->symbolName, + sampleAddr - symbol->address); + } + else + strName = "Unknown"; + cemuLog_log(LogType::Force, "[{:08x}] {:8.2f}% (Samples: {:5}) Symbol: {}", sample.first, + (double)(sample.second * 100) / (double)totalSampleCount, sample.second, strName); + } +} + +void DebugPPCThreadsWindow::ProfileThreadWorker(OSThread_t* thread) +{ + wxProgressDialogManager progressDialog(this); + progressDialog.Create("Profiling thread", + _("Capturing samples..."), + 1000, // range + wxPD_CAN_SKIP); + + std::unordered_map samples; + // loop for one minute + uint64 startTime = std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count(); + uint32 totalSampleCount = 0; + while (true) + { + // suspend thread + coreinit::OSSuspendThread(thread); + // wait until thread is not running anymore + __OSLockScheduler(); + while (coreinit::OSIsThreadRunningNoLock(thread)) + { + __OSUnlockScheduler(); + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + __OSLockScheduler(); + } + uint32 sampleIP = thread->context.srr0; + __OSUnlockScheduler(); + coreinit::OSResumeThread(thread); + // count sample + samples[sampleIP]++; + totalSampleCount++; + if ((totalSampleCount % 50) == 0) + { + wxString msg = fmt::format("Capturing samples... ({:})\nResults will be written to log.txt\n", + totalSampleCount); + if (totalSampleCount < 30000) + msg.Append(_("Click Skip button for early results with lower accuracy")); + else + msg.Append(_("Click Skip button to finish")); + progressDialog.Update(totalSampleCount * 1000 / 30000, msg); + if (progressDialog.IsCancelledOrSkipped()) + break; + } + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } + PresentProfileResults(thread, samples); + progressDialog.Destroy(); +} + +void DebugPPCThreadsWindow::ProfileThread(OSThread_t* thread) +{ + std::thread profileThread(&DebugPPCThreadsWindow::ProfileThreadWorker, this, thread); + profileThread.detach(); +} + void DebugPPCThreadsWindow::OnThreadListPopupClick(wxCommandEvent& evt) { - MPTR threadMPTR = (MPTR)(size_t)static_cast(evt.GetEventObject())->GetClientData(); - // check if thread is still active - bool threadIsActive = false; - srwlock_activeThreadList.LockWrite(); - for (sint32 i = 0; i < activeThreadCount; i++) - { - MPTR threadItrMPTR = activeThread[i]; - if (threadItrMPTR == threadMPTR) - { - threadIsActive = true; - break; - } - } - srwlock_activeThreadList.UnlockWrite(); - if (threadIsActive == false) - return; - // handle command + MPTR threadMPTR = (MPTR)(size_t) static_cast(evt.GetEventObject())->GetClientData(); OSThread_t* osThread = (OSThread_t*)memory_getPointerFromVirtualOffset(threadMPTR); + __OSLockScheduler(); + if (!coreinit::__OSIsThreadActive(osThread)) + { + __OSUnlockScheduler(); + return; + } + __OSUnlockScheduler(); + // handle command switch (evt.GetId()) { case THREADLIST_MENU_BOOST_PRIO_5: @@ -325,6 +423,9 @@ void DebugPPCThreadsWindow::OnThreadListPopupClick(wxCommandEvent& evt) case THREADLIST_MENU_DUMP_STACK_TRACE: DumpStackTrace(osThread); break; + case THREADLIST_MENU_PROFILE_THREAD: + ProfileThread(osThread); + break; } coreinit::__OSUpdateThreadEffectivePriority(osThread); // update thread list @@ -341,26 +442,19 @@ void DebugPPCThreadsWindow::OnThreadListRightClick(wxMouseEvent& event) // select item m_thread_list->SetItemState(itemIndex, wxLIST_STATE_FOCUSED, wxLIST_STATE_FOCUSED); long sel = m_thread_list->GetNextItem(-1, wxLIST_NEXT_ALL, - wxLIST_STATE_SELECTED); + wxLIST_STATE_SELECTED); if (sel != -1) m_thread_list->SetItemState(sel, 0, wxLIST_STATE_SELECTED); m_thread_list->SetItemState(itemIndex, wxLIST_STATE_SELECTED, wxLIST_STATE_SELECTED); // check if thread is still on the list of active threads MPTR threadMPTR = (MPTR)m_thread_list->GetItemData(itemIndex); - bool threadIsActive = false; - srwlock_activeThreadList.LockWrite(); - for (sint32 i = 0; i < activeThreadCount; i++) + __OSLockScheduler(); + if (!coreinit::__OSIsThreadActive(MEMPTR(threadMPTR))) { - MPTR threadItrMPTR = activeThread[i]; - if (threadItrMPTR == threadMPTR) - { - threadIsActive = true; - break; - } - } - srwlock_activeThreadList.UnlockWrite(); - if (threadIsActive == false) + __OSUnlockScheduler(); return; + } + __OSUnlockScheduler(); // create menu entry wxMenu menu; menu.SetClientData((void*)(size_t)threadMPTR); @@ -374,6 +468,7 @@ void DebugPPCThreadsWindow::OnThreadListRightClick(wxMouseEvent& event) menu.Append(THREADLIST_MENU_SUSPEND, _("Suspend")); menu.AppendSeparator(); menu.Append(THREADLIST_MENU_DUMP_STACK_TRACE, _("Write stack trace to log")); + menu.Append(THREADLIST_MENU_PROFILE_THREAD, _("Profile thread")); menu.Connect(wxEVT_COMMAND_MENU_SELECTED, wxCommandEventHandler(DebugPPCThreadsWindow::OnThreadListPopupClick), nullptr, this); PopupMenu(&menu); } diff --git a/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.h b/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.h index e967ad7c..649780c5 100644 --- a/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.h +++ b/src/gui/windows/PPCThreadsViewer/DebugPPCThreadsWindow.h @@ -15,12 +15,15 @@ public: void OnThreadListPopupClick(wxCommandEvent &evt); void OnThreadListRightClick(wxMouseEvent& event); - void DumpStackTrace(struct OSThread_t* thread); - void Close(); private: - wxListCtrl* m_thread_list; + void ProfileThread(struct OSThread_t* thread); + void ProfileThreadWorker(OSThread_t* thread); + void PresentProfileResults(OSThread_t* thread, const std::unordered_map& samples); + void DumpStackTrace(struct OSThread_t* thread); + + wxListCtrl* m_thread_list; wxCheckBox* m_auto_refresh; wxTimer* m_timer;