add input lag logging

project-slippi · Mar 20, 2020 · 078aa1e · 078aa1e
1 parent f5afaff
commit 078aa1e
Show file tree

Hide file tree

Showing 5 changed files with 49 additions and 11 deletions.
diff --git a/Source/Core/Core/HW/EXI_DeviceSlippi.cpp b/Source/Core/Core/HW/EXI_DeviceSlippi.cpp
@@ -61,6 +61,8 @@ static std::atomic<int> numDiffsProcessing(0);
 
 extern std::unique_ptr<SlippiPlaybackStatus> g_playback_status;
 
+extern u64 g_BButtonPressTime;
+
 template <typename T> bool isFutureReady(std::future<T> &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
@@ -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
@@ -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
@@ -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
@@ -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())