Add SPU usage for program dump

rpcs3/Emu/CPU/CPUThread.cpp

@@ -180,7 +180,7 @@ struct cpu_prof
 			new_samples = 0;
 		}
 
-		static void print_all(std::unordered_map<std::shared_ptr<cpu_thread>, sample_info>& threads)
+		static void print_all(std::unordered_map<std::shared_ptr<cpu_thread>, sample_info>& threads, sample_info& all_info)
 		{
 			u64 new_samples = 0;
 
@@ -193,24 +193,24 @@ struct cpu_prof
 
 			std::multimap<u64, u64, std::greater<u64>> chart;
 
-			std::unordered_map<u64, u64, value_hash<u64>> freq;
-
-			u64 samples = 0, idle = 0;
-			u64 reservation = 0;
-
 			for (auto& [_, info] : threads)
 			{
 				// This function collects thread information regardless of 'new_samples' member state
 				for (auto& [name, count] : info.freq)
 				{
-					freq[name] += count;
+					all_info.freq[name] += count;
 				}
 
-				samples += info.samples;
-				idle += info.idle;
-				reservation += info.reservation_samples;
+				all_info.samples += info.samples;
+				all_info.idle += info.idle;
+				all_info.reservation_samples += info.reservation_samples;
 			}
 
+			const u64 samples = all_info.samples;
+			const u64 idle = all_info.idle;
+			const u64 reservation = all_info.reservation_samples;
+			const auto& freq = all_info.freq;
+
 			if (samples == idle)
 			{
 				return;
@@ -232,6 +232,8 @@ struct cpu_prof
 		}
 	};
 
+	sample_info all_threads_info{};
+
 	void operator()()
 	{
 		std::unordered_map<std::shared_ptr<cpu_thread>, sample_info> threads;
@@ -335,7 +337,8 @@ struct cpu_prof
 			{
 				profiler.success("Flushing profiling results...");
 
-				sample_info::print_all(threads);
+				all_threads_info = {};
+				sample_info::print_all(threads, all_threads_info);
 			}
 
 			if (Emu.IsPaused())
@@ -356,14 +359,43 @@ struct cpu_prof
 		}
 
 		// Print all remaining results
-		sample_info::print_all(threads);
+		sample_info::print_all(threads, all_threads_info);
 	}
 
 	static constexpr auto thread_name = "CPU Profiler"sv;
 };
 
+
 using cpu_profiler = named_thread<cpu_prof>;
 
+extern f64 get_cpu_program_usage_percent(u64 hash)
+{
+	if (auto prof = g_fxo->try_get<cpu_profiler>(); prof && *prof == thread_state::finished)
+	{
+		if (Emu.IsStopped())
+		{
+			u64 total = 0;
+
+			for (auto [name, count] : prof->all_threads_info.freq)
+			{
+				if ((name & -65536) == hash)
+				{
+					total += count;
+				}
+			}
+
+			if (!total)
+			{
+				return 0;
+			}
+
+			return std::max<f64>(0.0001, static_cast<f64>(total) * 100 / (prof->all_threads_info.samples - prof->all_threads_info.idle));
+		}
+	}
+
+	return 0;
+}
+
 thread_local DECLARE(cpu_thread::g_tls_this_thread) = nullptr;
 
 // Total number of CPU threads

rpcs3/Emu/System.cpp

@@ -102,6 +102,8 @@ thread_local std::string_view g_tls_serialize_name;
 
 extern thread_local std::string(*g_tls_log_prefix)();
 
+extern f64 get_cpu_program_usage_percent(u64 hash);
+
 // Report error and call std::abort(), defined in main.cpp
 [[noreturn]] void report_fatal_error(std::string_view text, bool is_html = false, bool include_help_text = true);
 
@@ -3501,9 +3503,54 @@ void Emulator::Kill(bool allow_autoexit, bool savestate, savestate_stage* save_s
 						to_log = to_log.substr(0, utils::add_saturate<usz>(to_log.rfind("\n========== SPU BLOCK"sv), 1));
 						to_remove = to_log.size();
 
+						std::string new_log(to_log);
+
+						for (usz iter = 0, out_added = 0; iter < to_log.size();)
+						{
+							const usz index = to_log.find(") ==========", iter);
+
+							if (index == umax)
+							{
+								break;
+							}
+
+							const std::string_view until = to_log.substr(0, index);
+							const usz seperator = until.rfind(", ");
+
+							if (seperator == umax)
+							{
+								iter = index + 1;
+								continue;
+							}
+
+							const std::string_view prog_hash = until.substr(seperator + 2);
+
+							if (prog_hash.empty())
+							{
+								iter = index + 1;
+								continue;
+							}
+
+							const fmt::base57_result result = fmt::base57_result::from_string(prog_hash);
+
+							if (result.size < sizeof(be_t<u64>))
+							{
+								iter = index + 1;
+								continue;
+							}
+
+							const u64 hash_val = read_from_ptr<be_t<u64>>(result.data) & -65536;
+							const f64 usage = get_cpu_program_usage_percent(hash_val);
+							const std::string text_append = fmt::format("usage %%%g, ", usage);
+							new_log.insert(new_log.begin() + seperator + out_added + 2, text_append.begin(), text_append.end());
+
+							out_added += text_append.size();
+							iter = index + 1;
+						}
+
 						// Cannot log it all at once due to technical reasons, split it to 8MB at maximum of whole functions
 						// Assume the block prefix exists because it is created by RPCS3 (or log it in an ugly manner if it does not exist)
-						sys_log.notice("Logging spu.log #%u:\n\n%s\n", part_ctr, to_log);
+						sys_log.notice("Logging spu.log #%u:\n\n%s\n", part_ctr, new_log);
 					}
 
 					sys_log.notice("End spu.log (%u bytes)", total_size);