diff --git a/cockatrice/CMakeLists.txt b/cockatrice/CMakeLists.txt index ed196e501..1924d86bf 100644 --- a/cockatrice/CMakeLists.txt +++ b/cockatrice/CMakeLists.txt @@ -15,6 +15,9 @@ set(cockatrice_SOURCES src/client/network/update/client/client_update_checker.cpp src/client/network/update/client/release_channel.cpp src/client/network/update/card_spoiler/spoiler_background_updater.cpp + src/client/latency_graph_widget.cpp + src/client/latency_status_widget.cpp + src/client/lag_monitor.cpp src/client/sound_engine.cpp src/client/settings/cache_settings.cpp src/client/settings/card_counter_settings.cpp diff --git a/cockatrice/src/client/lag_monitor.cpp b/cockatrice/src/client/lag_monitor.cpp new file mode 100644 index 000000000..383d64644 --- /dev/null +++ b/cockatrice/src/client/lag_monitor.cpp @@ -0,0 +1,63 @@ +#include "lag_monitor.h" + +#include +#include +#include + +LagMonitor::LagMonitor(QObject *parent) : QObject(parent) +{ + qApp->installEventFilter(this); + + timer = new QTimer(this); + timer->setInterval(TICK_INTERVAL_MS); + connect(timer, &QTimer::timeout, this, &LagMonitor::checkTick); + tickClock.start(); + timer->start(); +} + +QList LagMonitor::recentStalls() const +{ + return stalls; +} + +void LagMonitor::clearStalls() +{ + stalls.clear(); +} + +bool LagMonitor::eventFilter(QObject *obj, QEvent *event) +{ + if (event->type() == QEvent::ApplicationStateChange) { + // The transition may span a suspend or an arbitrary unfocused period; + // discard the gap so it cannot be mistaken for a stall. + tickClock.restart(); + } + return QObject::eventFilter(obj, event); +} + +void LagMonitor::checkTick() +{ + recordGap(tickClock.restart()); +} + +void LagMonitor::recordGap(qint64 gapMs) +{ + if (gapMs <= STALL_THRESHOLD_MS) { + return; + } + + if (gapMs > MAX_PLAUSIBLE_STALL_MS) { + qCDebug(LagMonitorLog, "Ignoring implausible %lld ms gap (likely suspend)", static_cast(gapMs)); + return; + } + + const StallRecord record{.timestampMsSinceEpoch = QDateTime::currentMSecsSinceEpoch(), .durationMs = gapMs}; + + stalls.append(record); + while (stalls.size() > MAX_RECORDED_STALLS) { + stalls.removeFirst(); + } + + qCWarning(LagMonitorLog, "Event loop stalled for %lld ms (threshold: %d ms)", static_cast(gapMs), + STALL_THRESHOLD_MS); +} diff --git a/cockatrice/src/client/lag_monitor.h b/cockatrice/src/client/lag_monitor.h new file mode 100644 index 000000000..9fdf6b283 --- /dev/null +++ b/cockatrice/src/client/lag_monitor.h @@ -0,0 +1,87 @@ +/** + * @file lag_monitor.h + * @ingroup Client + */ + +#ifndef LAG_MONITOR_H +#define LAG_MONITOR_H + +#include +#include +#include +#include +#include + +inline Q_LOGGING_CATEGORY(LagMonitorLog, "lag_monitor"); + +class QEvent; +class QTimer; + +/** + * @brief Detects main-thread event loop stalls ("UI freezes") from the inside. + * + * A timer is expected to fire every TICK_INTERVAL_MS of wall time. When the + * observed gap greatly exceeds that interval, some other task blocked the + * event loop for roughly the overshooting duration. This is what separates + * "my client froze" from "the network is lagging" in user reports. + * + * Gaps that span an application state change (suspend, minimize, focus + * loss) are discarded, and implausibly huge gaps are dropped, so operating + * system power events do not fabricate stalls. This handling is load-bearing + * on Windows, where the monotonic clock used by Qt counts sleep time. + * + * Healthy operation costs one timer wakeup per tick and two integer + * comparisons. Allocations happen only when a stall is actually recorded. + */ +class LagMonitor : public QObject +{ + Q_OBJECT + +public: + struct StallRecord + { + qint64 timestampMsSinceEpoch = 0; ///< when the stalled period ended + qint64 durationMs = 0; ///< approximate length of the freeze; measured tick to tick, so it can exceed the true + ///< stall by up to TICK_INTERVAL_MS + }; + + static constexpr int TICK_INTERVAL_MS = 500; + static constexpr int STALL_THRESHOLD_MS = 2000; + static constexpr int MAX_RECORDED_STALLS = 32; + + /// Gaps beyond this are treated as suspend artifacts rather than stalls. + static constexpr qint64 MAX_PLAUSIBLE_STALL_MS = 600000; + + explicit LagMonitor(QObject *parent = nullptr); + + /** + * @brief Stalls recorded during this session, oldest first. + * + * Intended consumers are log output and the diagnostics export. The list + * holds at most MAX_RECORDED_STALLS entries. + */ + QList recentStalls() const; + + void clearStalls(); + + /** + * @brief Feeds a measured tick-to-tick gap through the detection logic. + * + * Split out of checkTick so threshold, plausibility, and trim behavior + * stay unit-testable without real timing. + */ + void recordGap(qint64 gapMs); + +protected: + bool eventFilter(QObject *obj, QEvent *event) override; + +private slots: + void checkTick(); + +private: + QTimer *timer; + QElapsedTimer tickClock; ///< monotonic clock, so wall clock steps do not fabricate stalls + QList stalls; +}; + +#endif diff --git a/cockatrice/src/client/latency_graph_widget.cpp b/cockatrice/src/client/latency_graph_widget.cpp new file mode 100644 index 000000000..46d6ccdd3 --- /dev/null +++ b/cockatrice/src/client/latency_graph_widget.cpp @@ -0,0 +1,51 @@ +/** + * @file latency_graph_widget.cpp + * @ingroup Client + */ + +#include "latency_graph_widget.h" + +#include + +LatencyGraphWidget::LatencyGraphWidget(QWidget *parent) : QWidget(parent) +{ +} + +void LatencyGraphWidget::setSamples(const QList &samplesMs) +{ + samples = samplesMs; + update(); +} + +void LatencyGraphWidget::paintEvent(QPaintEvent * /* event */) +{ + if (samples.isEmpty()) { + return; + } + + QPainter painter(this); + + // Heights are relative to the window's own worst sample (floored at + // MinScaleMs) so the shape of the variance stays readable even when every + // value is small. + qint64 heightScaleMs = MinScaleMs; + for (int sample : samples) { + heightScaleMs = qMax(heightScaleMs, static_cast(sample)); + } + + const qreal widthPerBar = static_cast(width()) / samples.size(); + for (int i = 0; i < samples.size(); ++i) { + const qreal heightRatio = qBound(0.0, static_cast(samples.at(i)) / heightScaleMs, 1.0); + const qreal barHeight = heightRatio * height(); + + // Colors follow an absolute quality ramp: a steady good ping stays + // green no matter how uniform the window is. + const qreal colorRatio = qBound(0.0, static_cast(samples.at(i)) / ColorScaleMs, 1.0); + QColor color; + color.setHsv(qRound(120.0 * (1.0 - colorRatio)), 255, 255); + + const QRectF bar(static_cast(i) * widthPerBar + 1.0, static_cast(height()) - barHeight, + qMax(1.0, widthPerBar - 2.0), barHeight); + painter.fillRect(bar, color); + } +} diff --git a/cockatrice/src/client/latency_graph_widget.h b/cockatrice/src/client/latency_graph_widget.h new file mode 100644 index 000000000..4f6f38f8b --- /dev/null +++ b/cockatrice/src/client/latency_graph_widget.h @@ -0,0 +1,43 @@ +/** + * @file latency_graph_widget.h + * @ingroup Client + */ + +#ifndef LATENCY_GRAPH_WIDGET_H +#define LATENCY_GRAPH_WIDGET_H + +#include +#include + +/** + * @brief Bar graph of recent network round-trip samples. + * + * Draws one bar per sample, oldest on the left. Bar height is relative to the + * window's own scale so the shape of the variance stays readable, while bar + * color maps each sample onto an absolute quality ramp (green at rest through + * red at ColorScaleMs) so a steady good ping never looks alarming. Size + * agnostic: the status bar embeds a small instance while the latency detail + * popup shows a large one. + */ +class LatencyGraphWidget : public QWidget +{ + Q_OBJECT +public: + explicit LatencyGraphWidget(QWidget *parent = nullptr); + + /// Sample in milliseconds that maps to a fully red bar. + static constexpr qint64 ColorScaleMs = 500; + + void setSamples(const QList &samplesMs); + +protected: + void paintEvent(QPaintEvent *event) override; + +private: + /// Floor of the vertical scale in milliseconds. Keeps small windows readable. + static constexpr qint64 MinScaleMs = 100; + + QList samples; +}; + +#endif diff --git a/cockatrice/src/client/latency_status_widget.cpp b/cockatrice/src/client/latency_status_widget.cpp new file mode 100644 index 000000000..779c726eb --- /dev/null +++ b/cockatrice/src/client/latency_status_widget.cpp @@ -0,0 +1,111 @@ +/** + * @file latency_status_widget.cpp + * @ingroup Client + */ + +#include "latency_status_widget.h" + +#include "latency_graph_widget.h" + +#include +#include +#include +#include + +LatencyStatusWidget::LatencyStatusWidget(QWidget *parent) : QWidget(parent) +{ + pingLabel = new QLabel(this); + pingLabel->setAccessibleName(tr("Ping")); + + latencyGraph = new LatencyGraphWidget(this); + latencyGraph->setFixedSize(90, 14); + + auto *layout = new QHBoxLayout(this); + layout->setContentsMargins(0, 0, 0, 0); + layout->setSpacing(4); + layout->addWidget(latencyGraph); + layout->addWidget(pingLabel); + + // Clicking anywhere in the area opens the detail view. + for (QObject *child : QList{pingLabel, latencyGraph}) { + child->installEventFilter(this); + } + setCursor(Qt::PointingHandCursor); + + hide(); +} + +void LatencyStatusWidget::updateData(const LatencyTracker::Stats &stats, const QList &samplesMs) +{ + latestSamples = samplesMs; + latencyGraph->setSamples(samplesMs); + if (popup && popup->isVisible() && detailGraph) { + detailGraph->setSamples(samplesMs); + } + + if (stats.sampleCount == 0) { + hide(); + return; + } + + const QString statsStr = statsText(stats); + + pingLabel->setText(tr("Ping: %1 ms").arg(stats.lastMs)); + pingLabel->setToolTip(statsStr); + pingLabel->setAccessibleDescription(statsStr); + if (popup && popup->isVisible() && detailLabel) { + detailLabel->setText(statsStr); + } + show(); +} + +bool LatencyStatusWidget::eventFilter(QObject *watched, QEvent *event) +{ + if ((watched == pingLabel || watched == latencyGraph) && event->type() == QEvent::MouseButtonPress) { + togglePopup(); + return true; + } + return QWidget::eventFilter(watched, event); +} + +void LatencyStatusWidget::togglePopup() +{ + if (!popup) { + popup = new QWidget(this, Qt::Popup | Qt::FramelessWindowHint); + auto *layout = new QVBoxLayout(popup); + layout->setContentsMargins(8, 8, 8, 8); + + detailLabel = new QLabel(popup); + detailLabel->setAccessibleName(tr("Connection latency details")); + detailLabel->setTextInteractionFlags(Qt::TextSelectableByMouse); + + detailGraph = new LatencyGraphWidget(popup); + detailGraph->setFixedSize(280, 80); + + layout->addWidget(detailLabel, 0, Qt::AlignLeft); + layout->addWidget(detailGraph, 0, Qt::AlignHCenter); + } + + if (popup->isVisible()) { + popup->hide(); + return; + } + + // Qt::Popup closes itself on any outside click, so just position and show. + if (latestSamples.isEmpty()) { + return; + } + detailGraph->setSamples(latestSamples); + detailLabel->setText(pingLabel->toolTip()); + popup->adjustSize(); + const QPoint anchor = mapToGlobal(QPoint(width() / 2, 0)); + popup->move(anchor.x() - popup->width() / 2, anchor.y() - popup->height() - 6); + popup->show(); +} + +QString LatencyStatusWidget::statsText(const LatencyTracker::Stats &stats) const +{ + return tr("Connection quality over the last %n sample(s):", "", stats.sampleCount) + "\n" + + tr("Last: %1 ms").arg(stats.lastMs) + "\n" + tr("Median: %1 ms").arg(stats.medianMs) + "\n" + + tr("95th percentile: %1 ms").arg(stats.p95Ms) + "\n" + tr("Maximum: %1 ms").arg(stats.maxMs); +} diff --git a/cockatrice/src/client/latency_status_widget.h b/cockatrice/src/client/latency_status_widget.h new file mode 100644 index 000000000..d9e1d130c --- /dev/null +++ b/cockatrice/src/client/latency_status_widget.h @@ -0,0 +1,50 @@ +/** + * @file latency_status_widget.h + * @ingroup Client + */ + +#ifndef LATENCY_STATUS_WIDGET_H +#define LATENCY_STATUS_WIDGET_H + +#include +#include +#include + +class QLabel; +class LatencyGraphWidget; + +/** + * @brief Status bar presentation of server round-trip health. + * + * Combines the textual "Ping" readout with a small LatencyGraphWidget + * sparkline of the rolling sample window. Clicking anywhere in the area opens + * a popup with a larger graph and the numeric statistics. It closes on any + * outside click. Stays hidden while disconnected or before any samples exist. + * Owns all latency display state so MainWindow only needs to forward one + * signal here. + */ +class LatencyStatusWidget : public QWidget +{ + Q_OBJECT +public: + explicit LatencyStatusWidget(QWidget *parent = nullptr); + +public slots: + void updateData(const LatencyTracker::Stats &stats, const QList &samplesMs); + +protected: + bool eventFilter(QObject *watched, QEvent *event) override; + +private: + void togglePopup(); + QString statsText(const LatencyTracker::Stats &stats) const; + + QLabel *pingLabel = nullptr; + LatencyGraphWidget *latencyGraph = nullptr; + QWidget *popup = nullptr; + LatencyGraphWidget *detailGraph = nullptr; + QLabel *detailLabel = nullptr; + QList latestSamples; +}; + +#endif 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/cockatrice/src/interface/widgets/server/games_model.cpp b/cockatrice/src/interface/widgets/server/games_model.cpp index ce10bee71..127badbb2 100644 --- a/cockatrice/src/interface/widgets/server/games_model.cpp +++ b/cockatrice/src/interface/widgets/server/games_model.cpp @@ -285,6 +285,9 @@ void GamesModel::updateGameList(const ServerInfo_Game &game) gameList.removeAt(i); endRemoveRows(); } else { + // MergeFrom concatenates repeated fields instead of replacing them, + // so clear game_types first to avoid duplicated entries. + gameList[i].clear_game_types(); gameList[i].MergeFrom(game); emit dataChanged(index(i, 0), index(i, NUM_COLS - 1)); } diff --git a/cockatrice/src/interface/widgets/tabs/tab_supervisor.cpp b/cockatrice/src/interface/widgets/tabs/tab_supervisor.cpp index f1b26da9d..f96c139b3 100644 --- a/cockatrice/src/interface/widgets/tabs/tab_supervisor.cpp +++ b/cockatrice/src/interface/widgets/tabs/tab_supervisor.cpp @@ -141,6 +141,7 @@ TabSupervisor::TabSupervisor(AbstractClient *_client, QMenu *tabsMenu, QWidget * connect(client, &AbstractClient::gameJoinedEventReceived, this, &TabSupervisor::gameJoined); connect(client, &AbstractClient::userMessageEventReceived, this, &TabSupervisor::processUserMessageEvent); connect(client, &AbstractClient::maxPingTime, this, &TabSupervisor::updatePingTime); + connect(client, &AbstractClient::pingStatsUpdated, this, &TabSupervisor::updateLatencyTooltip); connect(client, &AbstractClient::notifyUserEventReceived, this, &TabSupervisor::processNotifyUserEvent); // create tabs menu actions @@ -883,6 +884,23 @@ void TabSupervisor::updatePingTime(int value, int max) setTabIcon(indexOf(tabServer), QIcon(PingPixmapGenerator::generatePixmap(15, value, max))); } +void TabSupervisor::updateLatencyTooltip(const LatencyTracker::Stats &stats) +{ + if (!tabServer) { + return; + } + + if (stats.sampleCount == 0) { + setTabToolTip(indexOf(tabServer), QString()); + return; + } + + setTabToolTip(indexOf(tabServer), + tr("Connection quality over the last %n sample(s):", "", stats.sampleCount) + "\n" + + tr("Last: %1 ms").arg(stats.lastMs) + "\n" + tr("Median: %1 ms").arg(stats.medianMs) + "\n" + + tr("95th percentile: %1 ms").arg(stats.p95Ms) + "\n" + tr("Maximum: %1 ms").arg(stats.maxMs)); +} + void TabSupervisor::gameJoined(const Event_GameJoined &event) { QMap roomGameTypes; diff --git a/cockatrice/src/interface/widgets/tabs/tab_supervisor.h b/cockatrice/src/interface/widgets/tabs/tab_supervisor.h index 32ed14504..b389bad3e 100644 --- a/cockatrice/src/interface/widgets/tabs/tab_supervisor.h +++ b/cockatrice/src/interface/widgets/tabs/tab_supervisor.h @@ -24,6 +24,7 @@ #include #include #include +#include class TabCardArtRules; inline Q_LOGGING_CATEGORY(TabSupervisorLog, "tab_supervisor"); @@ -220,6 +221,7 @@ private slots: void updateCurrent(int index); void updatePingTime(int value, int max); + void updateLatencyTooltip(const LatencyTracker::Stats &stats); void gameJoined(const Event_GameJoined &event); void localGameJoined(const Event_GameJoined &event); void gameLeft(TabGame *tab); diff --git a/cockatrice/src/interface/window_main.cpp b/cockatrice/src/interface/window_main.cpp index 199a2d952..13c37473e 100644 --- a/cockatrice/src/interface/window_main.cpp +++ b/cockatrice/src/interface/window_main.cpp @@ -19,6 +19,7 @@ ***************************************************************************/ #include "window_main.h" +#include "../client/latency_status_widget.h" #include "../client/network/update/client/client_update_checker.h" #include "../client/network/update/client/release_channel.h" #include "../client/settings/cache_settings.h" @@ -56,6 +57,7 @@ #include #include #include +#include #include #include #include @@ -535,6 +537,12 @@ MainWindow::MainWindow(QWidget *parent) [this](bool show) { statusBar()->setVisible(show); }); statusBar()->setVisible(SettingsCache::instance().userInterface().getShowStatusBar()); + latencyStatus = new LatencyStatusWidget(this); + statusBar()->addPermanentWidget(latencyStatus); + + connect(connectionController, &ConnectionController::pingStatsUpdated, latencyStatus, + &LatencyStatusWidget::updateData); + connect(&SettingsCache::instance().shortcuts(), &ShortcutsSettings::shortCutChanged, this, &MainWindow::refreshShortcuts); refreshShortcuts(); diff --git a/cockatrice/src/interface/window_main.h b/cockatrice/src/interface/window_main.h index fc0791832..baacd3096 100644 --- a/cockatrice/src/interface/window_main.h +++ b/cockatrice/src/interface/window_main.h @@ -25,6 +25,7 @@ #ifndef WINDOW_H #define WINDOW_H +#include "../client/lag_monitor.h" #include "connection_controller/remote_connection_controller.h" #include "widgets/dialogs/dlg_local_game_options.h" @@ -49,6 +50,8 @@ class GameReplay; class HandlePublicServers; class LocalClient; class LocalServer; +class QLabel; +class LatencyStatusWidget; class QThread; class RemoteClient; class ServerInfo_User; @@ -145,6 +148,8 @@ private: WndSets *wndSets; ConnectionController *connectionController; LocalServer *localServer; + LagMonitor lagMonitor; ///< watches the main thread for event loop stalls + LatencyStatusWidget *latencyStatus = nullptr; ///< status bar widget with live round-trip stats and history graph bool bHasActivated, askedForDbUpdater; QProcess *cardUpdateProcess; DlgViewLog *logviewDialog; 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_network/libcockatrice/network/server/remote/game/server_game.cpp b/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.cpp index 069a10463..f537c3cd5 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.cpp +++ b/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.cpp @@ -829,7 +829,7 @@ void Server_Game::getInfo(ServerInfo_Game &result) const result.mutable_creator_info()->CopyFrom(*getCreatorInfo()); const Server_AbstractParticipant *host = participants.value(hostId, nullptr); if (host != nullptr) { - result.mutable_host_info()->CopyFrom(*host->getUserInfo()); + host->copyUserInfo(*result.mutable_host_info(), false); } else { result.mutable_host_info()->CopyFrom(*getCreatorInfo()); } 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..29caf257e 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -12,6 +12,8 @@ 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 lag_monitor_test COMMAND lag_monitor_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 +31,9 @@ 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(lag_monitor_test ${CMAKE_SOURCE_DIR}/cockatrice/src/client/lag_monitor.cpp lag_monitor_test.cpp) +target_include_directories(lag_monitor_test PRIVATE ${CMAKE_SOURCE_DIR}/cockatrice/src) +add_executable(latency_tracker_test latency_tracker_test.cpp) find_package(GTest) @@ -66,6 +71,8 @@ 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(lag_monitor_test gtest) + add_dependencies(latency_tracker_test gtest) endif() include_directories(${GTEST_INCLUDE_DIRS}) @@ -100,6 +107,10 @@ target_link_libraries( target_link_libraries( warning_categories_test libcockatrice_utility Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES} ) +target_link_libraries(lag_monitor_test 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/lag_monitor_test.cpp b/tests/lag_monitor_test.cpp new file mode 100644 index 000000000..9948eeabb --- /dev/null +++ b/tests/lag_monitor_test.cpp @@ -0,0 +1,103 @@ +#include "client/lag_monitor.h" + +#include +#include +#include +#include +#include + +namespace +{ + +/// Timestamps are taken at recording time; allow generous scheduler slack. +constexpr qint64 TIMESTAMP_SLACK_MS = 10000; + +} // namespace + +class LagMonitorTest : public ::testing::Test +{ +protected: + LagMonitor monitor; +}; + +TEST_F(LagMonitorTest, GapAtOrBelowThresholdIsIgnored) +{ + monitor.recordGap(0); + monitor.recordGap(LagMonitor::TICK_INTERVAL_MS); + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +TEST_F(LagMonitorTest, GapAboveThresholdIsRecorded) +{ + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1); + + const QList stalls = monitor.recentStalls(); + ASSERT_EQ(1, stalls.size()); + EXPECT_EQ(LagMonitor::STALL_THRESHOLD_MS + 1, stalls.first().durationMs); +} + +TEST_F(LagMonitorTest, RecordedTimestampIsFresh) +{ + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1); + + const qint64 now = QDateTime::currentMSecsSinceEpoch(); + ASSERT_EQ(1, monitor.recentStalls().size()); + EXPECT_LE(qAbs(monitor.recentStalls().first().timestampMsSinceEpoch - now), TIMESTAMP_SLACK_MS); +} + +TEST_F(LagMonitorTest, RecordsAreTrimmedToMaxOldestFirst) +{ + for (int i = 0; i < LagMonitor::MAX_RECORDED_STALLS + 5; ++i) { + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1 + i); + } + + const QList stalls = monitor.recentStalls(); + ASSERT_EQ(LagMonitor::MAX_RECORDED_STALLS, stalls.size()); + EXPECT_EQ(LagMonitor::STALL_THRESHOLD_MS + 6, stalls.first().durationMs); + EXPECT_EQ(LagMonitor::STALL_THRESHOLD_MS + 5 + LagMonitor::MAX_RECORDED_STALLS, stalls.last().durationMs); +} + +TEST_F(LagMonitorTest, GapAtPlausibilityCapIsKept) +{ + monitor.recordGap(LagMonitor::MAX_PLAUSIBLE_STALL_MS); + + ASSERT_EQ(1, monitor.recentStalls().size()); + EXPECT_EQ(LagMonitor::MAX_PLAUSIBLE_STALL_MS, monitor.recentStalls().first().durationMs); +} + +TEST_F(LagMonitorTest, GapBeyondPlausibilityCapIsDropped) +{ + monitor.recordGap(LagMonitor::MAX_PLAUSIBLE_STALL_MS + 1); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +TEST_F(LagMonitorTest, ClearStallsEmptiesList) +{ + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1); + ASSERT_EQ(1, monitor.recentStalls().size()); + + monitor.clearStalls(); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +TEST_F(LagMonitorTest, ApplicationStateChangeDoesNotRecordAStall) +{ + QObject probe; + QEvent event(QEvent::ApplicationStateChange); + + QCoreApplication::sendEvent(&probe, &event); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +int main(int argc, char **argv) +{ + QLoggingCategory::setFilterRules("lag_monitor.*=false"); + QCoreApplication app(argc, argv); + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); +} 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(); +}