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(); +}