From d5c3d82e67110ad94cd781b43b8845a9c75fa8f3 Mon Sep 17 00:00:00 2001 From: HeatXD <45072324+HeatXD@users.noreply.github.com> Date: Fri, 5 May 2023 04:59:39 +0200 Subject: [PATCH] Netplay: Desync detection state dumping for debugging. Netplay: Update the overclock ratio if the loaded file savestate had an active overclock. GGPO: Make ggpo report the frame that should be freed --- dep/ggpo-x/include/ggponet.h | 2 +- dep/ggpo-x/src/backends/p2p.cpp | 2 +- dep/ggpo-x/src/backends/synctest.cpp | 2 +- dep/ggpo-x/src/sync.cpp | 4 +- src/core/netplay.cpp | 79 +++++++++++++++++++++------- src/core/system.cpp | 11 ++-- 6 files changed, 73 insertions(+), 27 deletions(-) diff --git a/dep/ggpo-x/include/ggponet.h b/dep/ggpo-x/include/ggponet.h index cb306fa1b..8888d3372 100644 --- a/dep/ggpo-x/include/ggponet.h +++ b/dep/ggpo-x/include/ggponet.h @@ -248,7 +248,7 @@ typedef struct { * free_buffer - Frees a game state allocated in save_game_state. You * should deallocate the memory contained in the buffer. */ - void (__cdecl *free_buffer)(void* context, void *buffer); + void (__cdecl *free_buffer)(void* context, void *buffer, int frame); /* * advance_frame - Called during a rollback. You should advance your game diff --git a/dep/ggpo-x/src/backends/p2p.cpp b/dep/ggpo-x/src/backends/p2p.cpp index 0bc8a388b..ce3fdcc58 100644 --- a/dep/ggpo-x/src/backends/p2p.cpp +++ b/dep/ggpo-x/src/backends/p2p.cpp @@ -520,7 +520,7 @@ void Peer2PeerBackend::CheckRemoteChecksum(int framenumber, uint32 cs) int Peer2PeerBackend::HowFarBackForChecksums()const { - return 32; + return _sync.MaxPredictionFrames() + 2; }/* uint16 Peer2PeerBackend::GetChecksumForConfirmedFrame(int frameNumber) const { diff --git a/dep/ggpo-x/src/backends/synctest.cpp b/dep/ggpo-x/src/backends/synctest.cpp index c82a9c60d..a8fbe0884 100644 --- a/dep/ggpo-x/src/backends/synctest.cpp +++ b/dep/ggpo-x/src/backends/synctest.cpp @@ -158,7 +158,7 @@ SyncTestBackend::IncrementFrame(uint16_t cs) RaiseSyncError("Checksum for frame %d does not match saved (%d != %d)", frame, checksum, info.checksum); } printf("Checksum %08d for frame %d matches.\n", checksum, info.frame); - _callbacks.free_buffer(_callbacks.context, info.buf); + _callbacks.free_buffer(_callbacks.context, info.buf, info.frame); } _last_verified = frame; _rollingback = false; diff --git a/dep/ggpo-x/src/sync.cpp b/dep/ggpo-x/src/sync.cpp index 6053d0eb2..a4e69c725 100644 --- a/dep/ggpo-x/src/sync.cpp +++ b/dep/ggpo-x/src/sync.cpp @@ -24,7 +24,7 @@ Sync::~Sync() * structure so we can efficently copy frames via weak references. */ for (int i = 0; i < _savedstate.frames.size(); i++) { - _callbacks.free_buffer(_callbacks.context, _savedstate.frames[i].buf); + _callbacks.free_buffer(_callbacks.context, _savedstate.frames[i].buf, _savedstate.frames[i].frame); } delete [] _input_queues; _input_queues = NULL; @@ -204,7 +204,7 @@ Sync::SaveCurrentFrame() */ SavedFrame *state = &_savedstate.frames[_savedstate.head]; if (state->buf) { - _callbacks.free_buffer(_callbacks.context, state->buf); + _callbacks.free_buffer(_callbacks.context, state->buf, state->frame); state->buf = NULL; } state->frame = _framecount; diff --git a/src/core/netplay.cpp b/src/core/netplay.cpp index fe7db7ca5..48577c10b 100644 --- a/src/core/netplay.cpp +++ b/src/core/netplay.cpp @@ -34,7 +34,7 @@ static bool NpAdvFrameCb(void* ctx, int flags); static bool NpSaveFrameCb(void* ctx, unsigned char** buffer, int* len, int* checksum, int frame); static bool NpLoadFrameCb(void* ctx, unsigned char* buffer, int len, int rb_frames, int frame_to_load); static bool NpBeginGameCb(void* ctx, const char* game_name); -static void NpFreeBuffCb(void* ctx, void* buffer); +static void NpFreeBuffCb(void* ctx, void* buffer, int frame); static bool NpOnEventCb(void* ctx, GGPOEvent* ev); static Input ReadLocalInput(); @@ -61,7 +61,7 @@ static void Throttle(); // Desync Detection static void GenerateChecksumForFrame(int* checksum, int frame, unsigned char* buffer, int buffer_size); - +static void GenerateDesyncReport(s32 desync_frame); ////////////////////////////////////////////////////////////////////////// // Variables ////////////////////////////////////////////////////////////////////////// @@ -83,6 +83,7 @@ static float s_target_speed = 1.0f; static Common::Timer::Value s_frame_period = 0; static Common::Timer::Value s_next_frame_time = 0; static s32 s_next_timesync_recovery_frame = -1; + } // namespace Netplay // Netplay Impl @@ -182,7 +183,7 @@ void Netplay::SetSettings() // no block linking, it degrades savestate loading performance si.SetBoolValue("CPU", "RecompilerBlockLinking", false); - // not sure its needed but enabled for now. TODO + // not sure its needed but enabled for now... TODO si.SetBoolValue("GPU", "UseSoftwareRendererForReadbacks", true); Host::Internal::SetNetplaySettingsLayer(&si); @@ -276,9 +277,41 @@ void Netplay::GenerateChecksumForFrame(int* checksum, int frame, unsigned char* const u32 num_group_of_pages = buffer_size / sliding_window_size; const u32 start_position = (frame % num_group_of_pages) * sliding_window_size; *checksum = XXH32(buffer + start_position, sliding_window_size, frame); - Log_VerbosePrintf("Netplay Checksum: f:%d wf:%d c:%u", frame, frame % num_group_of_pages, *checksum); + // Log_VerbosePrintf("Netplay Checksum: f:%d wf:%d c:%u", frame, frame % num_group_of_pages, *checksum); } +void Netplay::GenerateDesyncReport(s32 desync_frame) +{ + std::string path = "\\netplaylogs\\desync_frame_" + std::to_string(desync_frame) + "_p" + + std::to_string(s_local_handle) + "_" + System::GetRunningSerial() + "_.txt"; + std::string filename = EmuFolders::Dumps + path; + + std::unique_ptr stream = + ByteStream::OpenFile(filename.c_str(), BYTESTREAM_OPEN_CREATE | BYTESTREAM_OPEN_WRITE | BYTESTREAM_OPEN_TRUNCATE | + BYTESTREAM_OPEN_ATOMIC_UPDATE | BYTESTREAM_OPEN_STREAMED); + if (!stream) + { + Log_VerbosePrint("desync log creation failed to create stream"); + return; + } + + if (!ByteStream::WriteBinaryToStream(stream.get(), + s_save_buffer_pool.back().get()->state_stream.get()->GetMemoryPointer(), + s_save_buffer_pool.back().get()->state_stream.get()->GetMemorySize())) + { + Log_VerbosePrint("desync log creation failed to write the stream"); + stream->Discard(); + return; + } + /* stream->Write(s_save_buffer_pool.back().get()->state_stream.get()->GetMemoryPointer(), + s_save_buffer_pool.back().get()->state_stream.get()->GetMemorySize());*/ + + stream->Commit(); + + Log_VerbosePrintf("desync log created for frame %d", desync_frame); +} + + void Netplay::AdvanceFrame() { ggpo_advance_frame(s_ggpo, 0); @@ -386,6 +419,12 @@ void Netplay::StartNetplaySession(s32 local_handle, u16 local_port, std::string& // notify that the session failed if (result != GGPO_OK) Log_ErrorPrintf("Failed to Create Netplay Session! Error: %d", result); + else + { + // Load savestate if available + std::string save = EmuFolders::SaveStates + "/netplay/" + System::GetRunningSerial() + ".sav"; + System::LoadState(save.c_str()); + } } void Netplay::StopNetplaySession() @@ -436,9 +475,6 @@ bool Netplay::NpBeginGameCb(void* ctx, const char* game_name) return false; } SPU::SetAudioOutputMuted(true); - // Load savestate if available - std::string save = EmuFolders::SaveStates + "/netplay/" + System::GetRunningSerial() + ".sav"; - System::LoadState(save.c_str()); // Fast Forward to Game Start if needed. while (System::GetInternalFrameNumber() < 2) System::RunFrame(); @@ -460,25 +496,27 @@ bool Netplay::NpAdvFrameCb(void* ctx, int flags) bool Netplay::NpSaveFrameCb(void* ctx, unsigned char** buffer, int* len, int* checksum, int frame) { SaveStateBuffer our_buffer; - if (s_save_buffer_pool.empty()) + // min size is 2 because otherwise the desync logger doesnt have enough time to dump the state. + if (s_save_buffer_pool.size() < 2) { our_buffer = std::make_unique(); } else { - our_buffer = std::move(s_save_buffer_pool.back()); - s_save_buffer_pool.pop_back(); + our_buffer = std::move(s_save_buffer_pool.front()); + s_save_buffer_pool.pop_front(); } if (!System::SaveMemoryState(our_buffer.get())) { - s_save_buffer_pool.push_back(std::move(our_buffer)); + s_save_buffer_pool.push_front(std::move(our_buffer)); return false; } - GenerateChecksumForFrame(checksum, frame, - reinterpret_cast(our_buffer.get()->state_stream.get()->GetMemoryPointer()), - our_buffer.get()->state_stream.get()->GetMemorySize()); + // desync detection + const u32 state_size = our_buffer.get()->state_stream.get()->GetMemorySize(); + unsigned char* state = reinterpret_cast(our_buffer.get()->state_stream.get()->GetMemoryPointer()); + GenerateChecksumForFrame(checksum, frame, state, state_size); *len = sizeof(System::MemorySaveState); *buffer = reinterpret_cast(our_buffer.release()); @@ -494,8 +532,9 @@ bool Netplay::NpLoadFrameCb(void* ctx, unsigned char* buffer, int len, int rb_fr return System::LoadMemoryState(*reinterpret_cast(buffer)); } -void Netplay::NpFreeBuffCb(void* ctx, void* buffer) +void Netplay::NpFreeBuffCb(void* ctx, void* buffer, int frame) { + // Log_VerbosePrintf("Reuse Buffer: %d", frame); SaveStateBuffer our_buffer(reinterpret_cast(buffer)); s_save_buffer_pool.push_back(std::move(our_buffer)); } @@ -503,7 +542,7 @@ void Netplay::NpFreeBuffCb(void* ctx, void* buffer) bool Netplay::NpOnEventCb(void* ctx, GGPOEvent* ev) { char buff[128]; - std::string msg; + std::string msg, filename; switch (ev->code) { case GGPOEventCode::GGPO_EVENTCODE_CONNECTED_TO_PEER: @@ -542,11 +581,13 @@ bool Netplay::NpOnEventCb(void* ctx, GGPOEvent* ev) HandleTimeSyncEvent(ev->u.timesync.frames_ahead, ev->u.timesync.timeSyncPeriodInFrames); break; case GGPOEventCode::GGPO_EVENTCODE_DESYNC: - sprintf(buff, "Possible Desync Detected: Frame: %d, L:%u, R:%u", ev->u.desync.nFrameOfDesync, - ev->u.desync.ourCheckSum, ev->u.desync.remoteChecksum); + sprintf(buff, "Desync Detected: Current Frame: %d, Desync Frame: %d, Diff: %d, L:%u, R:%u", CurrentFrame(), + ev->u.desync.nFrameOfDesync, CurrentFrame() - ev->u.desync.nFrameOfDesync, ev->u.desync.ourCheckSum, + ev->u.desync.remoteChecksum); msg = buff; - Log_InfoPrintf("%s", msg.c_str()); + GenerateDesyncReport(ev->u.desync.nFrameOfDesync); Host::AddKeyedOSDMessage("Netplay", msg, 5); + return true; default: sprintf(buff, "Netplay Event Code: %d", ev->code); diff --git a/src/core/system.cpp b/src/core/system.cpp index bc715b1ec..3704ba65f 100644 --- a/src/core/system.cpp +++ b/src/core/system.cpp @@ -1756,12 +1756,17 @@ bool System::DoState(StateWrapper& sw, GPUTexture** host_texture, bool update_di // during netplay if a file savestate is loaded set // the overclocks to the same value as the savestate // file savestates are usually only loaded at game start - if (Netplay::IsActive() && !is_memory_state) + if (Netplay::IsActive() && !is_memory_state && cpu_overclock_active) { - g_settings.cpu_overclock_enable = true; - g_settings.cpu_overclock_active = cpu_overclock_active; + g_settings.cpu_overclock_enable = cpu_overclock_active; g_settings.cpu_overclock_numerator = cpu_overclock_numerator; g_settings.cpu_overclock_denominator = cpu_overclock_denominator; + + g_settings.UpdateOverclockActive(); + + Host::AddFormattedOSDMessage(10.0f, + Host::TranslateString("OSDMessage", "WARNING: CPU overclock was changed to (%u%%) to match netplay savestate."), + g_settings.cpu_overclock_enable ? g_settings.GetCPUOverclockPercent() : 100u ); } UpdateOverclock();