PPU Profiler

elad335 · elad335 · commit 107d9dc53333 · 2025-11-19T21:37:50.000+02:00
diff --git a/rpcs3/Emu/CPU/CPUThread.cpp b/rpcs3/Emu/CPU/CPUThread.cpp
@@ -190,7 +190,7 @@ struct cpu_prof
 			reservation_samples = 0;
 		}
 
-		static std::string format(const std::multimap<u64, u64, std::greater<u64>>& chart, u64 samples, u64 idle, bool extended_print = false)
+		static std::string format(const std::multimap<u64, u64, std::greater<u64>>& chart, u64 samples, u64 idle, u32 type_id, bool extended_print = false)
 		{
 			// Print results
 			std::string results;
@@ -204,11 +204,18 @@ struct cpu_prof
 				const f64 _frac = count / busy / samples;
 
 				// Print only 7 hash characters out of 11 (which covers roughly 48 bits)
-				fmt::append(results, "\n\t[%s", fmt::base57(be_t<u64>{name}));
-				results.resize(results.size() - 4);
+				if (type_id == 2)
+				{
+					fmt::append(results, "\n\t[%s", fmt::base57(be_t<u64>{name}));
+					results.resize(results.size() - 4);
 
-				// Print chunk address from lowest 16 bits
-				fmt::append(results, "...chunk-0x%05x]: %.4f%% (%u)", (name & 0xffff) * 4, _frac * 100., count);
+					// Print chunk address from lowest 16 bits
+					fmt::append(results, "...chunk-0x%05x]: %.4f%% (%u)", (name & 0xffff) * 4, _frac * 100., count);
+				}
+				else
+				{
+					fmt::append(results, "\n\t[0x%07x]: %.4f%% (%u)", name, _frac * 100., count);
+				}
 
 				if (results.size() >= (extended_print ? 10000 : 5000))
 				{
@@ -257,27 +264,37 @@ struct cpu_prof
 			}
 
 			// Print results
-			const std::string results = format(chart, samples, idle);
+			const std::string results = format(chart, samples, idle, ptr->id_type());
 			profiler.notice("Thread \"%s\" [0x%08x]: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%):\n%s", ptr->get_name(), ptr->id, samples, get_percent(idle, samples), new_samples, reservation_samples, get_percent(reservation_samples, samples - idle), results);
 
 			new_samples = 0;
 		}
 
-		static void print_all(std::unordered_map<shared_ptr<cpu_thread>, sample_info>& threads, sample_info& all_info)
+		static void print_all(std::unordered_map<shared_ptr<cpu_thread>, sample_info>& threads, sample_info& all_info, u32 type_id)
 		{
 			u64 new_samples = 0;
 
 			// Print all results and cleanup
 			for (auto& [ptr, info] : threads)
 			{
+				if (ptr->id_type() != type_id)
+				{
+					continue;
+				}
+
 				new_samples += info.new_samples;
 				info.print(ptr);
 			}
 
 			std::multimap<u64, u64, std::greater<u64>> chart;
 
-			for (auto& [_, info] : threads)
+			for (auto& [ptr, info] : threads)
 			{
+				if (ptr->id_type() != type_id)
+				{
+					continue;
+				}
+
 				// This function collects thread information regardless of 'new_samples' member state
 				for (auto& [name, count] : info.freq)
 				{
@@ -301,7 +318,7 @@ struct cpu_prof
 
 			if (new_samples < min_print_all_samples && thread_ctrl::state() != thread_state::aborting)
 			{
-				profiler.notice("All Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%): Not enough new samples have been collected since the last print.", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle));
+				profiler.notice("All %s Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%): Not enough new samples have been collected since the last print.", type_id == 1 ? "PPU" : "SPU", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle));
 				return;
 			}
 
@@ -310,12 +327,13 @@ struct cpu_prof
 				chart.emplace(count, name);
 			}
 
-			const std::string results = format(chart, samples, idle, true);
-			profiler.notice("All Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%):%s", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle), results);
+			const std::string results = format(chart, samples, idle, type_id, true);
+			profiler.notice("All %s Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%):%s", type_id == 1 ? "PPU" : "SPU", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle), results);
 		}
 	};
 
-	sample_info all_threads_info{};
+	sample_info all_spu_threads_info{};
+	sample_info all_ppu_threads_info{};
 
 	void operator()()
 	{
@@ -376,8 +394,11 @@ struct cpu_prof
 			{
 				if (auto state = +ptr->state; cpu_flag::exit - state)
 				{
+					const auto spu = ptr->try_get<spu_thread>();
+					const auto ppu = ptr->try_get<ppu_thread>();
+
 					// Get short function hash
-					const u64 name = atomic_storage<u64>::load(ptr->block_hash);
+					const u64 name = ppu ? atomic_storage<u32>::load(ppu->cia) : atomic_storage<u64>::load(ptr->block_hash);
 
 					// Append occurrence
 					info.samples++;
@@ -387,17 +408,17 @@ struct cpu_prof
 						info.freq[name]++;
 						info.new_samples++;
 
-						if (auto spu = ptr->try_get<spu_thread>())
+						if (spu)
 						{
 							if (spu->raddr)
 							{
 								info.reservation_samples++;
 							}
-						}
 
-						// Append verification time to fixed common name 0000000...chunk-0x3fffc
-						if (name >> 16 && (name & 0xffff) == 0)
-							info.freq[0xffff]++;
+							// Append verification time to fixed common name 0000000...chunk-0x3fffc
+							if (name >> 16 && (name & 0xffff) == 0)
+								info.freq[0xffff]++;
+						}
 					}
 					else
 					{
@@ -420,8 +441,10 @@ struct cpu_prof
 			{
 				profiler.success("Flushing profiling results...");
 
-				all_threads_info = {};
-				sample_info::print_all(threads, all_threads_info);
+				all_ppu_threads_info = {};
+				all_spu_threads_info = {};
+				sample_info::print_all(threads, all_ppu_threads_info, 1);
+				sample_info::print_all(threads, all_spu_threads_info, 2);
 			}
 
 			if (Emu.IsPaused())
@@ -442,7 +465,8 @@ struct cpu_prof
 		}
 
 		// Print all remaining results
-		sample_info::print_all(threads, all_threads_info);
+		sample_info::print_all(threads, all_ppu_threads_info, 1);
+		sample_info::print_all(threads, all_spu_threads_info, 2);
 	}
 
 	static constexpr auto thread_name = "CPU Profiler"sv;
@@ -459,7 +483,7 @@ extern f64 get_cpu_program_usage_percent(u64 hash)
 		{
 			u64 total = 0;
 
-			for (auto [name, count] : prof->all_threads_info.freq)
+			for (auto [name, count] : prof->all_spu_threads_info.freq)
 			{
 				if ((name & -65536) == hash)
 				{
@@ -472,7 +496,7 @@ extern f64 get_cpu_program_usage_percent(u64 hash)
 				return 0;
 			}
 
-			return std::max<f64>(0.0001, static_cast<f64>(total) * 100 / (prof->all_threads_info.samples - prof->all_threads_info.idle));
+			return std::max<f64>(0.0001, static_cast<f64>(total) * 100 / (prof->all_spu_threads_info.samples - prof->all_spu_threads_info.idle));
 		}
 	}
 
@@ -639,22 +663,17 @@ void cpu_thread::operator()()
 		thread_ctrl::set_thread_affinity_mask(thread_ctrl::get_affinity_mask(get_class()));
 	}
 
-	while (!g_fxo->is_init<cpu_profiler>())
-	{
-		if (Emu.IsStopped())
-		{
-			return;
-		}
-
-		// Can we have a little race, right? First thread is started concurrently with g_fxo->init()
-		thread_ctrl::wait_for(1000);
-	}
+	ensure(g_fxo->is_init<cpu_profiler>());
 
 	switch (get_class())
 	{
 	case thread_class::ppu:
 	{
-		//g_fxo->get<cpu_profiler>().registered.push(id);
+		if (g_cfg.core.ppu_prof)
+		{
+			g_fxo->get<cpu_profiler>().registered.push(id);
+		}
+
 		break;
 	}
 	case thread_class::spu:
@@ -1546,7 +1565,7 @@ void cpu_thread::flush_profilers() noexcept
 		return;
 	}
 
-	if (g_cfg.core.spu_prof || g_cfg.core.spu_debug)
+	if (g_cfg.core.spu_prof || g_cfg.core.spu_debug || g_cfg.core.ppu_prof)
 	{
 		g_fxo->get<cpu_profiler>().registered.push(0);
 	}
diff --git a/rpcs3/Emu/Cell/PPUTranslator.cpp b/rpcs3/Emu/Cell/PPUTranslator.cpp
@@ -593,6 +593,11 @@ void PPUTranslator::CallFunction(u64 target, Value* indirect)
 			{
 				callee = m_module->getOrInsertFunction(fmt::format("__0x%x", target_last - base), type);
 				cast<Function>(callee.getCallee())->setCallingConv(CallingConv::GHC);
+
+				if (g_cfg.core.ppu_prof)
+				{
+					m_ir->CreateStore(m_ir->getInt32(target_last), m_ir->CreateStructGEP(m_thread_type, m_thread, static_cast<uint>(&m_cia - m_locals)));
+				}
 			}
 		}
 		else
diff --git a/rpcs3/Emu/system_config.h b/rpcs3/Emu/system_config.h
@@ -57,6 +57,7 @@ struct cfg_root : cfg::node
 		cfg::_bool spu_verification{ this, "SPU Verification", true }; // Should be enabled
 		cfg::_bool spu_cache{ this, "SPU Cache", true };
 		cfg::_bool spu_prof{ this, "SPU Profiler", false };
+		cfg::_bool ppu_prof{ this, "PPU Profiler", false };
 		cfg::uint<0, 16> mfc_transfers_shuffling{ this, "MFC Commands Shuffling Limit", 0 };
 		cfg::uint<0, 10000> mfc_transfers_timeout{ this, "MFC Commands Timeout", 0, true };
 		cfg::_bool mfc_shuffling_in_steps{ this, "MFC Commands Shuffling In Steps", false, true };

Original file line number	Diff line number	Diff line change
`@@ -190,7 +190,7 @@ struct cpu_prof`
`190`	`190`	`reservation_samples = 0;`
`191`	`191`	`}`
`192`	`192`
`193`		`- static std::string format(const std::multimap<u64, u64, std::greater<u64>>& chart, u64 samples, u64 idle, bool extended_print = false)`
	`193`	`+ static std::string format(const std::multimap<u64, u64, std::greater<u64>>& chart, u64 samples, u64 idle, u32 type_id, bool extended_print = false)`
`194`	`194`	`{`
`195`	`195`	`// Print results`
`196`	`196`	`std::string results;`
`@@ -204,11 +204,18 @@ struct cpu_prof`
`204`	`204`	`const f64 _frac = count / busy / samples;`
`205`	`205`
`206`	`206`	`// Print only 7 hash characters out of 11 (which covers roughly 48 bits)`
`207`		`- fmt::append(results, "\n\t[%s", fmt::base57(be_t<u64>{name}));`
`208`		`- results.resize(results.size() - 4);`
	`207`	`+ if (type_id == 2)`
	`208`	`+ {`
	`209`	`+ fmt::append(results, "\n\t[%s", fmt::base57(be_t<u64>{name}));`
	`210`	`+ results.resize(results.size() - 4);`
`209`	`211`
`210`		`- // Print chunk address from lowest 16 bits`
`211`		`- fmt::append(results, "...chunk-0x%05x]: %.4f%% (%u)", (name & 0xffff) * 4, _frac * 100., count);`
	`212`	`+ // Print chunk address from lowest 16 bits`
	`213`	`+ fmt::append(results, "...chunk-0x%05x]: %.4f%% (%u)", (name & 0xffff) * 4, _frac * 100., count);`
	`214`	`+ }`
	`215`	`+ else`
	`216`	`+ {`
	`217`	`+ fmt::append(results, "\n\t[0x%07x]: %.4f%% (%u)", name, _frac * 100., count);`
	`218`	`+ }`
`212`	`219`
`213`	`220`	`if (results.size() >= (extended_print ? 10000 : 5000))`
`214`	`221`	`{`
`@@ -257,27 +264,37 @@ struct cpu_prof`
`257`	`264`	`}`
`258`	`265`
`259`	`266`	`// Print results`
`260`		`- const std::string results = format(chart, samples, idle);`
	`267`	`+ const std::string results = format(chart, samples, idle, ptr->id_type());`
`261`	`268`	`profiler.notice("Thread \"%s\" [0x%08x]: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%):\n%s", ptr->get_name(), ptr->id, samples, get_percent(idle, samples), new_samples, reservation_samples, get_percent(reservation_samples, samples - idle), results);`
`262`	`269`
`263`	`270`	`new_samples = 0;`
`264`	`271`	`}`
`265`	`272`
`266`		`- static void print_all(std::unordered_map<shared_ptr<cpu_thread>, sample_info>& threads, sample_info& all_info)`
	`273`	`+ static void print_all(std::unordered_map<shared_ptr<cpu_thread>, sample_info>& threads, sample_info& all_info, u32 type_id)`
`267`	`274`	`{`
`268`	`275`	`u64 new_samples = 0;`
`269`	`276`
`270`	`277`	`// Print all results and cleanup`
`271`	`278`	`for (auto& [ptr, info] : threads)`
`272`	`279`	`{`
	`280`	`+ if (ptr->id_type() != type_id)`
	`281`	`+ {`
	`282`	`+ continue;`
	`283`	`+ }`
	`284`	`+`
`273`	`285`	`new_samples += info.new_samples;`
`274`	`286`	`info.print(ptr);`
`275`	`287`	`}`
`276`	`288`
`277`	`289`	`std::multimap<u64, u64, std::greater<u64>> chart;`
`278`	`290`
`279`		`- for (auto& [_, info] : threads)`
	`291`	`+ for (auto& [ptr, info] : threads)`
`280`	`292`	`{`
	`293`	`+ if (ptr->id_type() != type_id)`
	`294`	`+ {`
	`295`	`+ continue;`
	`296`	`+ }`
	`297`	`+`
`281`	`298`	`// This function collects thread information regardless of 'new_samples' member state`
`282`	`299`	`for (auto& [name, count] : info.freq)`
`283`	`300`	`{`
`@@ -301,7 +318,7 @@ struct cpu_prof`
`301`	`318`
`302`	`319`	`if (new_samples < min_print_all_samples && thread_ctrl::state() != thread_state::aborting)`
`303`	`320`	`{`
`304`		`- profiler.notice("All Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%): Not enough new samples have been collected since the last print.", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle));`
	`321`	`+ profiler.notice("All %s Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%): Not enough new samples have been collected since the last print.", type_id == 1 ? "PPU" : "SPU", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle));`
`305`	`322`	`return;`
`306`	`323`	`}`
`307`	`324`
`@@ -310,12 +327,13 @@ struct cpu_prof`
`310`	`327`	`chart.emplace(count, name);`
`311`	`328`	`}`
`312`	`329`
`313`		`- const std::string results = format(chart, samples, idle, true);`
`314`		`- profiler.notice("All Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%):%s", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle), results);`
	`330`	`+ const std::string results = format(chart, samples, idle, type_id, true);`
	`331`	`+ profiler.notice("All %s Threads: %u samples (%.4f%% idle), %u new, %u reservation (%.4f%%):%s", type_id == 1 ? "PPU" : "SPU", samples, get_percent(idle, samples), new_samples, reservation, get_percent(reservation, samples - idle), results);`
`315`	`332`	`}`
`316`	`333`	`};`
`317`	`334`
`318`		`- sample_info all_threads_info{};`
	`335`	`+ sample_info all_spu_threads_info{};`
	`336`	`+ sample_info all_ppu_threads_info{};`
`319`	`337`
`320`	`338`	`void operator()()`
`321`	`339`	`{`
`@@ -376,8 +394,11 @@ struct cpu_prof`
`376`	`394`	`{`
`377`	`395`	`if (auto state = +ptr->state; cpu_flag::exit - state)`
`378`	`396`	`{`
	`397`	`+ const auto spu = ptr->try_get<spu_thread>();`
	`398`	`+ const auto ppu = ptr->try_get<ppu_thread>();`
	`399`	`+`
`379`	`400`	`// Get short function hash`
`380`		`- const u64 name = atomic_storage<u64>::load(ptr->block_hash);`
	`401`	`+ const u64 name = ppu ? atomic_storage<u32>::load(ppu->cia) : atomic_storage<u64>::load(ptr->block_hash);`
`381`	`402`
`382`	`403`	`// Append occurrence`
`383`	`404`	`info.samples++;`
`@@ -387,17 +408,17 @@ struct cpu_prof`
`387`	`408`	`info.freq[name]++;`
`388`	`409`	`info.new_samples++;`
`389`	`410`
`390`		`- if (auto spu = ptr->try_get<spu_thread>())`
	`411`	`+ if (spu)`
`391`	`412`	`{`
`392`	`413`	`if (spu->raddr)`
`393`	`414`	`{`
`394`	`415`	`info.reservation_samples++;`
`395`	`416`	`}`
`396`		`- }`
`397`	`417`
`398`		`- // Append verification time to fixed common name 0000000...chunk-0x3fffc`
`399`		`- if (name >> 16 && (name & 0xffff) == 0)`
`400`		`- info.freq[0xffff]++;`
	`418`	`+ // Append verification time to fixed common name 0000000...chunk-0x3fffc`
	`419`	`+ if (name >> 16 && (name & 0xffff) == 0)`
	`420`	`+ info.freq[0xffff]++;`
	`421`	`+ }`
`401`	`422`	`}`
`402`	`423`	`else`
`403`	`424`	`{`
`@@ -420,8 +441,10 @@ struct cpu_prof`
`420`	`441`	`{`
`421`	`442`	`profiler.success("Flushing profiling results...");`
`422`	`443`
`423`		`- all_threads_info = {};`
`424`		`- sample_info::print_all(threads, all_threads_info);`
	`444`	`+ all_ppu_threads_info = {};`
	`445`	`+ all_spu_threads_info = {};`
	`446`	`+ sample_info::print_all(threads, all_ppu_threads_info, 1);`
	`447`	`+ sample_info::print_all(threads, all_spu_threads_info, 2);`
`425`	`448`	`}`
`426`	`449`
`427`	`450`	`if (Emu.IsPaused())`
`@@ -442,7 +465,8 @@ struct cpu_prof`
`442`	`465`	`}`
`443`	`466`
`444`	`467`	`// Print all remaining results`
`445`		`- sample_info::print_all(threads, all_threads_info);`
	`468`	`+ sample_info::print_all(threads, all_ppu_threads_info, 1);`
	`469`	`+ sample_info::print_all(threads, all_spu_threads_info, 2);`
`446`	`470`	`}`
`447`	`471`
`448`	`472`	`static constexpr auto thread_name = "CPU Profiler"sv;`
`@@ -459,7 +483,7 @@ extern f64 get_cpu_program_usage_percent(u64 hash)`
`459`	`483`	`{`
`460`	`484`	`u64 total = 0;`
`461`	`485`
`462`		`- for (auto [name, count] : prof->all_threads_info.freq)`
	`486`	`+ for (auto [name, count] : prof->all_spu_threads_info.freq)`
`463`	`487`	`{`
`464`	`488`	`if ((name & -65536) == hash)`
`465`	`489`	`{`
`@@ -472,7 +496,7 @@ extern f64 get_cpu_program_usage_percent(u64 hash)`
`472`	`496`	`return 0;`
`473`	`497`	`}`
`474`	`498`
`475`		`- return std::max<f64>(0.0001, static_cast<f64>(total) * 100 / (prof->all_threads_info.samples - prof->all_threads_info.idle));`
	`499`	`+ return std::max<f64>(0.0001, static_cast<f64>(total) * 100 / (prof->all_spu_threads_info.samples - prof->all_spu_threads_info.idle));`
`476`	`500`	`}`
`477`	`501`	`}`
`478`	`502`
`@@ -639,22 +663,17 @@ void cpu_thread::operator()()`
`639`	`663`	`thread_ctrl::set_thread_affinity_mask(thread_ctrl::get_affinity_mask(get_class()));`
`640`	`664`	`}`
`641`	`665`
`642`		`- while (!g_fxo->is_init<cpu_profiler>())`
`643`		`- {`
`644`		`- if (Emu.IsStopped())`
`645`		`- {`
`646`		`- return;`
`647`		`- }`
`648`		`-`
`649`		`- // Can we have a little race, right? First thread is started concurrently with g_fxo->init()`
`650`		`- thread_ctrl::wait_for(1000);`
`651`		`- }`
	`666`	`+ ensure(g_fxo->is_init<cpu_profiler>());`
`652`	`667`
`653`	`668`	`switch (get_class())`
`654`	`669`	`{`
`655`	`670`	`case thread_class::ppu:`
`656`	`671`	`{`
`657`		`- //g_fxo->get<cpu_profiler>().registered.push(id);`
	`672`	`+ if (g_cfg.core.ppu_prof)`
	`673`	`+ {`
	`674`	`+ g_fxo->get<cpu_profiler>().registered.push(id);`
	`675`	`+ }`
	`676`	`+`
`658`	`677`	`break;`
`659`	`678`	`}`
`660`	`679`	`case thread_class::spu:`
`@@ -1546,7 +1565,7 @@ void cpu_thread::flush_profilers() noexcept`
`1546`	`1565`	`return;`
`1547`	`1566`	`}`
`1548`	`1567`
`1549`		`- if (g_cfg.core.spu_prof \|\| g_cfg.core.spu_debug)`
	`1568`	`+ if (g_cfg.core.spu_prof \|\| g_cfg.core.spu_debug \|\| g_cfg.core.ppu_prof)`
`1550`	`1569`	`{`
`1551`	`1570`	`g_fxo->get<cpu_profiler>().registered.push(0);`
`1552`	`1571`	`}`
Original file line number	Diff line number	Diff line change
`@@ -593,6 +593,11 @@ void PPUTranslator::CallFunction(u64 target, Value* indirect)`
`593`	`593`	`{`
`594`	`594`	`callee = m_module->getOrInsertFunction(fmt::format("__0x%x", target_last - base), type);`
`595`	`595`	`cast<Function>(callee.getCallee())->setCallingConv(CallingConv::GHC);`
	`596`	`+`
	`597`	`+ if (g_cfg.core.ppu_prof)`
	`598`	`+ {`
	`599`	`+ m_ir->CreateStore(m_ir->getInt32(target_last), m_ir->CreateStructGEP(m_thread_type, m_thread, static_cast<uint>(&m_cia - m_locals)));`
	`600`	`+ }`
`596`	`601`	`}`
`597`	`602`	`}`
`598`	`603`	`else`