System.cpp: Fixup spu.log/tty.log dumping

This commit is contained in:
Eladash 2023-07-27 20:43:14 +03:00 committed by Elad Ashkenazi
parent 6547fa9cc3
commit 849af08ee9

View File

@ -2941,11 +2941,72 @@ void Emulator::Kill(bool allow_autoexit, bool savestate)
ar.set_reading_state();
}
// Final termination from main thread (move the last ownership of join thread in order to destroy it)
CallFromMainThread([join_thread = std::move(join_thread), allow_autoexit, this]() mutable
// Log additional debug information - do not do it on the main thread due to the concern of halting UI events
if (g_tty && sys_log.notice)
{
// Write merged TTY output after emulation has been safely stopped
if (usz attempted_read_size = utils::sub_saturate<usz>(g_tty.pos(), m_tty_file_init_pos))
{
if (fs::file tty_read_fd{fs::get_cache_dir() + "TTY.log"})
{
// Enfore an arbitrary limit for now to avoid OOM in case the guest code has bombarded TTY
// 3MB, this should be enough
constexpr usz c_max_tty_spill_size = 0x30'0000;
std::string tty_buffer(std::min<usz>(attempted_read_size, c_max_tty_spill_size), '\0');
tty_buffer.resize(tty_read_fd.read_at(m_tty_file_init_pos, tty_buffer.data(), tty_buffer.size()));
tty_read_fd.close();
if (!tty_buffer.empty())
{
// Mark start and end very clearly with RPCS3 put in it
sys_log.notice("\nAccumulated RPCS3 TTY:\n\n\n%s\n\n\nEnd RPCS3 TTY Section.\n", tty_buffer);
}
}
}
}
if (g_cfg.core.spu_debug && sys_log.notice)
{
const std::string cache_path = rpcs3::cache::get_ppu_cache();
if (fs::file spu_log{cache_path + "/spu.log"})
{
// 96MB limit, this may be a lot but this only has an effect when enabling the debug option
constexpr usz c_max_spu_log_spill_size = 0x600'0000;
const usz total_size = spu_log.size();
std::string log_buffer(std::min<usz>(spu_log.size(), c_max_spu_log_spill_size), '\0');
log_buffer.resize(spu_log.read(log_buffer.data(), log_buffer.size()));
spu_log.close();
if (!log_buffer.empty())
{
usz to_remove = 0;
usz part_ctr = 1;
for (std::string_view not_logged = log_buffer; !not_logged.empty(); part_ctr++, not_logged.remove_prefix(to_remove))
{
std::string_view to_log = not_logged;
to_log = to_log.substr(0, 0x2'0000);
to_log = to_log.substr(0, utils::add_saturate<usz>(to_log.rfind("\n========== SPU BLOCK"sv), 1));
to_remove = to_log.size();
// 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 part %u:\n\n%s\n", part_ctr, to_log);
}
sys_log.notice("End spu.log (%u bytes)", total_size);
}
}
}
// Final termination from main thread (move the last ownership of join thread in order to destroy it)
CallFromMainThread([join_thread = std::move(join_thread), allow_autoexit, this]() mutable
{
cpu_thread::cleanup();
initialize_timebased_time(0, true);
@ -3006,64 +3067,6 @@ void Emulator::Kill(bool allow_autoexit, bool savestate)
m_state = system_state::stopped;
GetCallbacks().on_stop();
if (g_tty && sys_log.notice)
{
// Write merged TTY output after emulation has been safely stopped
if (usz attempted_read_size = utils::sub_saturate<usz>(g_tty.pos(), m_tty_file_init_pos))
{
if (fs::file tty_read_fd{fs::get_cache_dir() + "TTY.log"})
{
// Enfore an arbitrary limit for now to avoid OOM in case the guest code has bombarded TTY
// 16MB, this should be enough
constexpr usz c_max_tty_spill_size = 0x10'0000;
std::string tty_buffer(std::min<usz>(attempted_read_size, c_max_tty_spill_size), '\0');
tty_buffer.resize(tty_read_fd.read_at(m_tty_file_init_pos, tty_buffer.data(), tty_buffer.size()));
tty_read_fd.close();
if (!tty_buffer.empty())
{
// Mark start and end very clearly with RPCS3 put in it
sys_log.notice("\nAccumulated RPCS3 TTY:\n\n\n%s\n\n\nEnd RPCS3 TTY Section.\n", tty_buffer);
}
}
}
}
if (g_cfg.core.spu_debug && sys_log.notice)
{
if (fs::file spu_log{cache_path + "/spu.log"})
{
// 96MB limit, this may be a lot but this only has an effect when enabling the debug option
constexpr usz c_max_tty_spill_size = 0x60'0000;
std::string log_buffer(std::min<usz>(spu_log.size(), c_max_tty_spill_size), '\0');
log_buffer.resize(spu_log.read(log_buffer.data(), log_buffer.size()));
spu_log.close();
if (!log_buffer.empty())
{
usz to_remove = 0;
usz part_ctr = 1;
for (std::string_view not_logged = log_buffer; !not_logged.empty(); part_ctr++, not_logged.remove_prefix(to_remove))
{
std::string_view to_log = not_logged;
to_log = to_log.substr(0, 0x8'0000);
to_log = to_log.substr(0, utils::add_saturate<usz>(to_log.rfind("\n========== SPU BLOCK"sv), 1));
to_remove = to_log.size();
// 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 part %u:\n\n%s\n", part_ctr, to_log);
}
sys_log.notice("End spu.log");
}
}
}
// Always Enable display sleep, not only if it was prevented.
enable_display_sleep();