[Network] Measure real server round-trip times (#7153)

* [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 <Bruebach.Lukas@bdosecurity.de>

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);
 

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<int> &samplesMs);
+
 private slots:
     // Slots wired directly to RemoteClient signals
     void onStatusChanged(ClientStatus status);

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})
 

libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.cpp

@@ -1,6 +1,7 @@
 #include "abstract_client.h"
 
 #include <google/protobuf/descriptor.h>
+#include <libcockatrice/protocol/debug_pb_message.h>
 #include <libcockatrice/protocol/featureset.h>
 #include <libcockatrice/protocol/get_pb_extension.h>
 #include <libcockatrice/protocol/pb/commands.pb.h>
@@ -28,6 +29,7 @@ AbstractClient::AbstractClient(QObject *parent)
     qRegisterMetaType<Response>("Response");
     qRegisterMetaType<Response::ResponseCode>("Response::ResponseCode");
     qRegisterMetaType<ClientStatus>("ClientStatus");
+    qRegisterMetaType<LatencyTracker::Stats>("LatencyTracker::Stats");
     qRegisterMetaType<RoomEvent>("RoomEvent");
     qRegisterMetaType<GameEventContainer>("GameEventContainer");
     qRegisterMetaType<Event_ServerIdentification>("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<int> samples;
+        samples.reserve(stats.sampleCount);
+        for (qint64 sample : latencyTracker.recentSamples()) {
+            samples.append(static_cast<int>(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;

libcockatrice_network/libcockatrice/network/client/abstract/abstract_client.h

@@ -7,11 +7,17 @@
 #ifndef ABSTRACTCLIENT_H
 #define ABSTRACTCLIENT_H
 
+#include "latency_tracker.h"
+
+#include <QElapsedTimer>
+#include <QLoggingCategory>
 #include <QMutex>
 #include <QVariant>
 #include <libcockatrice/protocol/pb/response.pb.h>
 #include <libcockatrice/protocol/pb/serverinfo_user.pb.h>
 
+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<int> &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;

libcockatrice_network/libcockatrice/network/client/abstract/latency_tracker.cpp

@@ -0,0 +1,60 @@
+#include "latency_tracker.h"
+
+#include <QtMath>
+#include <algorithm>
+
+void LatencyTracker::addSample(qint64 ms)
+{
+    samples[static_cast<size_t>(head)] = ms;
+    head = (head + 1) % WindowSize;
+    if (count < WindowSize) {
+        ++count;
+    }
+}
+
+QList<qint64> LatencyTracker::recentSamples() const
+{
+    QList<qint64> result;
+    result.reserve(count);
+    for (int i = count; i > 0; --i) {
+        const int index = (head + WindowSize - i) % WindowSize;
+        result.append(samples[static_cast<size_t>(index)]);
+    }
+    return result;
+}
+
+LatencyTracker::Stats LatencyTracker::stats() const
+{
+    if (count == 0) {
+        return {};
+    }
+
+    QList<qint64> sorted(samples.cbegin(), samples.cbegin() + count);
+    std::sort(sorted.begin(), sorted.end());
+
+    Stats s;
+    s.sampleCount = count;
+    s.lastMs = samples[static_cast<size_t>((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<double>(n)) - 1);
+    s.p95Ms = sorted[p95Index];
+
+    return s;
+}
+
+void LatencyTracker::clear()
+{
+    samples.fill(0);
+    head = 0;
+    count = 0;
+}

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 <QList>
+#include <QMetaType>
+#include <array>
+
+/**
+ * @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<qint64> recentSamples() const;
+
+    void clear();
+
+private:
+    std::array<qint64, WindowSize> 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

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()) {

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

libcockatrice_protocol/libcockatrice/protocol/pending_command.h

@@ -7,6 +7,7 @@
 #ifndef PENDING_COMMAND_H
 #define PENDING_COMMAND_H
 
+#include <QElapsedTimer>
 #include <QVariant>
 #include <libcockatrice/protocol/pb/commands.pb.h>
 #include <libcockatrice/protocol/pb/response.pb.h>
@@ -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

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)

tests/latency_tracker_test.cpp

@@ -0,0 +1,149 @@
+#include <gtest/gtest.h>
+#include <libcockatrice/network/client/abstract/latency_tracker.h>
+
+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<qint64> samples = tracker.recentSamples();
+
+    EXPECT_EQ((QList<qint64>{50, 10, 30}), samples);
+}
+
+TEST(LatencyTrackerTest, RecentSamplesFollowRingBufferWraparound)
+{
+    LatencyTracker tracker;
+    for (int i = 0; i <= 99; ++i) {
+        tracker.addSample(i);
+    }
+
+    const QList<qint64> 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();
+}