tracing: add some more startup related events and a new --profile-until-event flag (#3385)

While trying to narrow down why sometimes SDL takes 20-40seconds to
initialize I built up some more profiling features.

TLDR - I still don't know why SDL is taking a long time but I've
narrowed it down to it initializing the `GAME_CONTROLLER` subsystem.
This isn't unprecedented, I found numerous github issues and articles
suggesting this is the problem:

![image](https://github.com/open-goal/jak-project/assets/13153231/1853326b-7a40-458e-87a0-f7a9f44781e3)

I imagine it is hardware/OS related on some level, there are even some
recent commits in SDL that have made it worse on certain platforms. I've
had this problem myself so I will hope to get it again soon so i can
debug where in the SDL code the delay occurs and make a proper bug
report. Hopefully this helps but it's not yet confirmed -
https://github.com/open-goal/jak-project/pull/3384

common/global_profiler/GlobalProfiler.cpp

@@ -42,8 +42,17 @@ void GlobalProfiler::set_max_events(size_t event_count) {
   m_nodes.resize(event_count);
 }
 
+void GlobalProfiler::set_waiting_for_event(const std::string& event_name) {
+  if (!event_name.empty()) {
+    m_waiting_for_event = event_name;
+  }
+}
+
 void GlobalProfiler::event(const char* name, ProfNode::Kind kind) {
-  if (!m_enabled) {
+  if (m_waiting_for_event && m_waiting_for_event.value() == name) {
+    m_ignore_events = true;
+  }
+  if (!m_enabled || m_ignore_events) {
     return;
   }
   size_t my_idx = (m_next_idx++ % m_nodes.size());
@@ -68,7 +77,7 @@ void GlobalProfiler::begin_event(const char* name) {
 }
 
 void GlobalProfiler::end_event() {
-  if (!m_enabled) {
+  if (!m_enabled || m_ignore_events) {
     return;
   }
   size_t my_idx = (m_next_idx++ % m_nodes.size());

common/global_profiler/GlobalProfiler.h

@@ -1,6 +1,7 @@
 #pragma once
 
 #include <atomic>
+#include <optional>
 #include <string>
 #include <vector>
 
@@ -17,6 +18,7 @@ class GlobalProfiler {
  public:
   GlobalProfiler();
   void set_max_events(size_t event_count);
+  void set_waiting_for_event(const std::string& event_name);
   void instant_event(const char* name);
   void begin_event(const char* name);
   void event(const char* name, ProfNode::Kind kind);
@@ -31,6 +33,11 @@ class GlobalProfiler {
   u64 m_t0 = 0;
   std::atomic_size_t m_next_idx = 0;
   std::vector<ProfNode> m_nodes;
+  // this is very niche, but sometimes you want to capture up to a given event (ie. long startup)
+  // instead of having to make the user quit and record as fast as possible, we can instead just
+  // stop capturing events once we have received what we are looking for
+  std::optional<std::string> m_waiting_for_event = {};
+  bool m_ignore_events = false;
 };
 
 struct ScopedEvent {

game/graphics/gfx.cpp

@@ -74,7 +74,7 @@ u32 Init(GameVersion version) {
     {
       auto p = scoped_prof("startup::gfx::init_main_display");
       std::string title = "OpenGOAL";
-      if (g_game_version == GameVersion::Jak2) {
+      if (g_game_version == GameVersion::Jak2 || g_game_version == GameVersion::Jak3) {
         title += " - Work in Progress";
       }
       title += fmt::format(" - {} - {}", version_to_game_name_external(g_game_version),

game/graphics/pipelines/opengl.cpp

@@ -100,7 +100,7 @@ static int gl_init(GfxGlobalSettings& settings) {
     auto p = scoped_prof("startup::sdl::init_sdl");
     // remove SDL garbage from hooking signal handler.
     SDL_SetHint(SDL_HINT_NO_SIGNAL_HANDLERS, "1");
-    if (SDL_Init(SDL_INIT_VIDEO | SDL_INIT_GAMECONTROLLER) != 0) {
+    if (SDL_Init(SDL_INIT_VIDEO) != 0) {
       sdl_util::log_error("Could not initialize SDL, exiting");
       dialogs::create_error_message_dialog("Critical Error Encountered",
                                            "Could not initialize SDL, exiting");
@@ -492,8 +492,8 @@ void GLDisplay::render() {
   // Before we process the current frames SDL events we for keyboard/mouse button inputs.
   //
   // This technically means that keyboard/mouse button inputs will be a frame behind but the
-  // event-based code is buggy and frankly not worth stressing over.  Leaving this as a note incase
-  // someone complains. Binding handling is still taken care of by the event code though.
+  // event-based code is limiting (there aren't enough events to achieve a totally stateless
+  // approach). Binding handling is still taken care of by the event code though.
   {
     auto p = scoped_prof("sdl-input-monitor-poll-for-kb-mouse");
     ImGuiIO& io = ImGui::GetIO();

game/main.cpp

@@ -96,6 +96,7 @@ int main(int argc, char** argv) {
   bool disable_avx2 = false;
   bool disable_display = false;
   bool enable_profiling = false;
+  std::string profile_until_event = "";
   std::string gpu_test = "";
   std::string gpu_test_out_path = "";
   int port_number = -1;
@@ -111,6 +112,8 @@ int main(int argc, char** argv) {
   app.add_flag("--no-avx2", disable_avx2, "Disable AVX2 for testing");
   app.add_flag("--no-display", disable_display, "Disable video display");
   app.add_flag("--profile", enable_profiling, "Enables profiling immediately from startup");
+  app.add_option("--profile-until-event", profile_until_event,
+                 "Stops recording profile events once an event with this name is seen");
   app.add_option("--gpu-test", gpu_test,
                  "Tests for minimum graphics requirements.  Valid Options are: [opengl]");
   app.add_option("--gpu-test-out-path", gpu_test_out_path,
@@ -141,6 +144,7 @@ int main(int argc, char** argv) {
   }
 
   prof().set_enable(enable_profiling);
+  prof().set_waiting_for_event(profile_until_event);
 
   // Create struct with all non-kmachine handled args to pass to the runtime
   GameLaunchOptions game_options;

game/system/hid/display_manager.cpp

@@ -2,30 +2,41 @@
 
 #include "sdl_util.h"
 
+#include "common/global_profiler/GlobalProfiler.h"
+
 #include "third-party/fmt/core.h"
 #include "third-party/fmt/format.h"
 
 DisplayManager::DisplayManager(SDL_Window* window)
     : m_window(window), m_selected_fullscreen_display_id(0) {
+  prof().instant_event("ROOT");
+  {
+    auto p = scoped_prof("display_manager::init");
 #ifdef _WIN32
-  // Windows hint to disable OS level forced scaling and allow native resolution at non 100% scales
-  SetProcessDPIAware();
+    // Windows hint to disable OS level forced scaling and allow native resolution at non 100%
+    // scales
+    SetProcessDPIAware();
 #endif
-  update_curr_display_info();
-  update_video_modes();
-  // Load display settings from a file
-  m_display_settings = game_settings::DisplaySettings();
-  // Adjust window / monitor position
-  initialize_window_position_from_settings();
+    update_curr_display_info();
+    update_video_modes();
+    // Load display settings from a file
+    m_display_settings = game_settings::DisplaySettings();
+    // Adjust window / monitor position
+    initialize_window_position_from_settings();
+  }
 }
 
 DisplayManager::~DisplayManager() {
-  if (m_window_display_mode == WindowDisplayMode::Windowed) {
-    m_display_settings.display_id = m_active_display_id;
-    m_display_settings.window_xpos = m_window_xpos;
-    m_display_settings.window_ypos = m_window_ypos;
+  prof().instant_event("ROOT");
+  {
+    auto p = scoped_prof("display_manager::destroy");
+    if (m_window_display_mode == WindowDisplayMode::Windowed) {
+      m_display_settings.display_id = m_active_display_id;
+      m_display_settings.window_xpos = m_window_xpos;
+      m_display_settings.window_ypos = m_window_ypos;
+    }
+    m_display_settings.save_settings();
   }
-  m_display_settings.save_settings();
 }
 
 void DisplayManager::initialize_window_position_from_settings() {

game/system/hid/input_manager.cpp

@@ -6,6 +6,7 @@
 #include "input_manager.h"
 #include "sdl_util.h"
 
+#include "common/global_profiler/GlobalProfiler.h"
 #include "common/log/log.h"
 #include "common/util/Assert.h"
 #include "common/util/FileUtil.h"
@@ -18,94 +19,118 @@
 InputManager::InputManager()
     // Load user settings
     : m_settings(std::make_shared<game_settings::InputSettings>(game_settings::InputSettings())) {
-  // Update to latest controller DB file
-  std::string mapping_path =
-      (file_util::get_jak_project_dir() / "game" / "assets" / "sdl_controller_db.txt").string();
-  if (file_util::file_exists(mapping_path)) {
-    SDL_GameControllerAddMappingsFromFile(mapping_path.c_str());
-  } else {
-    lg::error("Could not find SDL Controller DB at path `{}`", mapping_path);
-  }
-  // Initialize atleast 2 ports, because that's normal for Jak
-  // more will be allocated if more controllers are found
-  m_data[0] = std::make_shared<PadData>();
-  m_data[1] = std::make_shared<PadData>();
-  m_keyboard = KeyboardDevice(m_settings);
-  m_mouse = MouseDevice(m_settings);
+  prof().instant_event("ROOT");
+  {
+    auto p = scoped_prof("input_manager::init");
+    {
+      auto p = scoped_prof("input_manager::init::sdl_init_subsystem");
+      // initializing the controllers on startup can sometimes take a very long time
+      // so we isolate that to here instead
+      if (SDL_InitSubSystem(SDL_INIT_GAMECONTROLLER) != 0) {
+        sdl_util::log_error(
+            "Could not initialize SDL Controller support, controllers will not work!");
+      }
+    }
 
-  if (m_data.find(m_keyboard_and_mouse_port) == m_data.end()) {
-    m_data[m_keyboard_and_mouse_port] = std::make_shared<PadData>();
+    // Update to latest controller DB file
+    std::string mapping_path =
+        (file_util::get_jak_project_dir() / "game" / "assets" / "sdl_controller_db.txt").string();
+    if (file_util::file_exists(mapping_path)) {
+      SDL_GameControllerAddMappingsFromFile(mapping_path.c_str());
+    } else {
+      lg::error("Could not find SDL Controller DB at path `{}`", mapping_path);
+    }
+    // Initialize atleast 2 ports, because that's normal for Jak
+    // more will be allocated if more controllers are found
+    m_data[0] = std::make_shared<PadData>();
+    m_data[1] = std::make_shared<PadData>();
+    m_keyboard = KeyboardDevice(m_settings);
+    m_mouse = MouseDevice(m_settings);
+
+    if (m_data.find(m_keyboard_and_mouse_port) == m_data.end()) {
+      m_data[m_keyboard_and_mouse_port] = std::make_shared<PadData>();
+    }
+    m_command_binds = CommandBindingGroups();
+    refresh_device_list();
+    ignore_background_controller_events(false);
+    hide_cursor(m_auto_hide_mouse);
   }
-  m_command_binds = CommandBindingGroups();
-  refresh_device_list();
-  ignore_background_controller_events(false);
-  hide_cursor(m_auto_hide_mouse);
 }
 
 InputManager::~InputManager() {
-  for (auto& device : m_available_controllers) {
-    device->close_device();
+  prof().instant_event("ROOT");
+  {
+    auto p = scoped_prof("input_manager::destroy");
+    for (auto& device : m_available_controllers) {
+      device->close_device();
+    }
+    m_settings->save_settings();
   }
-  m_settings->save_settings();
 }
 
 void InputManager::refresh_device_list() {
-  m_available_controllers.clear();
-  m_controller_port_mapping.clear();
-  // Enumerate devices
-  // TODO - if this was done on a separate thread, there would be no hitch in the game thread
-  // but of course, that presents other synchronization challenges.
-  const auto num_joysticks = SDL_NumJoysticks();
-  if (num_joysticks > 0) {
-    for (int i = 0; i < num_joysticks; i++) {
-      if (!SDL_IsGameController(i)) {
-        lg::error("Controller with device id {} is not avaiable via the GameController API", i);
-        continue;
+  prof().instant_event("ROOT");
+  {
+    auto p = scoped_prof("input_manager::refresh_device_list");
+    m_available_controllers.clear();
+    m_controller_port_mapping.clear();
+    // Enumerate devices
+    // TODO - if this was done on a separate thread, there would be no hitch in the game thread
+    // but of course, that presents other synchronization challenges.
+    const auto num_joysticks = SDL_NumJoysticks();
+    if (num_joysticks > 0) {
+      for (int i = 0; i < num_joysticks; i++) {
+        if (!SDL_IsGameController(i)) {
+          lg::error("Controller with device id {} is not avaiable via the GameController API", i);
+          continue;
+        }
+        auto controller = std::make_shared<GameController>(i, m_settings);
+        if (!controller->is_loaded()) {
+          lg::error("Unable to successfully connect to GameController with id {}, skipping", i);
+          continue;
+        }
+        m_available_controllers.push_back(controller);
+        // By default, controller port mapping is on a first-come-first-served basis
+        //
+        // However, we will use previously saved controller port mappings to take precedence
+        // For example, if you previous set your PS5 controller to be port 0, then even
+        // if another controller is detected first, the PS5 controller should be assigned as
+        // expected.
+        if (m_settings->controller_port_mapping.find(controller->get_guid()) !=
+            m_settings->controller_port_mapping.end()) {
+          // Though it's possible for a user to assign multiple controllers to the same port, so the
+          // last one wins
+          m_controller_port_mapping[m_settings->controller_port_mapping.at(
+              controller->get_guid())] = i;
+        } else {
+          m_controller_port_mapping[m_available_controllers.size() - 1] = i;
+          m_settings->controller_port_mapping[controller->get_guid()] =
+              m_available_controllers.size() - 1;
+        }
+        // Allocate a PadData if this is a new port
+        if (m_data.find(i) == m_data.end()) {
+          m_data[i] = std::make_shared<PadData>();
+        }
       }
-      auto controller = std::make_shared<GameController>(i, m_settings);
-      if (!controller->is_loaded()) {
-        lg::error("Unable to successfully connect to GameController with id {}, skipping", i);
-        continue;
-      }
-      m_available_controllers.push_back(controller);
-      // By default, controller port mapping is on a first-come-first-served basis
-      //
-      // However, we will use previously saved controller port mappings to take precedence
-      // For example, if you previous set your PS5 controller to be port 0, then even
-      // if another controller is detected first, the PS5 controller should be assigned as expected.
-      if (m_settings->controller_port_mapping.find(controller->get_guid()) !=
-          m_settings->controller_port_mapping.end()) {
-        // Though it's possible for a user to assign multiple controllers to the same port, so the
-        // last one wins
-        m_controller_port_mapping[m_settings->controller_port_mapping.at(controller->get_guid())] =
-            i;
-      } else {
-        m_controller_port_mapping[m_available_controllers.size() - 1] = i;
-        m_settings->controller_port_mapping[controller->get_guid()] =
-            m_available_controllers.size() - 1;
-      }
-      // Allocate a PadData if this is a new port
-      if (m_data.find(i) == m_data.end()) {
-        m_data[i] = std::make_shared<PadData>();
-      }
-    }
-    // If the controller that was last selected to be port 0 is around, prioritize it
-    if (!m_settings->last_selected_controller_guid.empty()) {
-      for (size_t i = 0; i < m_available_controllers.size(); i++) {
-        const auto& controller_guid = m_available_controllers.at(i)->get_guid();
-        if (controller_guid == m_settings->last_selected_controller_guid) {
-          m_controller_port_mapping[0] = i;
-          m_settings->controller_port_mapping[controller_guid] = 0;
-          break;
+      // If the controller that was last selected to be port 0 is around, prioritize it
+      if (!m_settings->last_selected_controller_guid.empty()) {
+        for (size_t i = 0; i < m_available_controllers.size(); i++) {
+          const auto& controller_guid = m_available_controllers.at(i)->get_guid();
+          if (controller_guid == m_settings->last_selected_controller_guid) {
+            m_controller_port_mapping[0] = i;
+            m_settings->controller_port_mapping[controller_guid] = 0;
+            break;
+          }
         }
       }
     }
-  }
-  if (m_available_controllers.empty()) {
-    lg::warn(
-        "No active game controllers could be found or loaded successfully - inputs will not work!");
-  } else {
-    lg::info("Found {} controllers", m_available_controllers.size());
+    if (m_available_controllers.empty()) {
+      lg::warn(
+          "No active game controllers could be found or loaded successfully - inputs will not "
+          "work!");
+    } else {
+      lg::info("Found {} controllers", m_available_controllers.size());
+    }
   }
 }