From eddbbf2d7bc4420764830ffa6b7f22b2848afcc4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Lukas=20Br=C3=BCbach?= Date: Sat, 22 Aug 2026 18:54:42 +0200 Subject: [PATCH] [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 --- .../remote_connection_controller.cpp | 3 + .../remote_connection_controller.h | 8 + .../network/client/abstract/CMakeLists.txt | 4 +- .../client/abstract/abstract_client.cpp | 59 +++++++ .../network/client/abstract/abstract_client.h | 38 +++++ .../client/abstract/latency_tracker.cpp | 60 +++++++ .../network/client/abstract/latency_tracker.h | 48 ++++++ .../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, 398 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..ee094dd28 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,9 @@ void ConnectionController::wireClientSignals() connect(remoteClient, &RemoteClient::statusChanged, this, &ConnectionController::onStatusChanged); + connect(remoteClient, &AbstractClient::pingStatsUpdated, this, &ConnectionController::pingStatsUpdated); + connect(remoteClient, &AbstractClient::pingSamplesUpdated, this, &ConnectionController::pingSamplesUpdated); + 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..a444f5d41 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,14 @@ signals: // action enable/disable logic void statusChanged(ClientStatus status); + // Forwarded from AbstractClient::pingStatsUpdated. See that signal for the + // meaning of the parameters. + void pingStatsUpdated(int lastMs, int medianMs, int p95Ms, int maxMs, int sampleCount); + + // Forwarded from AbstractClient::pingSamplesUpdated. See that signal for + // the meaning of the parameter. + void pingSamplesUpdated(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..c97a66a17 100644 --- a/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.cpp +++ b/libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.cpp @@ -71,6 +71,8 @@ void AbstractClient::processProtocolItem(const ServerMessage &item) } pendingCommands.remove(cmdId); + recordLatency(*pend); + pend->processResponse(response); pend->deleteLater(); break; @@ -161,9 +163,66 @@ void AbstractClient::queuePendingCommand(PendingCommand *pend) pendingCommands.insert(cmdId, pend); + pend->startTiming(); sendCommandContainer(pend->getCommandContainer()); } +namespace +{ +constexpr int StatsEmitIntervalMs = 1000; +// Game actions are what players perceive as lag. Surface unusually slow ones +// without requiring debug logging to be enabled. +constexpr qint64 SlowGameCommandWarnMs = 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 >= SlowGameCommandWarnMs && pend.getCommandContainer().game_command_size() > 0) { + qCWarning(AbstractClientLog) << "slow game command round trip:" << elapsed << "ms (cmd_id" + << pend.getCommandContainer().cmd_id() << ")"; + } + + // 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() >= StatsEmitIntervalMs) { + statsEmitClock.start(); + statsEmitClockStarted = true; + const LatencyTracker::Stats stats = latencyTracker.stats(); + const QList recentSamples = latencyTracker.recentSamples(); + + QList samples; + samples.reserve(stats.sampleCount); + for (qint64 sample : recentSamples) { + samples.append(static_cast(sample)); + } + + emit pingStatsUpdated(static_cast(stats.lastMs), static_cast(stats.medianMs), + static_cast(stats.p95Ms), static_cast(stats.maxMs), stats.sampleCount); + emit pingSamplesUpdated(samples); + } +} + +void AbstractClient::clearLatencyStats() +{ + latencyTracker.clear(); + statsEmitClockStarted = false; + emit pingStatsUpdated(0, 0, 0, 0, 0); + emit pingSamplesUpdated({}); +} + 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..b189932e8 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,23 @@ signals: void statusChanged(ClientStatus _status); void maxPingTime(int seconds, int maxSeconds); + /** + * @brief Aggregated round-trip statistics, emitted at most once per second. + * + * All values are in milliseconds. sampleCount is the number of samples + * currently in the rolling window. Emitted from the client thread. The + * connection to UI objects is automatically queued across threads. + */ + void pingStatsUpdated(int lastMs, int medianMs, int p95Ms, int maxMs, int sampleCount); + + /** + * @brief Chronological snapshot of the rolling window, oldest sample first. + * + * Emitted together with pingStatsUpdated under the same throttle, so + * graphs can redraw without polling the tracker across threads. + */ + void pingSamplesUpdated(const QList &samplesMs); + // Room events void roomEventReceived(const RoomEvent &event); // Game events @@ -85,6 +108,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 +141,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 a zeroed pingStatsUpdated 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..bf40ebfa0 --- /dev/null +++ b/libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.h @@ -0,0 +1,48 @@ +/** + * @file latency_tracker.h + * @ingroup Client + */ + +#ifndef LATENCY_TRACKER_H +#define LATENCY_TRACKER_H + +#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 +}; + +#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(); +}