From b91e872f5f583e1707088394f6b48261ea8d069a Mon Sep 17 00:00:00 2001 From: BruebachL <44814898+BruebachL@users.noreply.github.com> Date: Sun, 23 Aug 2026 00:03:52 +0200 Subject: [PATCH] [Network] Measure real server round-trip times (#7153) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * [Network] Measure real server round-trip times Time each command container from send to response with QElapsedTimer, aggregate samples in a fixed-size ring buffer (last/median/p95/max), and emit aggregated pingStatsUpdated at most once per second so the hot path stays free of signal traffic. Stats are cleared on disconnect. Forward the signal through ConnectionController for UI consumers. Unit-tested in latency_tracker_test. Took 37 minutes Took 4 minutes # Commit time for manual adjustment: # Took 8 minutes * Move params to struct, more informative debug Took 56 seconds Took 53 seconds Took 2 minutes Took 33 seconds --------- Co-authored-by: Lukas Brübach --- .../remote_connection_controller.cpp | 2 + .../remote_connection_controller.h | 4 + .../network/client/abstract/CMakeLists.txt | 4 +- .../client/abstract/abstract_client.cpp | 57 +++++++ .../network/client/abstract/abstract_client.h | 33 ++++ .../client/abstract/latency_tracker.cpp | 60 +++++++ .../network/client/abstract/latency_tracker.h | 51 ++++++ .../network/client/remote/remote_client.cpp | 1 + .../protocol/pending_command.cpp | 10 ++ .../libcockatrice/protocol/pending_command.h | 14 ++ tests/CMakeLists.txt | 6 + tests/latency_tracker_test.cpp | 149 ++++++++++++++++++ 12 files changed, 389 insertions(+), 2 deletions(-) create mode 100644 libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.cpp create mode 100644 libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.h create mode 100644 tests/latency_tracker_test.cpp diff --git a/cockatrice/src/client/network/connection_controller/remote_connection_controller.cpp b/cockatrice/src/client/network/connection_controller/remote_connection_controller.cpp index 53dde125f..890a621c8 100644 --- a/cockatrice/src/client/network/connection_controller/remote_connection_controller.cpp +++ b/cockatrice/src/client/network/connection_controller/remote_connection_controller.cpp @@ -44,6 +44,8 @@ void ConnectionController::wireClientSignals() connect(remoteClient, &RemoteClient::statusChanged, this, &ConnectionController::onStatusChanged); + connect(remoteClient, &AbstractClient::pingStatsUpdated, this, &ConnectionController::pingStatsUpdated); + connect(remoteClient, &RemoteClient::userInfoChanged, this, &ConnectionController::onUserInfoReceived, Qt::BlockingQueuedConnection); diff --git a/cockatrice/src/client/network/connection_controller/remote_connection_controller.h b/cockatrice/src/client/network/connection_controller/remote_connection_controller.h index 7486bc81a..bae99a3e0 100644 --- a/cockatrice/src/client/network/connection_controller/remote_connection_controller.h +++ b/cockatrice/src/client/network/connection_controller/remote_connection_controller.h @@ -54,6 +54,10 @@ signals: // action enable/disable logic void statusChanged(ClientStatus status); + // Forwarded from AbstractClient::pingStatsUpdated. See that signal for the + // meaning of the parameters. + void pingStatsUpdated(const LatencyTracker::Stats &stats, const QList &samplesMs); + private slots: // Slots wired directly to RemoteClient signals void onStatusChanged(ClientStatus status); diff --git a/libcockatrice_network/libcockatrice/network/client/abstract/CMakeLists.txt b/libcockatrice_network/libcockatrice/network/client/abstract/CMakeLists.txt index c4a8e4648..6fba8d629 100644 --- a/libcockatrice_network/libcockatrice/network/client/abstract/CMakeLists.txt +++ b/libcockatrice_network/libcockatrice/network/client/abstract/CMakeLists.txt @@ -2,9 +2,9 @@ set(CMAKE_AUTOMOC ON) set(CMAKE_AUTOUIC ON) set(CMAKE_AUTORCC ON) -set(HEADERS abstract_client.h) +set(HEADERS abstract_client.h latency_tracker.h) -set(SOURCES abstract_client.cpp) +set(SOURCES abstract_client.cpp latency_tracker.cpp) qt6_wrap_cpp(MOC_SOURCES ${HEADERS}) diff --git a/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.cpp b/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.cpp index 916f4351b..d6316deb3 100644 --- a/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.cpp +++ b/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.cpp @@ -1,6 +1,7 @@ #include "abstract_client.h" #include +#include #include #include #include @@ -28,6 +29,7 @@ AbstractClient::AbstractClient(QObject *parent) qRegisterMetaType("Response"); qRegisterMetaType("Response::ResponseCode"); qRegisterMetaType("ClientStatus"); + qRegisterMetaType("LatencyTracker::Stats"); qRegisterMetaType("RoomEvent"); qRegisterMetaType("GameEventContainer"); qRegisterMetaType("Event_ServerIdentification"); @@ -71,6 +73,8 @@ void AbstractClient::processProtocolItem(const ServerMessage &item) } pendingCommands.remove(cmdId); + recordLatency(*pend); + pend->processResponse(response); pend->deleteLater(); break; @@ -161,9 +165,62 @@ void AbstractClient::queuePendingCommand(PendingCommand *pend) pendingCommands.insert(cmdId, pend); + pend->startTiming(); sendCommandContainer(pend->getCommandContainer()); } +namespace +{ +constexpr int STATS_EMIT_INTERVAL_MS = 1000; +// Game actions are what players perceive as lag. Surface unusually slow ones +// without requiring debug logging to be enabled. +constexpr qint64 SLOW_GAME_COMMAND_WARN_MS = 1500; +} // namespace + +void AbstractClient::recordLatency(PendingCommand &pend) +{ + const qint64 elapsed = pend.elapsedMs(); + if (elapsed < 0) { + return; + } + + latencyTracker.addSample(elapsed); + + if (AbstractClientLog().isDebugEnabled()) { + qCDebug(AbstractClientLog).noquote() + << "command RTT:" << elapsed << "ms (cmd_id" << pend.getCommandContainer().cmd_id() << ")"; + } + + if (elapsed >= SLOW_GAME_COMMAND_WARN_MS && pend.getCommandContainer().game_command_size() > 0) { + qCWarning(AbstractClientLog).noquote() + << "slow game command round trip:" << elapsed << "ms | " << getSafeDebugString(pend.getCommandContainer()); + } + + // Emit aggregated stats at most once per StatsEmitIntervalMs so that the + // per-command hot path stays free of signal traffic. The keepalive ping + // guarantees a fresh sample roughly every second while connected. + if (!statsEmitClockStarted || statsEmitClock.elapsed() >= STATS_EMIT_INTERVAL_MS) { + statsEmitClock.start(); + statsEmitClockStarted = true; + const LatencyTracker::Stats stats = latencyTracker.stats(); + + QList samples; + samples.reserve(stats.sampleCount); + for (qint64 sample : latencyTracker.recentSamples()) { + samples.append(static_cast(sample)); + } + + emit pingStatsUpdated(stats, samples); + } +} + +void AbstractClient::clearLatencyStats() +{ + latencyTracker.clear(); + statsEmitClockStarted = false; + emit pingStatsUpdated(LatencyTracker::Stats{}, {}); +} + PendingCommand *AbstractClient::prepareSessionCommand(const ::google::protobuf::Message &cmd) { CommandContainer cont; diff --git a/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.h b/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.h index 982aa6bf3..1ef9a31e4 100644 --- a/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.h +++ b/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.h @@ -7,11 +7,17 @@ #ifndef ABSTRACTCLIENT_H #define ABSTRACTCLIENT_H +#include "latency_tracker.h" + +#include +#include #include #include #include #include +inline Q_LOGGING_CATEGORY(AbstractClientLog, "abstract_client"); + class PendingCommand; class CommandContainer; class RoomEvent; @@ -54,6 +60,18 @@ signals: void statusChanged(ClientStatus _status); void maxPingTime(int seconds, int maxSeconds); + /** + * @brief Aggregated round-trip statistics and a chronological snapshot of + * the rolling window, emitted at most once per second. + * + * All values in the stats struct are in milliseconds; sampleCount is the + * number of samples currently in the rolling window. The samples list is + * ordered oldest first so graphs can redraw without polling the tracker + * across threads. Emitted from the client thread. The connection to UI + * objects is automatically queued across threads. + */ + void pingStatsUpdated(const LatencyTracker::Stats &stats, const QList &samplesMs); + // Room events void roomEventReceived(const RoomEvent &event); // Game events @@ -85,6 +103,11 @@ private: int nextCmdId; mutable QMutex clientMutex; ClientStatus status; + LatencyTracker latencyTracker; + QElapsedTimer statsEmitClock; + bool statsEmitClockStarted = false; + + void recordLatency(PendingCommand &pend); private slots: void queuePendingCommand(PendingCommand *pend); protected slots: @@ -113,6 +136,16 @@ public: void sendCommand(const CommandContainer &cont); void sendCommand(PendingCommand *pend); + /** + * @brief Drops all recorded round-trip samples and resets the stats + * emission throttle, emitting zeroed stats so that UI listeners can + * clear their display. + * + * Must be called from the client thread (as RemoteClient's disconnect + * path does). The tracker is deliberately lock-free. + */ + void clearLatencyStats(); + bool getServerSupportsPasswordHash() const { return serverSupportsPasswordHash; diff --git a/libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.cpp b/libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.cpp new file mode 100644 index 000000000..98b353fdf --- /dev/null +++ b/libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.cpp @@ -0,0 +1,60 @@ +#include "latency_tracker.h" + +#include +#include + +void LatencyTracker::addSample(qint64 ms) +{ + samples[static_cast(head)] = ms; + head = (head + 1) % WindowSize; + if (count < WindowSize) { + ++count; + } +} + +QList LatencyTracker::recentSamples() const +{ + QList result; + result.reserve(count); + for (int i = count; i > 0; --i) { + const int index = (head + WindowSize - i) % WindowSize; + result.append(samples[static_cast(index)]); + } + return result; +} + +LatencyTracker::Stats LatencyTracker::stats() const +{ + if (count == 0) { + return {}; + } + + QList sorted(samples.cbegin(), samples.cbegin() + count); + std::sort(sorted.begin(), sorted.end()); + + Stats s; + s.sampleCount = count; + s.lastMs = samples[static_cast((head + WindowSize - 1) % WindowSize)]; + s.maxMs = sorted.last(); + + const int n = count; + if (n % 2 == 1) { + s.medianMs = sorted[n / 2]; + } else { + s.medianMs = (sorted[n / 2 - 1] + sorted[n / 2]) / 2; + } + + // Nearest-rank percentile: smallest value in the list such that at least + // 95% of the samples are <= it. + const int p95Index = qMax(0, qCeil(0.95 * static_cast(n)) - 1); + s.p95Ms = sorted[p95Index]; + + return s; +} + +void LatencyTracker::clear() +{ + samples.fill(0); + head = 0; + count = 0; +} diff --git a/libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.h b/libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.h new file mode 100644 index 000000000..75f18ac0c --- /dev/null +++ b/libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.h @@ -0,0 +1,51 @@ +/** + * @file latency_tracker.h + * @ingroup Client + */ + +#ifndef LATENCY_TRACKER_H +#define LATENCY_TRACKER_H + +#include +#include +#include + +/** + * @brief Fixed-capacity rolling window of network round-trip time samples. + * + * The hot path (addSample) is a single array store and is intentionally free of + * allocations, locks, or signal emissions so that recording one sample per + * completed command cannot affect gameplay performance. Aggregate statistics + * are only computed on demand in stats(), which callers should throttle. + */ +class LatencyTracker +{ +public: + static constexpr int WindowSize = 64; + + struct Stats + { + qint64 lastMs = 0; ///< most recently added sample + qint64 medianMs = 0; ///< median over the current window + qint64 p95Ms = 0; ///< 95th percentile over the current window + qint64 maxMs = 0; ///< maximum over the current window + int sampleCount = 0; ///< number of samples currently in the window + }; + + void addSample(qint64 ms); + Stats stats() const; + + /// Snapshot of the current window in chronological order (oldest first). + QList recentSamples() const; + + void clear(); + +private: + std::array samples{}; + int head = 0; ///< index where the next sample will be written + int count = 0; ///< number of valid samples, capped at WindowSize +}; + +Q_DECLARE_METATYPE(LatencyTracker::Stats) + +#endif diff --git a/libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp b/libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp index 7e20f2722..53608db65 100644 --- a/libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp +++ b/libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp @@ -543,6 +543,7 @@ void RemoteClient::doDisconnectFromServer() delete i; } pendingCommands.clear(); + clearLatencyStats(); setStatus(StatusDisconnected); if (websocket->isValid()) { diff --git a/libcockatrice_protocol/libcockatrice/protocol/pending_command.cpp b/libcockatrice_protocol/libcockatrice/protocol/pending_command.cpp index 4a9943d33..62d35313e 100644 --- a/libcockatrice_protocol/libcockatrice/protocol/pending_command.cpp +++ b/libcockatrice_protocol/libcockatrice/protocol/pending_command.cpp @@ -29,3 +29,13 @@ int PendingCommand::tick() { return ++ticks; } + +void PendingCommand::startTiming() +{ + startTime.start(); +} + +qint64 PendingCommand::elapsedMs() const +{ + return startTime.isValid() ? startTime.nsecsElapsed() / 1000000 : -1; +} diff --git a/libcockatrice_protocol/libcockatrice/protocol/pending_command.h b/libcockatrice_protocol/libcockatrice/protocol/pending_command.h index dbe57e7fc..b8f861d08 100644 --- a/libcockatrice_protocol/libcockatrice/protocol/pending_command.h +++ b/libcockatrice_protocol/libcockatrice/protocol/pending_command.h @@ -7,6 +7,7 @@ #ifndef PENDING_COMMAND_H #define PENDING_COMMAND_H +#include #include #include #include @@ -21,6 +22,7 @@ private: CommandContainer commandContainer; QVariant extraData; int ticks; + QElapsedTimer startTime; public: explicit PendingCommand(const CommandContainer &_commandContainer, QVariant _extraData = QVariant()); @@ -29,6 +31,18 @@ public: QVariant getExtraData() const; void processResponse(const Response &response); int tick(); + + /** + * @brief Starts the round-trip timer. Called by the client thread right + * before the command container is handed to the transport layer. + */ + void startTiming(); + + /** + * @return Milliseconds elapsed since startTiming(), or -1 if the timer was + * never started. + */ + qint64 elapsedMs() const; }; #endif diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 804293784..b0b959a51 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -12,6 +12,7 @@ add_test(NAME server_card_counter_test COMMAND server_card_counter_test) add_test(NAME server_counter_test COMMAND server_counter_test) add_test(NAME server_rate_limiter_test COMMAND server_rate_limiter_test) add_test(NAME warning_categories_test COMMAND warning_categories_test) +add_test(NAME latency_tracker_test COMMAND latency_tracker_test) add_test(NAME deck_hash_performance_test COMMAND deck_hash_performance_test) set_tests_properties(deck_hash_performance_test PROPERTIES TIMEOUT 5) @@ -29,6 +30,7 @@ add_executable(server_card_counter_test server_card_counter_test.cpp) add_executable(server_counter_test server_counter_test.cpp) add_executable(server_rate_limiter_test server_rate_limiter_test.cpp) add_executable(warning_categories_test warning_categories_test.cpp) +add_executable(latency_tracker_test latency_tracker_test.cpp) find_package(GTest) @@ -66,6 +68,7 @@ if(NOT GTEST_FOUND) add_dependencies(server_counter_test gtest) add_dependencies(server_rate_limiter_test gtest) add_dependencies(warning_categories_test gtest) + add_dependencies(latency_tracker_test gtest) endif() include_directories(${GTEST_INCLUDE_DIRS}) @@ -100,6 +103,9 @@ target_link_libraries( target_link_libraries( warning_categories_test libcockatrice_utility Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES} ) +target_link_libraries( + latency_tracker_test libcockatrice_network Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES} +) add_subdirectory(card_zone_algorithms) add_subdirectory(carddatabase) diff --git a/tests/latency_tracker_test.cpp b/tests/latency_tracker_test.cpp new file mode 100644 index 000000000..68631b7ca --- /dev/null +++ b/tests/latency_tracker_test.cpp @@ -0,0 +1,149 @@ +#include +#include + +TEST(LatencyTrackerTest, EmptyTrackerYieldsZeroedStats) +{ + LatencyTracker tracker; + + const auto stats = tracker.stats(); + + EXPECT_EQ(0, stats.sampleCount); + EXPECT_EQ(0, stats.lastMs); + EXPECT_EQ(0, stats.medianMs); + EXPECT_EQ(0, stats.p95Ms); + EXPECT_EQ(0, stats.maxMs); +} + +TEST(LatencyTrackerTest, SingleSampleIsEveryStatistic) +{ + LatencyTracker tracker; + tracker.addSample(42); + + const auto stats = tracker.stats(); + + EXPECT_EQ(1, stats.sampleCount); + EXPECT_EQ(42, stats.lastMs); + EXPECT_EQ(42, stats.medianMs); + EXPECT_EQ(42, stats.p95Ms); + EXPECT_EQ(42, stats.maxMs); +} + +TEST(LatencyTrackerTest, OddSizedWindowMedianAndP95) +{ + LatencyTracker tracker; + for (qint64 ms : {qint64(50), qint64(10), qint64(30), qint64(20), qint64(40)}) { + tracker.addSample(ms); + } + + const auto stats = tracker.stats(); + + EXPECT_EQ(5, stats.sampleCount); + EXPECT_EQ(40, stats.lastMs); + EXPECT_EQ(30, stats.medianMs); + // nearest-rank p95 of 5 samples: ceil(4.75) = 5th smallest + EXPECT_EQ(50, stats.p95Ms); + EXPECT_EQ(50, stats.maxMs); +} + +TEST(LatencyTrackerTest, EvenSizedWindowMedianIsAverageOfMiddleTwo) +{ + LatencyTracker tracker; + for (qint64 ms : {qint64(10), qint64(20), qint64(30), qint64(40)}) { + tracker.addSample(ms); + } + + const auto stats = tracker.stats(); + + EXPECT_EQ(4, stats.sampleCount); + EXPECT_EQ(25, stats.medianMs); + // nearest-rank p95 of 4 samples: ceil(3.8) = 4th smallest + EXPECT_EQ(40, stats.p95Ms); +} + +TEST(LatencyTrackerTest, WindowEvictsOldestSamples) +{ + LatencyTracker tracker; + for (int i = 0; i <= 99; ++i) { + tracker.addSample(i); + } + + const auto stats = tracker.stats(); + + EXPECT_EQ(LatencyTracker::WindowSize, stats.sampleCount); + EXPECT_EQ(99, stats.lastMs); + EXPECT_EQ(99, stats.maxMs); + // window now contains 36..99 (64 samples) + EXPECT_EQ(67, stats.medianMs); // (67 + 68) / 2 with integer division + EXPECT_EQ(96, stats.p95Ms); // ceil(0.95 * 64) - 1 = index 60 -> 36 + 60 +} + +TEST(LatencyTrackerTest, ClearResetsAllState) +{ + LatencyTracker tracker; + for (int i = 0; i <= 99; ++i) { + tracker.addSample(i); + } + + tracker.clear(); + const auto cleared = tracker.stats(); + EXPECT_EQ(0, cleared.sampleCount); + + tracker.addSample(7); + const auto stats = tracker.stats(); + EXPECT_EQ(1, stats.sampleCount); + EXPECT_EQ(7, stats.lastMs); + EXPECT_EQ(7, stats.medianMs); +} + +TEST(LatencyTrackerTest, LastSampleSurvivesWraparound) +{ + LatencyTracker tracker; + for (int i = 0; i < LatencyTracker::WindowSize; ++i) { + tracker.addSample(i); + } + tracker.addSample(1000); + + EXPECT_EQ(1000, tracker.stats().lastMs); +} + +TEST(LatencyTrackerTest, RecentSamplesAreChronologicalOldestFirst) +{ + LatencyTracker tracker; + for (qint64 ms : {qint64(50), qint64(10), qint64(30)}) { + tracker.addSample(ms); + } + + const QList samples = tracker.recentSamples(); + + EXPECT_EQ((QList{50, 10, 30}), samples); +} + +TEST(LatencyTrackerTest, RecentSamplesFollowRingBufferWraparound) +{ + LatencyTracker tracker; + for (int i = 0; i <= 99; ++i) { + tracker.addSample(i); + } + + const QList samples = tracker.recentSamples(); + + ASSERT_EQ(LatencyTracker::WindowSize, samples.size()); + EXPECT_EQ(36, samples.first()); + EXPECT_EQ(99, samples.last()); +} + +TEST(LatencyTrackerTest, RecentSamplesEmptyOnFreshAndClearedTracker) +{ + LatencyTracker tracker; + EXPECT_TRUE(tracker.recentSamples().isEmpty()); + + tracker.addSample(5); + tracker.clear(); + EXPECT_TRUE(tracker.recentSamples().isEmpty()); +} + +int main(int argc, char **argv) +{ + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); +}