Move params to struct, more informative debug

Took 56 seconds

Took 53 seconds

Took 2 minutes

Took 33 seconds
This commit is contained in:
Lukas Brübach 2026-08-22 23:41:41 +02:00
parent eddbbf2d7b
commit 3dc7a65416
5 changed files with 25 additions and 34 deletions

View file

@ -45,7 +45,6 @@ void ConnectionController::wireClientSignals()
connect(remoteClient, &RemoteClient::statusChanged, this, &ConnectionController::onStatusChanged); connect(remoteClient, &RemoteClient::statusChanged, this, &ConnectionController::onStatusChanged);
connect(remoteClient, &AbstractClient::pingStatsUpdated, this, &ConnectionController::pingStatsUpdated); connect(remoteClient, &AbstractClient::pingStatsUpdated, this, &ConnectionController::pingStatsUpdated);
connect(remoteClient, &AbstractClient::pingSamplesUpdated, this, &ConnectionController::pingSamplesUpdated);
connect(remoteClient, &RemoteClient::userInfoChanged, this, &ConnectionController::onUserInfoReceived, connect(remoteClient, &RemoteClient::userInfoChanged, this, &ConnectionController::onUserInfoReceived,
Qt::BlockingQueuedConnection); Qt::BlockingQueuedConnection);

View file

@ -56,11 +56,7 @@ signals:
// Forwarded from AbstractClient::pingStatsUpdated. See that signal for the // Forwarded from AbstractClient::pingStatsUpdated. See that signal for the
// meaning of the parameters. // meaning of the parameters.
void pingStatsUpdated(int lastMs, int medianMs, int p95Ms, int maxMs, int sampleCount); void pingStatsUpdated(const LatencyTracker::Stats &stats, const QList<int> &samplesMs);
// Forwarded from AbstractClient::pingSamplesUpdated. See that signal for
// the meaning of the parameter.
void pingSamplesUpdated(const QList<int> &samplesMs);
private slots: private slots:
// Slots wired directly to RemoteClient signals // Slots wired directly to RemoteClient signals

View file

@ -1,6 +1,7 @@
#include "abstract_client.h" #include "abstract_client.h"
#include <google/protobuf/descriptor.h> #include <google/protobuf/descriptor.h>
#include <libcockatrice/protocol/debug_pb_message.h>
#include <libcockatrice/protocol/featureset.h> #include <libcockatrice/protocol/featureset.h>
#include <libcockatrice/protocol/get_pb_extension.h> #include <libcockatrice/protocol/get_pb_extension.h>
#include <libcockatrice/protocol/pb/commands.pb.h> #include <libcockatrice/protocol/pb/commands.pb.h>
@ -28,6 +29,7 @@ AbstractClient::AbstractClient(QObject *parent)
qRegisterMetaType<Response>("Response"); qRegisterMetaType<Response>("Response");
qRegisterMetaType<Response::ResponseCode>("Response::ResponseCode"); qRegisterMetaType<Response::ResponseCode>("Response::ResponseCode");
qRegisterMetaType<ClientStatus>("ClientStatus"); qRegisterMetaType<ClientStatus>("ClientStatus");
qRegisterMetaType<LatencyTracker::Stats>("LatencyTracker::Stats");
qRegisterMetaType<RoomEvent>("RoomEvent"); qRegisterMetaType<RoomEvent>("RoomEvent");
qRegisterMetaType<GameEventContainer>("GameEventContainer"); qRegisterMetaType<GameEventContainer>("GameEventContainer");
qRegisterMetaType<Event_ServerIdentification>("Event_ServerIdentification"); qRegisterMetaType<Event_ServerIdentification>("Event_ServerIdentification");
@ -169,10 +171,10 @@ void AbstractClient::queuePendingCommand(PendingCommand *pend)
namespace namespace
{ {
constexpr int StatsEmitIntervalMs = 1000; constexpr int STATS_EMIT_INTERVAL_MS = 1000;
// Game actions are what players perceive as lag. Surface unusually slow ones // Game actions are what players perceive as lag. Surface unusually slow ones
// without requiring debug logging to be enabled. // without requiring debug logging to be enabled.
constexpr qint64 SlowGameCommandWarnMs = 1500; constexpr qint64 SLOW_GAME_COMMAND_WARN_MS = 1500;
} // namespace } // namespace
void AbstractClient::recordLatency(PendingCommand &pend) void AbstractClient::recordLatency(PendingCommand &pend)
@ -189,29 +191,26 @@ void AbstractClient::recordLatency(PendingCommand &pend)
<< "command RTT:" << elapsed << "ms (cmd_id" << pend.getCommandContainer().cmd_id() << ")"; << "command RTT:" << elapsed << "ms (cmd_id" << pend.getCommandContainer().cmd_id() << ")";
} }
if (elapsed >= SlowGameCommandWarnMs && pend.getCommandContainer().game_command_size() > 0) { if (elapsed >= SLOW_GAME_COMMAND_WARN_MS && pend.getCommandContainer().game_command_size() > 0) {
qCWarning(AbstractClientLog) << "slow game command round trip:" << elapsed << "ms (cmd_id" qCWarning(AbstractClientLog).noquote()
<< pend.getCommandContainer().cmd_id() << ")"; << "slow game command round trip:" << elapsed << "ms | " << getSafeDebugString(pend.getCommandContainer());
} }
// Emit aggregated stats at most once per StatsEmitIntervalMs so that the // Emit aggregated stats at most once per StatsEmitIntervalMs so that the
// per-command hot path stays free of signal traffic. The keepalive ping // per-command hot path stays free of signal traffic. The keepalive ping
// guarantees a fresh sample roughly every second while connected. // guarantees a fresh sample roughly every second while connected.
if (!statsEmitClockStarted || statsEmitClock.elapsed() >= StatsEmitIntervalMs) { if (!statsEmitClockStarted || statsEmitClock.elapsed() >= STATS_EMIT_INTERVAL_MS) {
statsEmitClock.start(); statsEmitClock.start();
statsEmitClockStarted = true; statsEmitClockStarted = true;
const LatencyTracker::Stats stats = latencyTracker.stats(); const LatencyTracker::Stats stats = latencyTracker.stats();
const QList<qint64> recentSamples = latencyTracker.recentSamples();
QList<int> samples; QList<int> samples;
samples.reserve(stats.sampleCount); samples.reserve(stats.sampleCount);
for (qint64 sample : recentSamples) { for (qint64 sample : latencyTracker.recentSamples()) {
samples.append(static_cast<int>(sample)); samples.append(static_cast<int>(sample));
} }
emit pingStatsUpdated(static_cast<int>(stats.lastMs), static_cast<int>(stats.medianMs), emit pingStatsUpdated(stats, samples);
static_cast<int>(stats.p95Ms), static_cast<int>(stats.maxMs), stats.sampleCount);
emit pingSamplesUpdated(samples);
} }
} }
@ -219,8 +218,7 @@ void AbstractClient::clearLatencyStats()
{ {
latencyTracker.clear(); latencyTracker.clear();
statsEmitClockStarted = false; statsEmitClockStarted = false;
emit pingStatsUpdated(0, 0, 0, 0, 0); emit pingStatsUpdated(LatencyTracker::Stats{}, {});
emit pingSamplesUpdated({});
} }
PendingCommand *AbstractClient::prepareSessionCommand(const ::google::protobuf::Message &cmd) PendingCommand *AbstractClient::prepareSessionCommand(const ::google::protobuf::Message &cmd)

View file

@ -61,21 +61,16 @@ signals:
void maxPingTime(int seconds, int maxSeconds); void maxPingTime(int seconds, int maxSeconds);
/** /**
* @brief Aggregated round-trip statistics, emitted at most once per second. * @brief Aggregated round-trip statistics and a chronological snapshot of
* the rolling window, emitted at most once per second.
* *
* All values are in milliseconds. sampleCount is the number of samples * All values in the stats struct are in milliseconds; sampleCount is the
* currently in the rolling window. Emitted from the client thread. The * number of samples currently in the rolling window. The samples list is
* connection to UI objects is automatically queued across threads. * 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(int lastMs, int medianMs, int p95Ms, int maxMs, int sampleCount); void pingStatsUpdated(const LatencyTracker::Stats &stats, const QList<int> &samplesMs);
/**
* @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<int> &samplesMs);
// Room events // Room events
void roomEventReceived(const RoomEvent &event); void roomEventReceived(const RoomEvent &event);
@ -143,8 +138,8 @@ public:
/** /**
* @brief Drops all recorded round-trip samples and resets the stats * @brief Drops all recorded round-trip samples and resets the stats
* emission throttle, emitting a zeroed pingStatsUpdated so that UI * emission throttle, emitting zeroed stats so that UI listeners can
* listeners can clear their display. * clear their display.
* *
* Must be called from the client thread (as RemoteClient's disconnect * Must be called from the client thread (as RemoteClient's disconnect
* path does). The tracker is deliberately lock-free. * path does). The tracker is deliberately lock-free.

View file

@ -7,6 +7,7 @@
#define LATENCY_TRACKER_H #define LATENCY_TRACKER_H
#include <QList> #include <QList>
#include <QMetaType>
#include <array> #include <array>
/** /**
@ -45,4 +46,6 @@ private:
int count = 0; ///< number of valid samples, capped at WindowSize int count = 0; ///< number of valid samples, capped at WindowSize
}; };
Q_DECLARE_METATYPE(LatencyTracker::Stats)
#endif #endif