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

@@ -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) {
+void GlobalProfiler::update_event_buffer_size(size_t new_size) {
-  ASSERT(!m_enabled);
+  m_max_events = new_size;
-  m_nodes.resize(event_count);
+  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) {
+void GlobalProfiler::dump_to_json() {
-  ASSERT(!m_enabled);
+  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;

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<ProfNode> m_nodes;

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,

common/util/compress.cpp

@@ -46,4 +46,17 @@ std::vector<u8> decompress_zstd(const void* data, size_t size) {
   ASSERT(decomp_size == decompressed_size);
   return result;
 }
+
+std::vector<u8> compress_zstd_no_header(const void* data, size_t size) {
+  size_t max_compressed = ZSTD_compressBound(size);
+  std::vector<u8> 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

common/util/compress.h

@@ -8,4 +8,5 @@ namespace compression {
 // compress and decompress data with zstd
 std::vector<u8> compress_zstd(const void* data, size_t size);
 std::vector<u8> decompress_zstd(const void* data, size_t size);
+std::vector<u8> compress_zstd_no_header(const void* data, size_t size);
 }  // namespace compression

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 <common/formatter/formatter.h>
 
 #include "decompiler/IR2/Form.h"
 #include "decompiler/analysis/analyze_inspect_method.h"

game/graphics/opengl_renderer/debug_gui.cpp

@@ -1,9 +1,7 @@
-
 #include "debug_gui.h"
 
-#include <algorithm>
-
 #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();
     }
 

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;

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.