From faabb9e1111ff377efd4098e7513c7a5432b2bdb Mon Sep 17 00:00:00 2001 From: Elad Ashkenazi <18193363+elad335@users.noreply.github.com> Date: Sat, 27 Jul 2024 09:49:22 +0300 Subject: [PATCH] Add SPU usage for program dump --- Utilities/StrFmt.cpp | 129 ++++++++++++++++++++++++++++++++++++ Utilities/StrFmt.h | 25 ++++++- rpcs3/Emu/CPU/CPUThread.cpp | 56 ++++++++++++---- rpcs3/Emu/System.cpp | 49 +++++++++++++- 4 files changed, 243 insertions(+), 16 deletions(-) diff --git a/Utilities/StrFmt.cpp b/Utilities/StrFmt.cpp index 34e75b4311..ef36c548bf 100644 --- a/Utilities/StrFmt.cpp +++ b/Utilities/StrFmt.cpp @@ -171,6 +171,135 @@ void fmt_class_string::format(std::string& out, u64 arg) } } +fmt::base57_result fmt::base57_result::from_string(std::string_view str) +{ + // Precomputed tail sizes if input data is not multiple of 8 + static constexpr u8 s_tail[8] = {0, 2, 3, 5, 6, 7, 9, 10}; + + fmt::base57_result result(str.size() / 11 * 8 + (str.size() % 11 ? 8 : 0)); + + // Each 11 chars of input produces 8 bytes of byte output + for (usz i = 0, p = 0; i < result.size; i += 8, p += 11) + { + // Load up to 8 bytes + const std::string_view be_value = str.substr(p); + be_t value = 0; + + for (u64 j = 10, multiplier = 0; j != umax; j--) + { + if (multiplier == 0) + { + multiplier = 1; + } + else + { + // Do it first to avoid overflow + multiplier *= 57; + } + + if (j < be_value.size()) + { + auto to_val = [](u8 c) -> u64 + { + if (std::isdigit(c)) + { + return c - '0'; + } + + if (std::isupper(c)) + { + // Omitted characters + if (c == 'B' || c == 'D' || c == 'I' || c == 'O') + { + return umax; + } + + if (c > 'O') + { + c -= 4; + } + else if (c > 'I') + { + c -= 3; + } + else if (c > 'D') + { + c -= 2; + } + else if (c > 'B') + { + c--; + } + + return c - 'A' + 10; + } + + if (std::islower(c)) + { + // Omitted characters + if (c == 'l') + { + return umax; + } + + if (c > 'l') + { + c--; + } + + return c - 'a' + 10 + 22; + } + + return umax; + }; + + const u64 res = to_val(be_value[j]); + + if (res == umax) + { + // Invalid input character + result = {}; + break; + } + + if (u64{umax} / multiplier < res) + { + // Overflow + result = {}; + break; + } + + const u64 addend = res * multiplier; + + if (~value < addend) + { + // Overflow + result = {}; + break; + } + + value += addend; + } + } + + if (!result.size) + { + break; + } + + if (result.size - i < sizeof(value)) + { + std::memcpy(result.memory.get() + i, &value, result.size - i); + } + else + { + std::memcpy(result.memory.get() + i, &value, sizeof(value)); + } + } + + return std::move(result); +} + void fmt_class_string::format(std::string& out, u64 arg) { fmt::append(out, "%p", arg); diff --git a/Utilities/StrFmt.h b/Utilities/StrFmt.h index 0388e921f8..f83cbe49fe 100644 --- a/Utilities/StrFmt.h +++ b/Utilities/StrFmt.h @@ -320,20 +320,39 @@ namespace fmt const uchar* data; usz size; + base57() = default; + template - base57(const T& arg) - : data(reinterpret_cast(&arg)) + base57(const T& arg) noexcept + : data(reinterpret_cast(std::addressof(arg))) , size(sizeof(T)) { } - base57(const uchar* data, usz size) + base57(const uchar* data, usz size) noexcept : data(data) , size(size) { } }; + struct base57_result : public base57 + { + std::unique_ptr memory; + + base57_result() noexcept = default; + base57_result(base57_result&&) = default; + base57_result& operator=(base57_result&&) = default; + + explicit base57_result(usz size) noexcept + : base57(size ? new uchar[size] : nullptr, size) + , memory(const_cast(this->data)) + { + } + + static base57_result from_string(std::string_view str); + }; + template constexpr const fmt_type_info type_info_v[sizeof...(Args) + 1]{fmt_type_info::make>()...}; diff --git a/rpcs3/Emu/CPU/CPUThread.cpp b/rpcs3/Emu/CPU/CPUThread.cpp index 704ccd52d6..5d6e24db1e 100644 --- a/rpcs3/Emu/CPU/CPUThread.cpp +++ b/rpcs3/Emu/CPU/CPUThread.cpp @@ -180,7 +180,7 @@ struct cpu_prof new_samples = 0; } - static void print_all(std::unordered_map, sample_info>& threads) + static void print_all(std::unordered_map, sample_info>& threads, sample_info& all_info) { u64 new_samples = 0; @@ -193,24 +193,24 @@ struct cpu_prof std::multimap> chart; - std::unordered_map> 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, 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; +extern f64 get_cpu_program_usage_percent(u64 hash) +{ + if (auto prof = g_fxo->try_get(); 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(0.0001, static_cast(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 diff --git a/rpcs3/Emu/System.cpp b/rpcs3/Emu/System.cpp index 5fad90df5a..218677aeba 100644 --- a/rpcs3/Emu/System.cpp +++ b/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(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)) + { + iter = index + 1; + continue; + } + + const u64 hash_val = read_from_ptr>(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);