From 1cc20508e910f35f581105a15a57dbb75ecb9caa Mon Sep 17 00:00:00 2001 From: Tyler Wilding Date: Fri, 23 Feb 2024 14:44:17 -0500 Subject: [PATCH] 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 | 13 +- common/global_profiler/GlobalProfiler.h | 7 + game/graphics/gfx.cpp | 2 +- game/graphics/pipelines/opengl.cpp | 6 +- game/main.cpp | 4 + game/system/hid/display_manager.cpp | 37 +++-- game/system/hid/input_manager.cpp | 175 ++++++++++++---------- 7 files changed, 150 insertions(+), 94 deletions(-) diff --git a/common/global_profiler/GlobalProfiler.cpp b/common/global_profiler/GlobalProfiler.cpp index 3000c46f36..269d2b3569 100644 --- a/common/global_profiler/GlobalProfiler.cpp +++ b/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()); diff --git a/common/global_profiler/GlobalProfiler.h b/common/global_profiler/GlobalProfiler.h index e00f279d21..44c9062972 100644 --- a/common/global_profiler/GlobalProfiler.h +++ b/common/global_profiler/GlobalProfiler.h @@ -1,6 +1,7 @@ #pragma once #include +#include #include #include @@ -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 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 m_waiting_for_event = {}; + bool m_ignore_events = false; }; struct ScopedEvent { diff --git a/game/graphics/gfx.cpp b/game/graphics/gfx.cpp index 78259aa42f..3762851f2b 100644 --- a/game/graphics/gfx.cpp +++ b/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), diff --git a/game/graphics/pipelines/opengl.cpp b/game/graphics/pipelines/opengl.cpp index 9d68a8fb46..d5f1d530ab 100644 --- a/game/graphics/pipelines/opengl.cpp +++ b/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(); diff --git a/game/main.cpp b/game/main.cpp index 195bf16e5b..edff28b3e1 100644 --- a/game/main.cpp +++ b/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; diff --git a/game/system/hid/display_manager.cpp b/game/system/hid/display_manager.cpp index 7b12936d93..437d1b2a5f 100644 --- a/game/system/hid/display_manager.cpp +++ b/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() { diff --git a/game/system/hid/input_manager.cpp b/game/system/hid/input_manager.cpp index b1f2dea661..30b3f09e5c 100644 --- a/game/system/hid/input_manager.cpp +++ b/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())) { - // 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(); - m_data[1] = std::make_shared(); - 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(); + // 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(); + m_data[1] = std::make_shared(); + 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(); + } + 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(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(); + } } - auto controller = std::make_shared(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(); - } - } - // 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()); + } } }