Log cpu usage periodically

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

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]];
 					}

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<named_thread<progress_dialog_server>>();
 
+	// Initialize performance monitor
+	g_fxo->init<named_thread<perf_monitor>>();
+
 	// 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<named_thread<progress_dialog_server>>();
 
+		// Initialize performance monitor
+		g_fxo->init<named_thread<perf_monitor>>();
+
 		// Set title to actual disc title if necessary
 		const std::string disc_sfo_dir = vfs::get("/dev_bdvd/PS3_GAME/PARAM.SFO");
 

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<double> 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()
+{
+}

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;
+};

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)

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())

rpcs3/emucore.vcxproj

@@ -72,6 +72,7 @@
     <ClCompile Include="Emu\Io\pad_config_types.cpp" />
     <ClCompile Include="Emu\localized_string.cpp" />
     <ClCompile Include="Emu\NP\rpcn_config.cpp" />
+    <ClCompile Include="Emu\perf_monitor.cpp" />
     <ClCompile Include="Emu\RSX\Common\texture_cache.cpp" />
     <ClCompile Include="Emu\RSX\Overlays\overlay_controls.cpp" />
     <ClCompile Include="Emu\RSX\Overlays\overlay_media_list_dialog.cpp" />
@@ -476,6 +477,7 @@
     <ClInclude Include="Emu\NP\np_structs_extra.h" />
     <ClInclude Include="Emu\NP\rpcn_client.h" />
     <ClInclude Include="Emu\NP\rpcn_config.h" />
+    <ClInclude Include="Emu\perf_monitor.hpp" />
     <ClInclude Include="Emu\RSX\Common\bitfield.hpp" />
     <ClInclude Include="Emu\RSX\Common\profiling_timer.hpp" />
     <ClInclude Include="Emu\RSX\Common\simple_array.hpp" />

rpcs3/emucore.vcxproj.filters

@@ -1030,6 +1030,9 @@
     <ClCompile Include="Emu\RSX\Overlays\overlay_media_list_dialog.cpp">
       <Filter>Emu\GPU\RSX\Overlays</Filter>
     </ClCompile>
+    <ClCompile Include="Emu\perf_monitor.cpp">
+      <Filter>Emu</Filter>
+    </ClCompile>
   </ItemGroup>
   <ItemGroup>
     <ClInclude Include="Crypto\aes.h">
@@ -2056,6 +2059,9 @@
     <ClInclude Include="Emu\RSX\Common\time.hpp">
       <Filter>Emu\GPU\RSX\Common</Filter>
     </ClInclude>
+    <ClInclude Include="Emu\perf_monitor.hpp">
+      <Filter>Emu</Filter>
+    </ClInclude>
   </ItemGroup>
   <ItemGroup>
     <None Include="Emu\RSX\Common\Interpreter\FragmentInterpreter.glsl">

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 <algorithm>
 
 #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<double>& 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<bool, size_t>
+		{
+			std::add_pointer_t<char> 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<std::string> 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<std::string> 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

rpcs3/util/cpu_stats.hpp

@@ -2,17 +2,40 @@
 
 #include "util/types.hpp"
 
+#ifdef _WIN32
+#include <pdh.h>
+#include <pdhmsg.h>
+#elif __linux__
+#include <vector>
+#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<size_t> m_previous_idle_times_per_cpu;
+		std::vector<size_t> 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<double>& per_core_usage, double& total_usage);
+
+		static u32 get_current_thread_count();
 	};
 }