From 04df3928667d40f17fca9d15f97858ec2e4259b0 Mon Sep 17 00:00:00 2001 From: Megamouse Date: Fri, 11 Mar 2022 21:08:44 +0100 Subject: [PATCH] Log cpu usage periodically --- rpcs3/Emu/CMakeLists.txt | 1 + .../Emu/RSX/Overlays/overlay_perf_metrics.cpp | 2 +- rpcs3/Emu/System.cpp | 7 + rpcs3/Emu/perf_monitor.cpp | 50 ++++ rpcs3/Emu/perf_monitor.hpp | 11 + rpcs3/Emu/system_progress.cpp | 6 +- rpcs3/display_sleep_control.cpp | 6 +- rpcs3/emucore.vcxproj | 2 + rpcs3/emucore.vcxproj.filters | 6 + rpcs3/util/cpu_stats.cpp | 230 +++++++++++++++++- rpcs3/util/cpu_stats.hpp | 27 +- 11 files changed, 338 insertions(+), 10 deletions(-) create mode 100644 rpcs3/Emu/perf_monitor.cpp create mode 100644 rpcs3/Emu/perf_monitor.hpp diff --git a/rpcs3/Emu/CMakeLists.txt b/rpcs3/Emu/CMakeLists.txt index 1a27efa1f9..c4a99bfb04 100644 --- a/rpcs3/Emu/CMakeLists.txt +++ b/rpcs3/Emu/CMakeLists.txt @@ -12,6 +12,7 @@ add_library(rpcs3_emu GDB.cpp title.cpp perf_meter.cpp + perf_monitor.cpp ) # prevent WolfSSL from warning about not having harden options diff --git a/rpcs3/Emu/RSX/Overlays/overlay_perf_metrics.cpp b/rpcs3/Emu/RSX/Overlays/overlay_perf_metrics.cpp index b9551b3e71..e94bd64c84 100644 --- a/rpcs3/Emu/RSX/Overlays/overlay_perf_metrics.cpp +++ b/rpcs3/Emu/RSX/Overlays/overlay_perf_metrics.cpp @@ -474,7 +474,7 @@ namespace rsx m_rsx_load = rsx_thread.get_load(); - m_total_threads = utils::cpu_stats::get_thread_count(); + m_total_threads = utils::cpu_stats::get_current_thread_count(); [[fallthrough]]; } diff --git a/rpcs3/Emu/System.cpp b/rpcs3/Emu/System.cpp index 957f946a12..b595a3e322 100644 --- a/rpcs3/Emu/System.cpp +++ b/rpcs3/Emu/System.cpp @@ -6,6 +6,7 @@ #include "Emu/system_progress.hpp" #include "Emu/system_utils.hpp" #include "Emu/perf_meter.hpp" +#include "Emu/perf_monitor.hpp" #include "Emu/vfs_config.h" #include "Emu/Cell/ErrorCodes.h" @@ -463,6 +464,9 @@ bool Emulator::BootRsxCapture(const std::string& path) // Initialize progress dialog g_fxo->init>(); + // Initialize performance monitor + g_fxo->init>(); + // PS3 'executable' m_state = system_state::ready; GetCallbacks().on_ready(); @@ -1115,6 +1119,9 @@ game_boot_result Emulator::Load(const std::string& title_id, bool add_only, bool // Initialize progress dialog g_fxo->init>(); + // Initialize performance monitor + g_fxo->init>(); + // Set title to actual disc title if necessary const std::string disc_sfo_dir = vfs::get("/dev_bdvd/PS3_GAME/PARAM.SFO"); diff --git a/rpcs3/Emu/perf_monitor.cpp b/rpcs3/Emu/perf_monitor.cpp new file mode 100644 index 0000000000..873c531fee --- /dev/null +++ b/rpcs3/Emu/perf_monitor.cpp @@ -0,0 +1,50 @@ +#include "stdafx.h" +#include "perf_monitor.hpp" +#include "util/cpu_stats.hpp" +#include "Utilities/Thread.h" + +LOG_CHANNEL(sys_log, "SYS"); + +void perf_monitor::operator()() +{ + constexpr u64 update_interval_us = 1000000; // Update every second + constexpr u64 log_interval_us = 10000000; // Log every 10 seconds + u64 elapsed_us = 0; + + utils::cpu_stats stats; + stats.init_cpu_query(); + + while (thread_ctrl::state() != thread_state::aborting) + { + thread_ctrl::wait_for(update_interval_us); + elapsed_us += update_interval_us; + + double total_usage = 0.0; + std::vector per_core_usage; + + stats.get_per_core_usage(per_core_usage, total_usage); + + if (elapsed_us >= log_interval_us) + { + elapsed_us = 0; + + std::string msg = fmt::format("CPU Usage: Total: %.1f%%", total_usage); + + if (!per_core_usage.empty()) + { + fmt::append(msg, ", Cores:"); + } + + for (size_t i = 0; i < per_core_usage.size(); i++) + { + fmt::append(msg, "%s %.1f%%", i > 0 ? "," : "", per_core_usage[i]); + } + + sys_log.notice("%s", msg); + } + } +} + +perf_monitor::~perf_monitor() +{ +} diff --git a/rpcs3/Emu/perf_monitor.hpp b/rpcs3/Emu/perf_monitor.hpp new file mode 100644 index 0000000000..634e891c83 --- /dev/null +++ b/rpcs3/Emu/perf_monitor.hpp @@ -0,0 +1,11 @@ +#pragma once + +#include "util/types.hpp" + +struct perf_monitor +{ + void operator()(); + ~perf_monitor(); + + static constexpr auto thread_name = "Performance Sensor"sv; +}; diff --git a/rpcs3/Emu/system_progress.cpp b/rpcs3/Emu/system_progress.cpp index 2165f56a89..8fb0e79e0a 100644 --- a/rpcs3/Emu/system_progress.cpp +++ b/rpcs3/Emu/system_progress.cpp @@ -46,7 +46,7 @@ void progress_dialog_server::operator()() break; } - std::this_thread::sleep_for(5ms); + thread_ctrl::wait_for(5000); text0 = +g_progr; } @@ -138,7 +138,7 @@ void progress_dialog_server::operator()() if (skip_this_one) { // Do nothing - std::this_thread::sleep_for(10ms); + thread_ctrl::wait_for(10000); continue; } @@ -173,7 +173,7 @@ void progress_dialog_server::operator()() } } - std::this_thread::sleep_for(10ms); + thread_ctrl::wait_for(10000); } if (g_system_progress_stopping || thread_ctrl::state() == thread_state::aborting) diff --git a/rpcs3/display_sleep_control.cpp b/rpcs3/display_sleep_control.cpp index 1f69b4763e..8e51abb79f 100644 --- a/rpcs3/display_sleep_control.cpp +++ b/rpcs3/display_sleep_control.cpp @@ -22,7 +22,7 @@ bool display_sleep_control_supported() #if defined(_WIN32) || defined(__APPLE__) return true; #elif defined(HAVE_QTDBUS) - for (const QString& service : { "org.freedesktop.ScreenSaver", "org.mate.ScreenSaver" }) + for (const char* service : { "org.freedesktop.ScreenSaver", "org.mate.ScreenSaver" }) { QDBusInterface interface(service, "/ScreenSaver", service, QDBusConnection::sessionBus()); if (interface.isValid()) @@ -54,7 +54,7 @@ void enable_display_sleep() #elif defined(HAVE_QTDBUS) if (s_dbus_cookie != 0) { - for (const QString& service : { "org.freedesktop.ScreenSaver", "org.mate.ScreenSaver" }) + for (const char* service : { "org.freedesktop.ScreenSaver", "org.mate.ScreenSaver" }) { QDBusInterface interface(service, "/ScreenSaver", service, QDBusConnection::sessionBus()); if (interface.isValid()) @@ -80,7 +80,7 @@ void disable_display_sleep() #elif defined(__APPLE__) IOPMAssertionCreateWithName(kIOPMAssertionTypePreventUserIdleDisplaySleep, kIOPMAssertionLevelOn, CFSTR("Game running"), &s_pm_assertion); #elif defined(HAVE_QTDBUS) - for (const QString& service : { "org.freedesktop.ScreenSaver", "org.mate.ScreenSaver" }) + for (const char* service : { "org.freedesktop.ScreenSaver", "org.mate.ScreenSaver" }) { QDBusInterface interface(service, "/ScreenSaver", service, QDBusConnection::sessionBus()); if (interface.isValid()) diff --git a/rpcs3/emucore.vcxproj b/rpcs3/emucore.vcxproj index 642fb0c86a..07333f9e76 100644 --- a/rpcs3/emucore.vcxproj +++ b/rpcs3/emucore.vcxproj @@ -72,6 +72,7 @@ + @@ -476,6 +477,7 @@ + diff --git a/rpcs3/emucore.vcxproj.filters b/rpcs3/emucore.vcxproj.filters index fcc2bf9c7e..2a9cd319ed 100644 --- a/rpcs3/emucore.vcxproj.filters +++ b/rpcs3/emucore.vcxproj.filters @@ -1030,6 +1030,9 @@ Emu\GPU\RSX\Overlays + + Emu + @@ -2056,6 +2059,9 @@ Emu\GPU\RSX\Common + + Emu + diff --git a/rpcs3/util/cpu_stats.cpp b/rpcs3/util/cpu_stats.cpp index fdfb8f999f..d592695cc0 100644 --- a/rpcs3/util/cpu_stats.cpp +++ b/rpcs3/util/cpu_stats.cpp @@ -1,12 +1,17 @@ #include "util/types.hpp" #include "util/cpu_stats.hpp" #include "util/sysinfo.hpp" +#include "util/logs.hpp" +#include "Utilities/StrUtil.h" #include #ifdef _WIN32 #include "windows.h" #include "tlhelp32.h" +#pragma comment(lib, "pdh.lib") #else +#include "fstream" +#include "sstream" #include "stdlib.h" #include "sys/times.h" #include "sys/types.h" @@ -44,8 +49,27 @@ # endif #endif +LOG_CHANNEL(perf_log, "PERF"); + namespace utils { +#ifdef _WIN32 + std::string pdh_error(PDH_STATUS status) + { + HANDLE hPdhLibrary = LoadLibrary(L"pdh.dll"); + LPWSTR pMessage = NULL; + + if (hPdhLibrary && + FormatMessage(FORMAT_MESSAGE_FROM_HMODULE | FORMAT_MESSAGE_ALLOCATE_BUFFER | FORMAT_MESSAGE_IGNORE_INSERTS, + hPdhLibrary, status, 0, (LPWSTR)&pMessage, 0, NULL)) + { + return fmt::format("%s (0x%x)", fmt::trim(wchar_to_utf8(pMessage), " \t\n\r\f\v"), status); + } + + return fmt::format("0x%x", status); + } +#endif + cpu_stats::cpu_stats() { #ifdef _WIN32 @@ -66,6 +90,210 @@ namespace utils #endif } + void cpu_stats::init_cpu_query() + { +#ifdef _WIN32 + PDH_STATUS status = PdhOpenQuery(NULL, NULL, &m_cpu_query); + if (ERROR_SUCCESS != status) + { + perf_log.error("Failed to open cpu query for per core cpu usage: %s", pdh_error(status)); + return; + } + status = PdhAddEnglishCounter(m_cpu_query, L"\\Processor(*)\\% Processor Time", NULL, &m_cpu_cores); + if (ERROR_SUCCESS != status) + { + perf_log.error("Failed to add processor time counter for per core cpu usage: %s", pdh_error(status)); + return; + } + status = PdhCollectQueryData(m_cpu_query); + if (ERROR_SUCCESS != status) + { + perf_log.error("Failed to collect per core cpu usage: %s", pdh_error(status)); + return; + } +#endif + } + + void cpu_stats::get_per_core_usage(std::vector& per_core_usage, double& total_usage) + { + total_usage = 0.0; + + per_core_usage.resize(utils::get_thread_count()); + std::fill(per_core_usage.begin(), per_core_usage.end(), 0.0); + + const auto string_to_number = [](const std::string& str) -> std::pair + { + std::add_pointer_t eval; + const size_t number = std::strtol(str.c_str(), &eval, 10); + + if (str.c_str() + str.size() == eval) + { + return { true, number }; + } + + return { false, 0 }; + }; + +#ifdef _WIN32 + + PDH_STATUS status = PdhCollectQueryData(m_cpu_query); + if (ERROR_SUCCESS != status) + { + perf_log.error("Failed to collect per core cpu usage: %s", pdh_error(status)); + return; + } + + PDH_FMT_COUNTERVALUE counterVal{}; + DWORD dwBufferSize = 0; // Size of the pItems buffer + DWORD dwItemCount = 0; // Number of items in the pItems buffer + PDH_FMT_COUNTERVALUE_ITEM *pItems = NULL; // Array of PDH_FMT_COUNTERVALUE_ITEM structures + + status = PdhGetFormattedCounterArray(m_cpu_cores, PDH_FMT_DOUBLE, &dwBufferSize, &dwItemCount, pItems); + if (PDH_MORE_DATA == status) + { + pItems = (PDH_FMT_COUNTERVALUE_ITEM*)malloc(dwBufferSize); + if (pItems) + { + status = PdhGetFormattedCounterArray(m_cpu_cores, PDH_FMT_DOUBLE, &dwBufferSize, &dwItemCount, pItems); + if (ERROR_SUCCESS == status) + { + ensure(dwItemCount > 0); + ensure((dwItemCount - 1) == per_core_usage.size()); // Remove one for _Total + + // Loop through the array and get the instance name and percentage. + for (DWORD i = 0; i < dwItemCount; i++) + { + const std::string token = wchar_to_utf8(pItems[i].szName); + + if (const std::string lower = fmt::to_lower(token); lower.find("total") != umax) + { + total_usage = pItems[i].FmtValue.doubleValue; + continue; + } + + if (const auto [success, cpu_index] = string_to_number(token); success && cpu_index < dwItemCount) + { + per_core_usage[cpu_index] = pItems[i].FmtValue.doubleValue; + } + else if (!success) + { + perf_log.error("Can not convert string to cpu index for per core cpu usage. (token='%s')", token); + } + else + { + perf_log.error("Invalid cpu index for per core cpu usage. (token='%s', cpu_index=%d, cores=%d)", token, cpu_index, dwItemCount); + } + } + } + else + { + perf_log.error("Failed to get per core cpu usage: %s", pdh_error(status)); + } + } + else + { + perf_log.error("Failed to allocate buffer for per core cpu usage."); + } + } + if (pItems) free(pItems); + +#elif __linux__ + + m_previous_idle_times_per_cpu.resize(utils::get_thread_count(), 0.0); + m_previous_total_times_per_cpu.resize(utils::get_thread_count(), 0.0); + + if (std::ifstream proc_stat("/proc/stat"); proc_stat.good()) + { + std::stringstream content; + content << proc_stat.rdbuf(); + proc_stat.close(); + + const std::vector lines = fmt::split(content.str(), {"\n"}); + if (lines.empty()) + { + perf_log.error("/proc/stat is empty"); + return; + } + + for (const std::string& line : lines) + { + const std::vector tokens = fmt::split(line, {" "}); + if (tokens.size() < 5) + { + return; + } + + const std::string& token = tokens[0]; + if (!token.starts_with("cpu")) + { + return; + } + + // Get CPU index + int cpu_index = -1; // -1 for total + + constexpr size_t size_of_cpu = 3; + if (token.size() > size_of_cpu) + { + if (const auto [success, val] = string_to_number(token.substr(size_of_cpu)); success && val < per_core_usage.size()) + { + cpu_index = val; + } + else if (!success) + { + perf_log.error("Can not convert string to cpu index for per core cpu usage. (token='%s', line='%s')", token, line); + continue; + } + else + { + perf_log.error("Invalid cpu index for per core cpu usage. (cpu_index=%d, cores=%d, token='%s', line='%s')", cpu_index, per_core_usage.size(), token, line); + continue; + } + } + + size_t idle_time = 0; + size_t total_time = 0; + + for (size_t i = 1; i < tokens.size(); i++) + { + if (const auto [success, val] = string_to_number(tokens[i]); success) + { + if (i == 4) + { + idle_time = val; + } + + total_time += val; + } + else + { + perf_log.error("Can not convert string to time for per core cpu usage. (i=%d, token='%s', line='%s')", i, tokens[i], line); + } + } + + if (cpu_index < 0) + { + const double idle_time_delta = idle_time - std::exchange(m_previous_idle_time_total, idle_time); + const double total_time_delta = total_time - std::exchange(m_previous_total_time_total, total_time); + total_usage = 100.0 * (1.0 - idle_time_delta / total_time_delta); + } + else + { + const double idle_time_delta = idle_time - std::exchange(m_previous_idle_times_per_cpu[cpu_index], idle_time); + const double total_time_delta = total_time - std::exchange(m_previous_total_times_per_cpu[cpu_index], total_time); + per_core_usage[cpu_index] = 100.0 * (1.0 - idle_time_delta / total_time_delta); + } + } + } + else + { + perf_log.error("Failed to open /proc/stat (%s)", strerror(errno)); + } +#else + total_usage = get_usage(); +#endif + } + double cpu_stats::get_usage() { #ifdef _WIN32 @@ -123,7 +351,7 @@ namespace utils #endif } - u32 cpu_stats::get_thread_count() // static + u32 cpu_stats::get_current_thread_count() // static { #ifdef _WIN32 // first determine the id of the current process diff --git a/rpcs3/util/cpu_stats.hpp b/rpcs3/util/cpu_stats.hpp index fea3330974..c94c8dbeb8 100644 --- a/rpcs3/util/cpu_stats.hpp +++ b/rpcs3/util/cpu_stats.hpp @@ -2,17 +2,40 @@ #include "util/types.hpp" +#ifdef _WIN32 +#include +#include +#elif __linux__ +#include +#endif + namespace utils { class cpu_stats { - u64 m_last_cpu = 0, m_sys_cpu = 0, m_usr_cpu = 0; + u64 m_last_cpu = 0; + u64 m_sys_cpu = 0; + u64 m_usr_cpu = 0; + +#ifdef _WIN32 + PDH_HQUERY m_cpu_query = nullptr; + PDH_HCOUNTER m_cpu_total = nullptr; + PDH_HCOUNTER m_cpu_cores = nullptr; +#elif __linux__ + size_t m_previous_idle_time_total = 0; + size_t m_previous_total_time_total = 0; + std::vector m_previous_idle_times_per_cpu; + std::vector m_previous_total_times_per_cpu; +#endif public: cpu_stats(); double get_usage(); - static u32 get_thread_count(); + void init_cpu_query(); + void get_per_core_usage(std::vector& per_core_usage, double& total_usage); + + static u32 get_current_thread_count(); }; }