From 078aa1ef6e004506416fe590cd4a1455d543348c Mon Sep 17 00:00:00 2001 From: Jas Laferriere Date: Thu, 19 Mar 2020 18:20:00 -0700 Subject: [PATCH] add input lag logging --- Source/Core/Core/HW/EXI_DeviceSlippi.cpp | 18 +++++++++++++-- Source/Core/Core/HW/EXI_DeviceSlippi.h | 8 ++++++- Source/Core/Core/HW/SI.cpp | 29 +++++++++++++++++++----- Source/Core/DolphinWX/Frame.h | 2 +- Source/Core/DolphinWX/FrameTools.cpp | 3 ++- 5 files changed, 49 insertions(+), 11 deletions(-) diff --git a/Source/Core/Core/HW/EXI_DeviceSlippi.cpp b/Source/Core/Core/HW/EXI_DeviceSlippi.cpp index 7af04cacba..8d6cd8c818 100644 --- a/Source/Core/Core/HW/EXI_DeviceSlippi.cpp +++ b/Source/Core/Core/HW/EXI_DeviceSlippi.cpp @@ -61,6 +61,8 @@ static std::atomic numDiffsProcessing(0); extern std::unique_ptr g_playback_status; +extern u64 g_BButtonPressTime; + template bool isFutureReady(std::future &t) { return t.wait_for(std::chrono::seconds(0)) == std::future_status::ready; @@ -1193,7 +1195,7 @@ bool CEXISlippi::shouldSkipOnlineFrame(int32_t frame) // Return true if we are too far ahead for rollback. 5 is the number of frames we can // receive for the opponent at one time and is our "look-ahead" limit int32_t latestRemoteFrame = slippi_netplay->GetSlippiLatestRemoteFrame(); - if (frame - latestRemoteFrame >= ROLLBACK_MAX_FRAMES) // TODO: 5 is rollback amount, should be a variable + if (frame - latestRemoteFrame >= ROLLBACK_MAX_FRAMES) { WARN_LOG(SLIPPI_ONLINE, "Halting for one frame due to rollback limit (frame: %d | latest: %d)...", frame, latestRemoteFrame); @@ -1383,7 +1385,7 @@ void CEXISlippi::prepareOnlineMatchState() SlippiMatchmaking::ProcessState mmState = matchmaking->GetMatchmakeState(); #ifdef LOCAL_TESTING - if (mmState != 0) + if (localSelections.isCharacterSelected) mmState = SlippiMatchmaking::ProcessState::CONNECTION_SUCCESS; #endif @@ -1550,6 +1552,18 @@ void CEXISlippi::DMAWrite(u32 _uAddr, u32 _uSize) case CMD_SET_MATCH_SELECTIONS: setMatchSelections(&memPtr[bufLoc + 1]); break; + case CMD_LOG_MESSAGE: + { + ERROR_LOG(SLIPPI, "%s: %llu", (char *)&memPtr[bufLoc + 1], Common::Timer::GetTimeUs()); + + std::string logStr = std::string((char *)&memPtr[bufLoc + 1]); + if (logStr == "Shine start") + { + NOTICE_LOG(SLIPPI, "%llu", Common::Timer::GetTimeUs() - g_BButtonPressTime); + } + + break; + } default: writeToFile(&memPtr[bufLoc], payloadLen + 1, ""); break; diff --git a/Source/Core/Core/HW/EXI_DeviceSlippi.h b/Source/Core/Core/HW/EXI_DeviceSlippi.h index 7f8774c6e8..dc5395e6ec 100644 --- a/Source/Core/Core/HW/EXI_DeviceSlippi.h +++ b/Source/Core/Core/HW/EXI_DeviceSlippi.h @@ -25,7 +25,7 @@ #define MELEE_HEAP_START 0x00bd5c40 #define MELEE_HEAP_SIZE 0x5D7960 -#define ROLLBACK_MAX_FRAMES 5 +#define ROLLBACK_MAX_FRAMES 7 // Acts class CEXISlippi : public IEXIDevice @@ -68,6 +68,9 @@ class CEXISlippi : public IEXIDevice CMD_GET_MATCH_STATE = 0xB3, CMD_FIND_OPPONENT = 0xB4, CMD_SET_MATCH_SELECTIONS = 0xB5, + + // Misc + CMD_LOG_MESSAGE = 0xD0, }; enum @@ -101,6 +104,9 @@ class CEXISlippi : public IEXIDevice {CMD_GET_MATCH_STATE, 0}, {CMD_FIND_OPPONENT, 0}, {CMD_SET_MATCH_SELECTIONS, 6}, + + // Misc + {CMD_LOG_MESSAGE, 0xFFFF}, // Variable size... will only work if by itself }; // Communication with Launcher diff --git a/Source/Core/Core/HW/SI.cpp b/Source/Core/Core/HW/SI.cpp index 21bbc23a5c..b64685b48b 100644 --- a/Source/Core/Core/HW/SI.cpp +++ b/Source/Core/Core/HW/SI.cpp @@ -9,6 +9,7 @@ #include "Common/ChunkFile.h" #include "Common/CommonTypes.h" +#include "Common/Timer.h" #include "Core/ConfigManager.h" #include "Core/CoreTiming.h" #include "Core/HW/MMIO.h" @@ -26,6 +27,8 @@ #include "InputCommon/GCAdapter.h" #include "InputCommon/GCPadStatus.h" +u64 g_BButtonPressTime = 0; + namespace SerialInterface { static CoreTiming::EventType* changeDevice; @@ -352,12 +355,16 @@ void RegisterMMIO(MMIO::Mapping* mmio, u32 base) // double msec = (diff / (double)SystemTimers::GetTicksPerSecond()) * 1000.0; - if(NetPlay::IsNetPlayRunning() && netplay_client && (netplay_client->BufferSizeForPort(c) % NetPlayClient::buffer_accuracy) != 0) - // Schedule an event to poll and send inputs earlier in the next frame - CoreTiming::ScheduleEvent(diff - (diff / NetPlayClient::buffer_accuracy) * (netplay_client->BufferSizeForPort(c) % NetPlayClient::buffer_accuracy), et_send_netplay_inputs); - - last_si_read = std::chrono::high_resolution_clock::now(); - } + // if (NetPlay::IsNetPlayRunning() && netplay_client && + // (netplay_client->BufferSizeForPort(c) % NetPlayClient::buffer_accuracy) != 0) + // Schedule an event to poll and send inputs earlier in the next frame + u32 buffer = netplay_client ? netplay_client->BufferSizeForPort(c) : 0; + CoreTiming::ScheduleEvent(diff - (diff / NetPlayClient::buffer_accuracy) * + (buffer % NetPlayClient::buffer_accuracy), + et_send_netplay_inputs); + + last_si_read = std::chrono::high_resolution_clock::now(); + } // Stop if we are not the first plugged in controller break; @@ -674,6 +681,16 @@ static void RunSIBuffer(u64 userdata, s64 cyclesLate) static void SendNetplayInputs(u64 userdata, s64 cyclesLate) { + static short prevButton = 0x0000; + + GCPadStatus status = GCAdapter::Input(0); + if (status.button & 0x0200 && !(prevButton & 0x0200)) + { + g_BButtonPressTime = Common::Timer::GetTimeUs(); + ERROR_LOG(SLIPPI, "B Press: %llu", g_BButtonPressTime); + } + prevButton = status.button; + if(netplay_client) { for(int i = 0; i < 4; i++) diff --git a/Source/Core/DolphinWX/Frame.h b/Source/Core/DolphinWX/Frame.h index 862ec3ee96..d82c2475da 100644 --- a/Source/Core/DolphinWX/Frame.h +++ b/Source/Core/DolphinWX/Frame.h @@ -176,7 +176,7 @@ class CFrame : public CRenderFrame wxTimer m_poll_hotkey_timer; wxTimer m_handle_signal_timer; - slippiTimer *m_slippi_timer; + slippiTimer *m_slippi_timer = nullptr; PlaybackSlider *seekBar = nullptr; wxStaticText *seekBarText = nullptr; diff --git a/Source/Core/DolphinWX/FrameTools.cpp b/Source/Core/DolphinWX/FrameTools.cpp index 601844d729..509e20364a 100644 --- a/Source/Core/DolphinWX/FrameTools.cpp +++ b/Source/Core/DolphinWX/FrameTools.cpp @@ -852,7 +852,8 @@ void CFrame::DoStop() if (m_Mgr->GetPane(_("Slippi Pane")).IsShown()) { m_Mgr->GetPane(_("Slippi Pane")).Hide(); - delete m_slippi_timer; + if (m_slippi_timer) + delete m_slippi_timer; } if (!m_tried_graceful_shutdown && TriggerSTMPowerEvent())