From 73ff53f01d2c83770eada2e5753931f5332eafeb Mon Sep 17 00:00:00 2001 From: Tyler Wilding Date: Sat, 22 Jun 2024 22:01:33 -0400 Subject: [PATCH] debugging: Improve event profiler utility (#3561) - Can make the event buffer larger or smaller - UI shows the current event index / size, so you know how fast it's filling up - Can save compressed, 10x reduction in filesize and Windows 11 explorer actually supports ZSTD natively now so this isn't inconvenient at all ![Screenshot 2024-06-22 000343](https://github.com/open-goal/jak-project/assets/13153231/2f7dfa41-d931-4170-a848-840cbed9be9f) > An example of almost 1 million events. Results in a 4mb file. --- common/global_profiler/GlobalProfiler.cpp | 35 ++++++++++++++++----- common/global_profiler/GlobalProfiler.h | 10 ++++-- common/log/log.cpp | 2 +- common/util/compress.cpp | 13 ++++++++ common/util/compress.h | 3 +- decompiler/ObjectFile/ObjectFileDB_IR2.cpp | 2 +- game/graphics/opengl_renderer/debug_gui.cpp | 25 ++++++++++++--- game/graphics/opengl_renderer/debug_gui.h | 2 +- game/graphics/pipelines/opengl.cpp | 18 ----------- 9 files changed, 74 insertions(+), 36 deletions(-) diff --git a/common/global_profiler/GlobalProfiler.cpp b/common/global_profiler/GlobalProfiler.cpp index 246885ab8..cdbed8af6 100644 --- a/common/global_profiler/GlobalProfiler.cpp +++ b/common/global_profiler/GlobalProfiler.cpp @@ -26,6 +26,8 @@ u64 get_current_tid() { } #endif #include "common/log/log.h" +#include "common/util/compress.h" +#include "common/util/string_util.h" // clang-format on u64 get_current_ts() { @@ -34,12 +36,12 @@ u64 get_current_ts() { GlobalProfiler::GlobalProfiler() { m_t0 = get_current_ts(); - set_max_events(65536); + m_nodes.resize(m_max_events); } -void GlobalProfiler::set_max_events(size_t event_count) { - ASSERT(!m_enabled); - m_nodes.resize(event_count); +void GlobalProfiler::update_event_buffer_size(size_t new_size) { + m_max_events = new_size; + m_nodes.resize(m_max_events); } void GlobalProfiler::set_waiting_for_event(const std::string& event_name) { @@ -72,6 +74,10 @@ void GlobalProfiler::root_event() { instant_event("ROOT"); } +size_t GlobalProfiler::get_next_idx() { + return (m_next_idx % m_nodes.size()); +} + void GlobalProfiler::begin_event(const char* name) { event(name, ProfNode::BEGIN); } @@ -96,8 +102,10 @@ void GlobalProfiler::set_enable(bool en) { m_enabled = en; } -void GlobalProfiler::dump_to_json(const std::string& path) { - ASSERT(!m_enabled); +void GlobalProfiler::dump_to_json() { + if (m_enabled) { + set_enable(false); + } nlohmann::json json; auto& trace_events = json["traceEvents"]; @@ -185,7 +193,20 @@ void GlobalProfiler::dump_to_json(const std::string& path) { t.second.highest_at_target); } - file_util::write_text_file(path, json.dump()); + if (m_enable_compression) { + const auto json_str = json.dump(); + const auto compressed_data = + compression::compress_zstd_no_header(json_str.data(), json_str.size()); + auto file_path = file_util::get_jak_project_dir() / "profile_data" / + fmt::format("prof-{}.json.zst", str_util::current_local_timestamp_no_colons()); + file_util::create_dir_if_needed_for_file(file_path); + file_util::write_binary_file(file_path, compressed_data.data(), compressed_data.size()); + } else { + auto file_path = file_util::get_jak_project_dir() / "profile_data" / + fmt::format("prof-{}.json", str_util::current_local_timestamp_no_colons()); + file_util::create_dir_if_needed_for_file(file_path); + file_util::write_text_file(file_path, json.dump()); + } } GlobalProfiler gprof; diff --git a/common/global_profiler/GlobalProfiler.h b/common/global_profiler/GlobalProfiler.h index 44c906297..fdf903f8f 100644 --- a/common/global_profiler/GlobalProfiler.h +++ b/common/global_profiler/GlobalProfiler.h @@ -17,7 +17,8 @@ struct ProfNode { class GlobalProfiler { public: GlobalProfiler(); - void set_max_events(size_t event_count); + size_t get_max_events() { return m_max_events; } + void update_event_buffer_size(size_t new_size); void set_waiting_for_event(const std::string& event_name); void instant_event(const char* name); void begin_event(const char* name); @@ -25,11 +26,16 @@ class GlobalProfiler { void end_event(); void clear(); void set_enable(bool en); - void dump_to_json(const std::string& path); + void dump_to_json(); void root_event(); + bool is_enabled() { return m_enabled; } + size_t get_next_idx(); + + bool m_enable_compression = false; private: std::atomic_bool m_enabled = false; + size_t m_max_events = 65536; u64 m_t0 = 0; std::atomic_size_t m_next_idx = 0; std::vector m_nodes; diff --git a/common/log/log.cpp b/common/log/log.cpp index dfe623b0b..8457b0cbf 100644 --- a/common/log/log.cpp +++ b/common/log/log.cpp @@ -140,7 +140,7 @@ void printstd(const char* format, va_list arg_list) { internal::log_vprintf(format, arg_list); } -// how many extra log files for a single program should be kept? +// how many extra log files for a single program should be kept constexpr int LOG_ROTATE_MAX = 10; void set_file(const std::string& filename, diff --git a/common/util/compress.cpp b/common/util/compress.cpp index 7c4aee82b..ec61030a9 100644 --- a/common/util/compress.cpp +++ b/common/util/compress.cpp @@ -46,4 +46,17 @@ std::vector decompress_zstd(const void* data, size_t size) { ASSERT(decomp_size == decompressed_size); return result; } + +std::vector compress_zstd_no_header(const void* data, size_t size) { + size_t max_compressed = ZSTD_compressBound(size); + std::vector result(max_compressed); + + size_t compressed_size = ZSTD_compress(result.data(), max_compressed, data, size, 1); + if (ZSTD_isError(compressed_size)) { + ASSERT_MSG(false, fmt::format("ZSTD error: {}", ZSTD_getErrorName(compressed_size))); + } + + result.resize(compressed_size); + return result; +} } // namespace compression diff --git a/common/util/compress.h b/common/util/compress.h index 295ccfa4f..1f15474bb 100644 --- a/common/util/compress.h +++ b/common/util/compress.h @@ -8,4 +8,5 @@ namespace compression { // compress and decompress data with zstd std::vector compress_zstd(const void* data, size_t size); std::vector decompress_zstd(const void* data, size_t size); -} // namespace compression \ No newline at end of file +std::vector compress_zstd_no_header(const void* data, size_t size); +} // namespace compression diff --git a/decompiler/ObjectFile/ObjectFileDB_IR2.cpp b/decompiler/ObjectFile/ObjectFileDB_IR2.cpp index abef0ff79..36e76e127 100644 --- a/decompiler/ObjectFile/ObjectFileDB_IR2.cpp +++ b/decompiler/ObjectFile/ObjectFileDB_IR2.cpp @@ -5,13 +5,13 @@ #include "ObjectFileDB.h" +#include "common/formatter/formatter.h" #include "common/goos/PrettyPrinter.h" #include "common/link_types.h" #include "common/log/log.h" #include "common/util/FileUtil.h" #include "common/util/Timer.h" #include "common/util/string_util.h" -#include #include "decompiler/IR2/Form.h" #include "decompiler/analysis/analyze_inspect_method.h" diff --git a/game/graphics/opengl_renderer/debug_gui.cpp b/game/graphics/opengl_renderer/debug_gui.cpp index 5dcfdda26..ba865e727 100644 --- a/game/graphics/opengl_renderer/debug_gui.cpp +++ b/game/graphics/opengl_renderer/debug_gui.cpp @@ -1,9 +1,7 @@ - #include "debug_gui.h" -#include - #include "common/global_profiler/GlobalProfiler.h" +#include "common/util/string_util.h" #include "game/graphics/display.h" #include "game/graphics/gfx.h" @@ -164,10 +162,27 @@ void OpenGlDebugGui::draw(const DmaStats& dma_stats) { } if (ImGui::BeginMenu("Event Profiler")) { - if (ImGui::Checkbox("Record", &record_events)) { + if (ImGui::Checkbox("Record Events", &record_events)) { prof().set_enable(record_events); } - ImGui::MenuItem("Dump to file", nullptr, &dump_events); + ImGui::SameLine(); + ImGui::Text(fmt::format("({}/{})", prof().get_next_idx(), prof().get_max_events()).c_str()); + ImGui::InputInt("Event Buffer Size", &max_event_buffer_size); + if (ImGui::Button("Resize")) { + prof().update_event_buffer_size(max_event_buffer_size); + } + if (ImGui::Button("Reset Events")) { + prof().clear(); + } + ImGui::Separator(); + ImGui::Checkbox("Enable Compression", &prof().m_enable_compression); + if (ImGui::Button("Dump to File")) { + record_events = false; + prof().dump_to_json(); + } + // if (ImGui::Button("Open dump folder")) { + // // TODO - https://github.com/mlabbe/nativefiledialog + // } ImGui::EndMenu(); } diff --git a/game/graphics/opengl_renderer/debug_gui.h b/game/graphics/opengl_renderer/debug_gui.h index 52c1cc2e6..7ed401b21 100644 --- a/game/graphics/opengl_renderer/debug_gui.h +++ b/game/graphics/opengl_renderer/debug_gui.h @@ -64,7 +64,7 @@ class OpenGlDebugGui { bool small_profiler = false; bool record_events = false; - bool dump_events = false; + int max_event_buffer_size = 65536; bool want_reboot_in_debug = false; bool screenshot_hotkey_enabled = true; diff --git a/game/graphics/pipelines/opengl.cpp b/game/graphics/pipelines/opengl.cpp index ec54f4040..f36bb6233 100644 --- a/game/graphics/pipelines/opengl.cpp +++ b/game/graphics/pipelines/opengl.cpp @@ -448,23 +448,6 @@ void render_game_frame(int game_width, } } -void update_global_profiler() { - if (g_gfx_data->debug_gui.dump_events) { - prof().set_enable(false); - g_gfx_data->debug_gui.dump_events = false; - - // TODO - the file rotation code had an infinite loop here if it couldn't find anything - // matching the format - // - // Does the existing log rotation code have that problem? - - auto file_path = file_util::get_jak_project_dir() / "profile_data" / - fmt::format("prof-{}.json", str_util::current_local_timestamp_no_colons()); - file_util::create_dir_if_needed_for_file(file_path); - prof().dump_to_json(file_path.string()); - } -} - void GLDisplay::process_sdl_events() { SDL_Event evt; while (SDL_PollEvent(&evt) != 0) { @@ -603,7 +586,6 @@ void GLDisplay::render() { // Start timing for the next frame. g_gfx_data->debug_gui.start_frame(); prof().instant_event("ROOT"); - update_global_profiler(); // toggle even odd and wake up engine waiting on vsync. // TODO: we could play with moving this earlier, right after the final bucket renderer.