[Client/Server/Protocol] Surface live metrics in the Developer tab (#7212)

* [Server] Instrument command processing, game starts, and event loops

Add a lock-free MetricsRegistry that accumulates per-command processing
times in preallocated histogram slots (one per protobuf command type,
bucketed at 1/5/10/25/50/100/250/500/1000/2500/5000 ms +Inf). The
hot-path observeCommand() uses only relaxed atomic adds — no locks,
no allocations, no cache-line ping-pong beyond the unavoidable counter
updates.

Wire the registry into AbstractServerSocketInterface::processCommandContainer()
so every processed command is attributed with its container's wall-clock
time. When a container exceeds metrics/slow_command_ms (default 500),
a warning is logged including the connected username.

Add an EventLoopWatchdog heartbeat that runs on every socket pool thread.
If a heartbeat overshoots metrics/stall_warn_ms (default 2000 ms), the
overshoot is recorded in atomic counters and a warning is logged. Both
thresholds are configurable in servatrice.ini; setting stall_warn_ms to 0
disables the watchdogs entirely.

Track game-start durations via a separate histogram in MetricsRegistry.
Server_Game::startGameNow() measures the time from zone creation through
player materialization and reports it via Server::observeGameStartDurationMs().

Add a live card-count gauge: Server_Game exposes getCardsInGame() and
Servatrice::getCardsInGamesTotal() sums across all running games under
the appropriate read locks.

Include a standalone metrics_registry_test (Google Test) that validates
empty registries, single/multi-sample histograms, kind encoding,
overflow-slot collapse, negative-duration clamping, gauge rendering,
and the game-start histogram separation.

Took 10 minutes

* [Client/Server/Protocol] Surface live metrics in the Developer tab

Extend Response_GetServerStats with live counters from the in-process
MetricsRegistry: cards in games, event loop stall totals/worst,
total commands processed, average command time, active command types,
and game-start count/duration. Add a repeated CommandStats message
carrying per-command breakdowns (kind, extension number, resolved
protobuf name, count, total ms) for every type that has seen at
least one sample.

Server-side cmdGetServerStats() populates all new fields after the
existing DB uptime snapshot query, resolving protobuf extension names
via the descriptor pool for human-readable labels like
session/Command_Ping.

Expand TabDeveloper with two tables: an overview section (existing
DB stats plus the new live metrics) and a per-command breakdown table
(Command / Count / Total ms / Avg ms) sorted by total_ms descending
so the hottest commands surface first.

Took 55 minutes

Took 47 seconds

* [Server] Drop dead Prometheus histogram, add developer command metrics, fix watchdog init order

- metrics_registry: remove toPrometheusText/appendCumulativeBuckets and the time-bucket histogram that nothing in production ever emitted (the future /metrics exporter can bring it back); keep counts/totals read by the Developer tab
- Fix +Inf bucket routing that never incremented, and its test that locked the bug in
- Instrument developer_command container (kind 6) in processCommandContainer and stats label resolution
- Read metrics/{slow_command_ms,stall_warn_ms} at the top of initServer() so stall_warn_ms=0 disables the watchdogs before pool threads start
- Shrink KindStride to 1280 (largest extension in use is 1206) with a static_assert; document scrape cost of getCardsInGamesTotal; note slow_command logging has no rate limit in servatrice.ini.example

* [Tests] Give metrics_registry_test an explicit main

* [Server] Record only the dispatched command family; drop unused totals

processCommandContainer recorded every family in a container even though
the base if/else-if dispatch processes at most one. An unauthenticated
client could batch a session command (login) with fabricated developer,
moderator, and admin entries and forge genuine-looking samples that were
never executed or authorized. Mirror the base's selection, skip when the
handler was already deleted, and skip entries whose extension number is
-1 (which would otherwise wrap into the previous kind's id range).

[Server] Drop dead process-lifetime byte/uptime counters

txBytesTotal/rxBytesTotal added an atomic RMW to every socket write and
read for counters nothing consumes (cmdGetServerStats fills tx_bytes,
rx_bytes, and uptime_secs from the DB snapshot). Remove the two atomics
and the getTxBytesTotal/getRxBytesTotal/getUptimeSeconds getters; the
incTxBytes/incRxBytes slots and mutexes remain for the ISL legacy
counters.

[Protocol] Document kind 5 as developer in CommandStats

NumKinds is 6 and the server emits kind_index = 5 for developer
commands; the comment stopped at 4.

* [Client] Togglable auto-refresh for Developer stats tab

* [Oracle] Fix clang-format alignment of card type priority list

---------

Co-authored-by: Lukas Brübach <Bruebach.Lukas@bdosecurity.de>
This commit is contained in:
BruebachL 2026-09-11 17:18:56 +02:00 committed by GitHub
parent d5d99e4dfb
commit 202a5ac958
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
22 changed files with 818 additions and 7 deletions

View file

@ -6,40 +6,80 @@
#include "tab_developer.h" #include "tab_developer.h"
#include <QCheckBox>
#include <QDateTime> #include <QDateTime>
#include <QHBoxLayout>
#include <QHeaderView> #include <QHeaderView>
#include <QLabel> #include <QLabel>
#include <QPushButton> #include <QPushButton>
#include <QSpinBox>
#include <QTableWidget> #include <QTableWidget>
#include <QTimer>
#include <QVBoxLayout> #include <QVBoxLayout>
#include <algorithm>
#include <libcockatrice/network/client/abstract/abstract_client.h> #include <libcockatrice/network/client/abstract/abstract_client.h>
#include <libcockatrice/protocol/pb/command_get_server_stats.pb.h> #include <libcockatrice/protocol/pb/command_get_server_stats.pb.h>
#include <libcockatrice/protocol/pb/response_get_server_stats.pb.h> #include <libcockatrice/protocol/pb/response_get_server_stats.pb.h>
#include <libcockatrice/protocol/pending_command.h> #include <libcockatrice/protocol/pending_command.h>
static constexpr int DEFAULT_AUTO_REFRESH_INTERVAL_SECS = 30;
TabDeveloper::TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_client) TabDeveloper::TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_client)
: Tab(_tabSupervisor), client(_client) : Tab(_tabSupervisor), client(_client)
{ {
statsTable = new QTableWidget(0, 2); statsTable = new QTableWidget(0, 2);
statsTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Expanding); statsTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Preferred);
statsTable->setEditTriggers(QAbstractItemView::NoEditTriggers); statsTable->setEditTriggers(QAbstractItemView::NoEditTriggers);
statsTable->setSelectionBehavior(QAbstractItemView::SelectRows); statsTable->setSelectionBehavior(QAbstractItemView::SelectRows);
statsTable->setSelectionMode(QAbstractItemView::SingleSelection); statsTable->setSelectionMode(QAbstractItemView::SingleSelection);
statsTable->horizontalHeader()->setStretchLastSection(true);
statsTable->verticalHeader()->setVisible(false); statsTable->verticalHeader()->setVisible(false);
statsTable->horizontalHeader()->setSectionResizeMode(0, QHeaderView::Interactive);
statsTable->horizontalHeader()->setSectionResizeMode(1, QHeaderView::Interactive);
statsTable->horizontalHeader()->setStretchLastSection(true);
commandTable = new QTableWidget(0, 4);
commandTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Expanding);
commandTable->setEditTriggers(QAbstractItemView::NoEditTriggers);
commandTable->setSelectionBehavior(QAbstractItemView::SelectRows);
commandTable->setSelectionMode(QAbstractItemView::SingleSelection);
commandTable->verticalHeader()->setVisible(false);
commandTable->horizontalHeader()->setSectionResizeMode(0, QHeaderView::Interactive);
commandTable->horizontalHeader()->setSectionResizeMode(1, QHeaderView::Interactive);
commandTable->horizontalHeader()->setSectionResizeMode(2, QHeaderView::Interactive);
commandTable->horizontalHeader()->setSectionResizeMode(3, QHeaderView::Interactive);
statusLabel = new QLabel; statusLabel = new QLabel;
autoRefreshCheckBox = new QCheckBox;
autoRefreshCheckBox->setChecked(false);
refreshIntervalSpinBox = new QSpinBox;
refreshIntervalSpinBox->setRange(5, 3600);
refreshIntervalSpinBox->setValue(DEFAULT_AUTO_REFRESH_INTERVAL_SECS);
refreshIntervalSpinBox->setEnabled(false);
autoRefreshTimer = new QTimer(this);
connect(autoRefreshTimer, &QTimer::timeout, this, &TabDeveloper::refreshClicked);
connect(autoRefreshCheckBox, &QCheckBox::toggled, this, &TabDeveloper::autoRefreshToggled);
connect(refreshIntervalSpinBox, QOverload<int>::of(&QSpinBox::valueChanged), this,
&TabDeveloper::refreshIntervalChanged);
refreshButton = new QPushButton; refreshButton = new QPushButton;
refreshButton->setAutoDefault(true); refreshButton->setAutoDefault(true);
connect(refreshButton, &QPushButton::clicked, this, &TabDeveloper::refreshClicked); connect(refreshButton, &QPushButton::clicked, this, &TabDeveloper::refreshClicked);
auto *buttonLayout = new QHBoxLayout; auto *buttonLayout = new QHBoxLayout;
buttonLayout->addWidget(statusLabel, 1, Qt::AlignLeft); buttonLayout->addWidget(statusLabel, 1, Qt::AlignLeft);
buttonLayout->addWidget(autoRefreshCheckBox, 0, Qt::AlignRight);
buttonLayout->addWidget(refreshIntervalSpinBox, 0, Qt::AlignRight);
buttonLayout->addWidget(refreshButton, 0, Qt::AlignRight); buttonLayout->addWidget(refreshButton, 0, Qt::AlignRight);
auto *tableLayout = new QHBoxLayout;
tableLayout->addWidget(statsTable, 1);
tableLayout->addWidget(commandTable, 2);
auto *mainLayout = new QVBoxLayout; auto *mainLayout = new QVBoxLayout;
mainLayout->addWidget(statsTable); mainLayout->addLayout(tableLayout, 1);
mainLayout->addLayout(buttonLayout); mainLayout->addLayout(buttonLayout);
auto *central = new QWidget; auto *central = new QWidget;
@ -51,8 +91,13 @@ TabDeveloper::TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_clien
void TabDeveloper::retranslateUi() void TabDeveloper::retranslateUi()
{ {
autoRefreshCheckBox->setText(tr("Auto-refresh"));
autoRefreshCheckBox->setToolTip(tr("Automatically request fresh server statistics at a fixed interval."));
refreshIntervalSpinBox->setSuffix(tr(" s"));
refreshIntervalSpinBox->setToolTip(tr("Seconds between automatic refreshes."));
refreshButton->setText(tr("Refresh server stats")); refreshButton->setText(tr("Refresh server stats"));
statsTable->setHorizontalHeaderLabels(QString(tr("Statistic;Value")).split(";")); statsTable->setHorizontalHeaderLabels(QString(tr("Statistic;Value")).split(";"));
commandTable->setHorizontalHeaderLabels(QString(tr("Command;Count;Total ms;Avg ms")).split(";"));
if (statsTable->rowCount() == 0) { if (statsTable->rowCount() == 0) {
statusLabel->clear(); statusLabel->clear();
} }
@ -75,6 +120,14 @@ QString TabDeveloper::formatBytes(quint64 bytes)
return tr("%1 bytes").arg(bytes); return tr("%1 bytes").arg(bytes);
} }
QString TabDeveloper::formatDurationMs(qint64 ms)
{
if (ms >= 1000) {
return tr("%1 s").arg(QString::number(ms / 1000.0, 'f', 2));
}
return tr("%1 ms").arg(ms);
}
void TabDeveloper::appendStatRow(const QString &name, const QString &value) void TabDeveloper::appendStatRow(const QString &name, const QString &value)
{ {
const int row = statsTable->rowCount(); const int row = statsTable->rowCount();
@ -83,16 +136,52 @@ void TabDeveloper::appendStatRow(const QString &name, const QString &value)
statsTable->setItem(row, 1, new QTableWidgetItem(value)); statsTable->setItem(row, 1, new QTableWidgetItem(value));
} }
void TabDeveloper::appendSeparatorRow(const QString &sectionTitle)
{
const int row = statsTable->rowCount();
statsTable->insertRow(row);
auto *labelItem = new QTableWidgetItem(sectionTitle);
auto font = labelItem->font();
font.setBold(true);
labelItem->setFont(font);
labelItem->setFlags(labelItem->flags() & ~Qt::ItemIsSelectable);
statsTable->setItem(row, 0, labelItem);
statsTable->setItem(row, 1, new QTableWidgetItem(QString()));
}
void TabDeveloper::refreshClicked() void TabDeveloper::refreshClicked()
{ {
if (requestPending) {
return;
}
requestPending = true;
Command_GetServerStats cmd; Command_GetServerStats cmd;
PendingCommand *pend = client->prepareDeveloperCommand(cmd); PendingCommand *pend = client->prepareDeveloperCommand(cmd);
connect(pend, &PendingCommand::finished, this, &TabDeveloper::serverStatsResponse); connect(pend, &PendingCommand::finished, this, &TabDeveloper::serverStatsResponse);
client->sendCommand(pend); client->sendCommand(pend);
} }
void TabDeveloper::autoRefreshToggled(bool checked)
{
refreshIntervalSpinBox->setEnabled(checked);
if (checked) {
refreshIntervalChanged();
refreshClicked();
} else {
autoRefreshTimer->stop();
}
}
void TabDeveloper::refreshIntervalChanged()
{
if (autoRefreshCheckBox->isChecked()) {
autoRefreshTimer->start(refreshIntervalSpinBox->value() * 1000);
}
}
void TabDeveloper::serverStatsResponse(const Response &resp) void TabDeveloper::serverStatsResponse(const Response &resp)
{ {
requestPending = false;
if (resp.response_code() != Response::RespOk) { if (resp.response_code() != Response::RespOk) {
statusLabel->setText(tr("No server statistics available yet.")); statusLabel->setText(tr("No server statistics available yet."));
return; return;
@ -101,6 +190,8 @@ void TabDeveloper::serverStatsResponse(const Response &resp)
const Response_GetServerStats &response = resp.GetExtension(Response_GetServerStats::ext); const Response_GetServerStats &response = resp.GetExtension(Response_GetServerStats::ext);
statsTable->setRowCount(0); statsTable->setRowCount(0);
// Overview section
appendStatRow(tr("Registered users online"), QString::number(response.users_count())); appendStatRow(tr("Registered users online"), QString::number(response.users_count()));
appendStatRow(tr("Moderators online"), QString::number(response.mods_count())); appendStatRow(tr("Moderators online"), QString::number(response.mods_count()));
appendStatRow(tr("Games running"), QString::number(response.games_count())); appendStatRow(tr("Games running"), QString::number(response.games_count()));
@ -117,6 +208,54 @@ void TabDeveloper::serverStatsResponse(const Response &resp)
const QDateTime snapshotTime = QDateTime::fromSecsSinceEpoch(static_cast<qint64>(response.timest())); const QDateTime snapshotTime = QDateTime::fromSecsSinceEpoch(static_cast<qint64>(response.timest()));
appendStatRow(tr("Snapshot taken"), snapshotTime.toLocalTime().toString("yyyy-MM-dd HH:mm")); appendStatRow(tr("Snapshot taken"), snapshotTime.toLocalTime().toString("yyyy-MM-dd HH:mm"));
// Live metrics section
appendSeparatorRow(tr("Live Metrics"));
appendStatRow(tr("Cards in live games"), QString::number(response.cards_in_games()));
appendStatRow(tr("Total commands processed"), QString::number(response.total_commands()));
if (response.total_commands() > 0) {
const double avgMs = static_cast<double>(response.total_command_time_ms()) / response.total_commands();
appendStatRow(tr("Avg command time"), QString::number(avgMs, 'f', 2) + " ms");
}
appendStatRow(tr("Active command types"), QString::number(response.active_command_types()));
appendStatRow(tr("Event loop stalls"), QString::number(response.eventloop_stalls_total()));
appendStatRow(tr("Last stall overshoot"), formatDurationMs(response.eventloop_last_stall_ms()));
appendStatRow(tr("Worst stall overshoot"), formatDurationMs(response.eventloop_max_stall_ms()));
if (response.game_start_count() > 0) {
appendStatRow(tr("Game starts"), QString::number(response.game_start_count()));
const double avgStartMs = static_cast<double>(response.game_start_total_ms()) / response.game_start_count();
appendStatRow(tr("Avg game start time"), QString::number(avgStartMs, 'f', 1) + " ms");
}
// Per-command breakdown table
QList<CommandStats> sortedStats(response.command_stats().begin(), response.command_stats().end());
std::sort(sortedStats.begin(), sortedStats.end(),
[](const auto &a, const auto &b) { return a.total_ms() > b.total_ms(); });
commandTable->setRowCount(0);
for (const auto &cs : sortedStats) {
const int row = commandTable->rowCount();
commandTable->insertRow(row);
commandTable->setItem(row, 0, new QTableWidgetItem(QString::fromStdString(cs.command_name())));
auto *countItem = new QTableWidgetItem(QString::number(cs.count()));
countItem->setTextAlignment(Qt::AlignRight | Qt::AlignVCenter);
commandTable->setItem(row, 1, countItem);
auto *totalItem = new QTableWidgetItem(QString::number(cs.total_ms()));
totalItem->setTextAlignment(Qt::AlignRight | Qt::AlignVCenter);
commandTable->setItem(row, 2, totalItem);
const double avg = cs.count() > 0 ? static_cast<double>(cs.total_ms()) / cs.count() : 0.0;
auto *avgItem = new QTableWidgetItem(QString::number(avg, 'f', 2));
avgItem->setTextAlignment(Qt::AlignRight | Qt::AlignVCenter);
commandTable->setItem(row, 3, avgItem);
}
commandTable->resizeColumnsToContents();
statsTable->resizeColumnsToContents(); statsTable->resizeColumnsToContents();
commandTable->resizeColumnsToContents();
statusLabel->setText(tr("Updated %1").arg(QDateTime::currentDateTime().toString("yyyy-MM-dd HH:mm"))); statusLabel->setText(tr("Updated %1").arg(QDateTime::currentDateTime().toString("yyyy-MM-dd HH:mm")));
} }

View file

@ -10,9 +10,12 @@
#include "tab.h" #include "tab.h"
class AbstractClient; class AbstractClient;
class QCheckBox;
class QLabel; class QLabel;
class QPushButton; class QPushButton;
class QSpinBox;
class QTableWidget; class QTableWidget;
class QTimer;
class Response; class Response;
class TabDeveloper : public Tab class TabDeveloper : public Tab
@ -21,15 +24,24 @@ class TabDeveloper : public Tab
private: private:
AbstractClient *client; AbstractClient *client;
QTableWidget *statsTable; QTableWidget *statsTable;
QTableWidget *commandTable;
QPushButton *refreshButton; QPushButton *refreshButton;
QLabel *statusLabel; QLabel *statusLabel;
QCheckBox *autoRefreshCheckBox;
QSpinBox *refreshIntervalSpinBox;
QTimer *autoRefreshTimer;
bool requestPending = false;
void appendStatRow(const QString &name, const QString &value); void appendStatRow(const QString &name, const QString &value);
void appendSeparatorRow(const QString &sectionTitle);
static QString formatBytes(quint64 bytes); static QString formatBytes(quint64 bytes);
static QString formatDurationMs(qint64 ms);
private slots: private slots:
void refreshClicked(); void refreshClicked();
void serverStatsResponse(const Response &resp); void serverStatsResponse(const Response &resp);
void autoRefreshToggled(bool checked);
void refreshIntervalChanged();
public: public:
explicit TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_client); explicit TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_client);

View file

@ -66,6 +66,15 @@ Server_AbstractPlayer::Server_AbstractPlayer(Server_Game *_game,
Server_AbstractPlayer::~Server_AbstractPlayer() = default; Server_AbstractPlayer::~Server_AbstractPlayer() = default;
int Server_AbstractPlayer::getCardCount() const
{
int result = 0;
for (auto *zone : zones) {
result += zone->getCards().size();
}
return result;
}
void Server_AbstractPlayer::prepareDestroy() void Server_AbstractPlayer::prepareDestroy()
{ {
delete deck; delete deck;

View file

@ -43,6 +43,8 @@ public:
Server_AbstractUserInterface *_handler); Server_AbstractUserInterface *_handler);
~Server_AbstractPlayer() override; ~Server_AbstractPlayer() override;
void prepareDestroy() override; void prepareDestroy() override;
/// Total cards across all of this player's zones. The caller must hold the game's mutex.
int getCardCount() const;
const DeckList *getDeckList() const const DeckList *getDeckList() const
{ {
return deck; return deck;

View file

@ -32,6 +32,7 @@
#include "server_spectator.h" #include "server_spectator.h"
#include <QDebug> #include <QDebug>
#include <QElapsedTimer>
#include <QRegularExpression> #include <QRegularExpression>
#include <QTimer> #include <QTimer>
#include <google/protobuf/descriptor.h> #include <google/protobuf/descriptor.h>
@ -238,6 +239,17 @@ int Server_Game::getPlayerCount() const
return participants.size() - getSpectatorCount(); return participants.size() - getSpectatorCount();
} }
int Server_Game::getCardsInGame() const
{
QMutexLocker locker(&gameMutex);
int result = 0;
for (auto *player : getPlayers()) {
result += player->getCardCount();
}
return result;
}
int Server_Game::getSpectatorCount() const int Server_Game::getSpectatorCount() const
{ {
QMutexLocker locker(&gameMutex); QMutexLocker locker(&gameMutex);
@ -330,6 +342,9 @@ void Server_Game::doStartGameIfReady(bool forceStartGame)
} }
} }
// Only actual starts are timed. The early returns above are no-ops.
QElapsedTimer startupTimer;
startupTimer.start();
players = getPlayers(); // players could have been kicked, get new list of players players = getPlayers(); // players could have been kicked, get new list of players
if (lifecycleStrategy->onGameStarting(this) == Server_GameLifecycleStrategy::StartAction::Handled) { if (lifecycleStrategy->onGameStarting(this) == Server_GameLifecycleStrategy::StartAction::Handled) {
locker.unlock(); locker.unlock();
@ -373,6 +388,7 @@ void Server_Game::doStartGameIfReady(bool forceStartGame)
activePlayer = -1; activePlayer = -1;
nextTurn(); nextTurn();
room->getServer()->observeGameStartDurationMs(startupTimer.nsecsElapsed() / 1000000);
locker.unlock(); locker.unlock();

View file

@ -123,6 +123,8 @@ public:
return gameStarted; return gameStarted;
} }
int getPlayerCount() const; int getPlayerCount() const;
/// Total cards across all players' zones. Takes gameMutex itself.
int getCardsInGame() const;
int getSpectatorCount() const; int getSpectatorCount() const;
QMap<int, Server_AbstractPlayer *> getPlayers() const; QMap<int, Server_AbstractPlayer *> getPlayers() const;
Server_AbstractPlayer *getPlayer(int id) const; Server_AbstractPlayer *getPlayer(int id) const;

View file

@ -180,6 +180,11 @@ public:
{ {
return false; return false;
} }
/// Called once per actual game start with how long bringing every player's
/// zones online took, so servers can spot deck sizes that wedge threads.
virtual void observeGameStartDurationMs(qint64 /* elapsedMs */)
{
}
Server_DatabaseInterface *getDatabaseInterface() const; Server_DatabaseInterface *getDatabaseInterface() const;
int getNextLocalGameId() int getNextLocalGameId()

View file

@ -136,7 +136,7 @@ public:
return timeRunning - lastDataReceived; return timeRunning - lastDataReceived;
} }
bool addSaidMessageSize(int size); bool addSaidMessageSize(int size);
void processCommandContainer(const CommandContainer &cont); virtual void processCommandContainer(const CommandContainer &cont);
void sendProtocolItem(const Response &item); void sendProtocolItem(const Response &item);
void sendProtocolItem(const SessionEvent &item); void sendProtocolItem(const SessionEvent &item);

View file

@ -1,6 +1,14 @@
syntax = "proto2"; syntax = "proto2";
import "response.proto"; import "response.proto";
message CommandStats {
optional uint32 kind_index = 1; // 0=session, 1=room, 2=game, 3=moderator, 4=admin, 5=developer
optional uint32 extension_number = 2; // protobuf extension number within the kind
optional string command_name = 3; // e.g. "session/Command_Ping"
optional uint64 count = 4; // number of times observed
optional uint64 total_ms = 5; // cumulative processing milliseconds
}
message Response_GetServerStats { message Response_GetServerStats {
extend Response { extend Response {
optional Response_GetServerStats ext = 1220; optional Response_GetServerStats ext = 1220;
@ -16,4 +24,18 @@ message Response_GetServerStats {
optional uint64 uptime_secs = 6; optional uint64 uptime_secs = 6;
optional uint64 timest = 7; // unix timestamp of the snapshot optional uint64 timest = 7; // unix timestamp of the snapshot
// Live metrics from MetricsRegistry (reset on server restart)
optional uint64 cards_in_games = 8;
optional uint64 eventloop_stalls_total = 9;
optional uint64 eventloop_last_stall_ms = 10;
optional uint64 eventloop_max_stall_ms = 11;
optional uint64 total_commands = 12;
optional uint64 total_command_time_ms = 13;
optional int32 active_command_types = 14;
optional uint64 game_start_count = 15;
optional uint64 game_start_total_ms = 16;
// Per-command breakdown (only types with count > 0)
repeated CommandStats command_stats = 20;
} }

View file

@ -6,7 +6,9 @@ project(Servatrice VERSION "${PROJECT_VERSION_MAJOR}.${PROJECT_VERSION_MINOR}.${
set(servatrice_SOURCES set(servatrice_SOURCES
src/email_parser.cpp src/email_parser.cpp
src/event_loop_watchdog.cpp
src/main.cpp src/main.cpp
src/metrics_registry.cpp
src/servatrice.cpp src/servatrice.cpp
src/servatrice_connection_pool.cpp src/servatrice_connection_pool.cpp
src/servatrice_database_interface.cpp src/servatrice_database_interface.cpp

View file

@ -382,6 +382,19 @@ max_reports_per_day=10
; Maximum number of report comments a single user can post per hour; default is 30; set to 0 to disable the limit ; Maximum number of report comments a single user can post per hour; default is 30; set to 0 to disable the limit
max_comments_per_hour=30 max_comments_per_hour=30
[metrics]
; Command containers that take longer than this many milliseconds are logged
; as slow commands. Set to 0 to disable the log line. A latency spike produces
; one warning per slow container with no rate limiting of its own -- a bad
; patch can briefly flood the log, which is how you notice it.
slow_command_ms=500
; Each socket pool thread runs a watchdog heartbeat. If a heartbeat arrives
; this many milliseconds late, the stall is logged and exposed as
; servatrice_eventloop_* metrics in the Developer tab. Set to 0 to disable
; the watchdogs.
stall_warn_ms=2000
[logging] [logging]
; Admin/Moderators can query the stored logs for information when looking up reports by various players. This ; Admin/Moderators can query the stored logs for information when looking up reports by various players. This
; option can allow or disallow them from doing so. ; option can allow or disallow them from doing so.

View file

@ -0,0 +1,34 @@
/**
* @file event_loop_watchdog.cpp
* @ingroup Servatrice
*/
#include "event_loop_watchdog.h"
#include "servatrice.h"
#include <QTimer>
EventLoopWatchdog::EventLoopWatchdog(Servatrice *_servatrice, QString _threadName)
: QObject(nullptr), servatrice(_servatrice), threadName(std::move(_threadName))
{
}
void EventLoopWatchdog::start()
{
heartbeatTimer = new QTimer(this);
sinceLastTick.start();
connect(heartbeatTimer, &QTimer::timeout, this, &EventLoopWatchdog::checkHeartbeat);
heartbeatTimer->start(HeartbeatIntervalMs);
}
void EventLoopWatchdog::checkHeartbeat()
{
const qint64 elapsedMs = sinceLastTick.restart();
const qint64 overshootMs = qMax<qint64>(0, elapsedMs - HeartbeatIntervalMs);
if (overshootMs < servatrice->getMetricsStallWarnMs()) {
return;
}
servatrice->observeEventLoopStall(threadName, overshootMs);
}

View file

@ -0,0 +1,50 @@
/**
* @file event_loop_watchdog.h
* @ingroup Servatrice
*/
#ifndef EVENT_LOOP_WATCHDOG_H
#define EVENT_LOOP_WATCHDOG_H
#include <QElapsedTimer>
#include <QObject>
#include <QString>
class Servatrice;
class QTimer;
/**
* @brief Detects blocked or overloaded worker event loops.
*
* One instance lives in each socket pool thread. A heartbeat timer tick that
* arrives late means the loop spent that time elsewhere: busy work, a queued
* slot, or a hard wedge. Overshoots past the configured threshold bump
* lock-free counters on the metrics registry and log one warning per stall,
* so a stuck pool thread becomes visible instead of silent lag.
*/
class EventLoopWatchdog : public QObject
{
Q_OBJECT
public:
/// How often the heartbeat expects to fire. Small enough to catch short stalls.
static constexpr int HeartbeatIntervalMs = 500;
EventLoopWatchdog(Servatrice *_servatrice, QString _threadName);
/**
* Starts the heartbeat timer. Must be invoked queued after the instance
* was moved to its target thread so the timer lives there too.
*/
void start();
private slots:
void checkHeartbeat();
private:
Servatrice *servatrice;
QString threadName;
QElapsedTimer sinceLastTick;
QTimer *heartbeatTimer = nullptr;
};
#endif

View file

@ -0,0 +1,70 @@
#include "metrics_registry.h"
#include <QList>
void MetricsRegistry::observeCommand(int typeId, qint64 elapsedMs)
{
if (typeId < 0 || typeId >= MaxTypes) {
typeId = MaxTypes - 1; // overflow slot keeps misrouted ids visible
}
if (elapsedMs < 0) {
elapsedMs = 0;
}
TypeStats &stats = slotFor(typeId);
stats.count.fetch_add(1, std::memory_order_relaxed);
stats.totalMs.fetch_add(elapsedMs, std::memory_order_relaxed);
totalCommandsCounter.fetch_add(1, std::memory_order_relaxed);
totalTimeCounter.fetch_add(elapsedMs, std::memory_order_relaxed);
}
void MetricsRegistry::observeGameStartDurationMs(qint64 elapsedMs)
{
if (elapsedMs < 0) {
elapsedMs = 0;
}
gameStartStats.count.fetch_add(1, std::memory_order_relaxed);
gameStartStats.totalMs.fetch_add(elapsedMs, std::memory_order_relaxed);
}
MetricsRegistry::TypeStats &MetricsRegistry::slotFor(int typeId)
{
return typeSlots[static_cast<size_t>(typeId)];
}
const MetricsRegistry::TypeStats &MetricsRegistry::slotFor(int typeId) const
{
return typeSlots[static_cast<size_t>(typeId)];
}
int MetricsRegistry::activeTypeCount() const
{
int active = 0;
for (int type = 0; type < MaxTypes; ++type) {
if (slotFor(type).count.load(std::memory_order_relaxed) > 0) {
++active;
}
}
return active;
}
QList<MetricsRegistry::ActiveTypeStats> MetricsRegistry::collectActiveStats() const
{
QList<ActiveTypeStats> result;
for (int type = 0; type < MaxTypes; ++type) {
const TypeStats &stats = slotFor(type);
const qint64 count = stats.count.load(std::memory_order_relaxed);
if (count == 0) {
continue;
}
result.append({type, count, stats.totalMs.load(std::memory_order_relaxed)});
}
return result;
}
MetricsRegistry::GameStartSnapshot MetricsRegistry::getGameStartSnapshot() const
{
return {gameStartStats.count.load(std::memory_order_relaxed),
gameStartStats.totalMs.load(std::memory_order_relaxed)};
}

View file

@ -0,0 +1,120 @@
/**
* @file metrics_registry.h
* @ingroup Servatrice
*/
#ifndef METRICS_REGISTRY_H
#define METRICS_REGISTRY_H
#include <QList>
#include <QString>
#include <array>
#include <atomic>
/**
* @brief Lock-free accumulation of command processing statistics.
*
* observeCommand() is called once per processed command from whichever socket
* thread handled it. It uses relaxed atomic adds on preallocated storage only,
* so it introduces no locks, allocations, or shared cache-line ping-pong
* beyond the unavoidable counter updates.
*
* Reading happens rarely (metrics scraping), accepts momentary tears between
* related counters, and therefore also needs no synchronization.
*
* Only counts and totals are retained. An earlier Prometheus-style cumulative
* histogram (per-type, time-bucketed) was cut because nothing in the server
* ever wrote it out; it belongs to the future /metrics exporter that needs it.
*/
class MetricsRegistry
{
public:
/**
* Extension numbers are only unique per command kind, so recorded ids
* combine the kind index with the protobuf extension number.
*
* The stride is only as wide as it needs to be: 1280 is the first round
* number above the largest extension actually in use (ModeratorCommand =
* 1206) and keeps the preallocated TypeStats array small. Bump it if a new
* command exceeds it.
*/
static constexpr int KindStride = 1280;
static constexpr int NumKinds = 6;
static constexpr const char *KindNames[NumKinds] = {"session", "room", "game", "moderator", "admin", "developer"};
/// Upper bound on distinct command type ids (see typeIdFor).
static constexpr int MaxTypes = NumKinds * KindStride;
/// Guard against typeIdFor() overflowing into the neighbouring kind's slots.
static_assert(KindStride > 1206, "KindStride must exceed the highest command extension number in use");
static int typeIdFor(int kindIndex, int extensionNumber)
{
return kindIndex * KindStride + extensionNumber;
}
void observeCommand(int typeId, qint64 elapsedMs);
/**
* Records how long one game start took to bring every player's zones
* online. Kept separate from command timings because it is triggered by
* the server itself and can dwarf any single command when decks are huge.
*/
void observeGameStartDurationMs(qint64 elapsedMs);
/// Total number of observed commands across all types.
qint64 totalCommands() const
{
return totalCommandsCounter.load(std::memory_order_relaxed);
}
/// Cumulative processing milliseconds across all types.
qint64 totalTimeMs() const
{
return totalTimeCounter.load(std::memory_order_relaxed);
}
/// Number of distinct type slots that have seen at least one sample.
int activeTypeCount() const;
struct ActiveTypeStats
{
int typeId;
qint64 count;
qint64 totalMs;
};
/**
* Returns stats for every type slot that has seen at least one sample.
* Callers resolve the numeric type id to a human-readable label via
* typeIdFor()/KindNames as needed.
*/
QList<ActiveTypeStats> collectActiveStats() const;
struct GameStartSnapshot
{
qint64 count;
qint64 totalMs;
};
GameStartSnapshot getGameStartSnapshot() const;
private:
struct TypeStats
{
std::atomic<qint64> count{0};
std::atomic<qint64> totalMs{0};
};
TypeStats &slotFor(int typeId);
const TypeStats &slotFor(int typeId) const;
std::array<TypeStats, MaxTypes> typeSlots{};
TypeStats gameStartStats{};
std::atomic<qint64> totalCommandsCounter{0};
std::atomic<qint64> totalTimeCounter{0};
};
#endif

View file

@ -20,6 +20,7 @@
#include "servatrice.h" #include "servatrice.h"
#include "email_parser.h" #include "email_parser.h"
#include "event_loop_watchdog.h"
#include "isl_interface.h" #include "isl_interface.h"
#include "main.h" #include "main.h"
#include "servatrice_connection_pool.h" #include "servatrice_connection_pool.h"
@ -38,6 +39,7 @@
#include <QStringList> #include <QStringList>
#include <QTimer> #include <QTimer>
#include <QUrl> #include <QUrl>
#include <game/server_game.h>
#include <iostream> #include <iostream>
#include <libcockatrice/deck_list/deck_list.h> #include <libcockatrice/deck_list/deck_list.h>
#include <libcockatrice/protocol/featureset.h> #include <libcockatrice/protocol/featureset.h>
@ -63,6 +65,7 @@ Servatrice_GameServer::Servatrice_GameServer(Servatrice *_server,
server->addDatabaseInterface(newThread, newDatabaseInterface); server->addDatabaseInterface(newThread, newDatabaseInterface);
newThread->start(); newThread->start();
server->watchWorkerThread(newThread);
QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection, QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection,
Q_ARG(QSqlDatabase, _sqlDatabase)); Q_ARG(QSqlDatabase, _sqlDatabase));
@ -86,7 +89,6 @@ void Servatrice_GameServer::incomingConnection(qintptr socketDescriptor)
Servatrice_ConnectionPool *pool = findLeastUsedConnectionPool(); Servatrice_ConnectionPool *pool = findLeastUsedConnectionPool();
auto ssi = new TcpServerSocketInterface(server, pool->getDatabaseInterface()); auto ssi = new TcpServerSocketInterface(server, pool->getDatabaseInterface());
connect(ssi, SIGNAL(incTxBytes(qint64)), this, SLOT(incTxBytes(qint64)));
ssi->moveToThread(pool->thread()); ssi->moveToThread(pool->thread());
pool->addClient(); pool->addClient();
connect(ssi, SIGNAL(destroyed()), pool, SLOT(removeClient())); connect(ssi, SIGNAL(destroyed()), pool, SLOT(removeClient()));
@ -131,6 +133,7 @@ Servatrice_WebsocketGameServer::Servatrice_WebsocketGameServer(Servatrice *_serv
server->addDatabaseInterface(newThread, newDatabaseInterface); server->addDatabaseInterface(newThread, newDatabaseInterface);
newThread->start(); newThread->start();
server->watchWorkerThread(newThread);
QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection, QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection,
Q_ARG(QSqlDatabase, _sqlDatabase)); Q_ARG(QSqlDatabase, _sqlDatabase));
@ -156,7 +159,6 @@ void Servatrice_WebsocketGameServer::onNewConnection()
Servatrice_ConnectionPool *pool = findLeastUsedConnectionPool(); Servatrice_ConnectionPool *pool = findLeastUsedConnectionPool();
auto ssi = new WebsocketServerSocketInterface(server, pool->getDatabaseInterface()); auto ssi = new WebsocketServerSocketInterface(server, pool->getDatabaseInterface());
connect(ssi, SIGNAL(incTxBytes(quint64)), this, SLOT(incTxBytes(quint64)));
/* /*
* Due to a Qt limitation, websockets can't be moved to another thread. * Due to a Qt limitation, websockets can't be moved to another thread.
* This will hopefully change in Qt6 if QtWebSocket will be integrated in QtNetwork * This will hopefully change in Qt6 if QtWebSocket will be integrated in QtNetwork
@ -226,6 +228,13 @@ bool Servatrice::initServer()
{ {
serverId = getServerID(); serverId = getServerID();
// METRICS (always active. Slow-command logging and stall watchdogs are
// controlled by their respective thresholds below). Read up front so the
// values are available before any pool thread is started and watchdogged.
metricsSlowCommandMs = settingsCache->value("metrics/slow_command_ms", 500).toInt();
metricsStallWarnMs = qMax(0, settingsCache->value("metrics/stall_warn_ms", 2000).toInt());
if (getAuthenticationMethodString() == "sql") { if (getAuthenticationMethodString() == "sql") {
qDebug() << "Authenticating method: sql"; qDebug() << "Authenticating method: sql";
authenticationMethod = AuthenticationSql; authenticationMethod = AuthenticationSql;
@ -470,9 +479,55 @@ bool Servatrice::initServer()
} }
setRequiredFeatures(getRequiredFeatures()); setRequiredFeatures(getRequiredFeatures());
return true; return true;
} }
void Servatrice::observeGameStartDurationMs(qint64 elapsedMs)
{
metricsRegistry.observeGameStartDurationMs(elapsedMs);
}
void Servatrice::observeEventLoopStall(const QString &threadName, qint64 overshootMs)
{
eventLoopStallsTotal.fetch_add(1, std::memory_order_relaxed);
eventLoopLastStallMs.store(overshootMs, std::memory_order_relaxed);
qint64 prevMax = eventLoopMaxStallMs.load(std::memory_order_relaxed);
while (overshootMs > prevMax &&
!eventLoopMaxStallMs.compare_exchange_weak(prevMax, overshootMs, std::memory_order_relaxed)) {
// retry until the max is at least as high as the new sample
}
qWarning() << "Event loop stall in" << threadName << "- heartbeat overshot by" << overshootMs << "ms";
}
void Servatrice::watchWorkerThread(QThread *thread)
{
if (metricsStallWarnMs <= 0) {
return; // watchdogs disabled via metrics/stall_warn_ms = 0
}
auto *watchdog = new EventLoopWatchdog(this, thread->objectName());
connect(thread, &QThread::finished, watchdog, &QObject::deleteLater);
watchdog->moveToThread(thread);
QMetaObject::invokeMethod(watchdog, &EventLoopWatchdog::start, Qt::QueuedConnection);
}
qint64 Servatrice::getCardsInGamesTotal() const
{
qint64 total = 0;
QReadLocker roomsLocker(&roomsLock); // locking order: roomsLock before gamesLock/gameMutex
QMapIterator<int, Server_Room *> roomIterator(rooms);
while (roomIterator.hasNext()) {
Server_Room *room = roomIterator.next().value();
QReadLocker gamesLocker(&room->gamesLock);
for (auto *game : room->getGames()) {
total += game->getCardsInGame();
}
}
return total;
}
void Servatrice::addDatabaseInterface(QThread *thread, Servatrice_DatabaseInterface *databaseInterface) void Servatrice::addDatabaseInterface(QThread *thread, Servatrice_DatabaseInterface *databaseInterface)
{ {
databaseInterfaces.insert(thread, databaseInterface); databaseInterfaces.insert(thread, databaseInterface);

View file

@ -20,6 +20,8 @@
#ifndef SERVATRICE_H #ifndef SERVATRICE_H
#define SERVATRICE_H #define SERVATRICE_H
#include "metrics_registry.h"
#include <QDateTime> #include <QDateTime>
#include <QHostAddress> #include <QHostAddress>
#include <QMetaType> #include <QMetaType>
@ -30,6 +32,7 @@
#include <QSslKey> #include <QSslKey>
#include <QTcpServer> #include <QTcpServer>
#include <QWebSocketServer> #include <QWebSocketServer>
#include <atomic>
#include <libcockatrice/protocol/pb/response_report_stats.pb.h> #include <libcockatrice/protocol/pb/response_report_stats.pb.h>
#include <memory> #include <memory>
#include <server.h> #include <server.h>
@ -170,6 +173,12 @@ private:
int uptime; int uptime;
QMutex txBytesMutex, rxBytesMutex; QMutex txBytesMutex, rxBytesMutex;
quint64 txBytes, rxBytes; quint64 txBytes, rxBytes;
MetricsRegistry metricsRegistry;
int metricsSlowCommandMs = 500;
int metricsStallWarnMs = 2000;
std::atomic<qint64> eventLoopStallsTotal{0}; ///< heartbeat overshoots past the warn threshold
std::atomic<qint64> eventLoopLastStallMs{0}; ///< overshoot of the most recent stall
std::atomic<qint64> eventLoopMaxStallMs{0}; ///< worst overshoot seen since process start
QString shutdownReason; QString shutdownReason;
int shutdownMinutes; int shutdownMinutes;
@ -286,6 +295,49 @@ public:
void incRxBytes(quint64 num); void incRxBytes(quint64 num);
void addDatabaseInterface(QThread *thread, Servatrice_DatabaseInterface *databaseInterface); void addDatabaseInterface(QThread *thread, Servatrice_DatabaseInterface *databaseInterface);
// Metrics (see [metrics] section in servatrice.ini.example)
MetricsRegistry &getMetricsRegistry()
{
return metricsRegistry;
}
/**
* Sums cards across all zones of all running games. Each game takes its
* own gameMutex -- the hot per-game lock every game action contends on --
* and then iterates every player's zones, so the scrape cost is really
* O(total cards in play) plus one mutex acquisition per live game. Keep
* scrapes infrequent in big multiplayer rooms.
*/
qint64 getCardsInGamesTotal() const;
int getMetricsSlowCommandMs() const
{
return metricsSlowCommandMs;
}
/// Heartbeat overshoot that counts as a stall. A value of 0 disables the watchdogs.
int getMetricsStallWarnMs() const
{
return metricsStallWarnMs;
}
void observeGameStartDurationMs(qint64 elapsedMs) override;
qint64 getEventLoopStallsTotal() const
{
return eventLoopStallsTotal.load(std::memory_order_relaxed);
}
qint64 getEventLoopLastStallMs() const
{
return eventLoopLastStallMs.load(std::memory_order_relaxed);
}
qint64 getEventLoopMaxStallMs() const
{
return eventLoopMaxStallMs.load(std::memory_order_relaxed);
}
/// Records one heartbeat overshoot and logs a single warning for it.
void observeEventLoopStall(const QString &threadName, qint64 overshootMs);
/**
* Installs an EventLoopWatchdog in @p thread. Called once per socket pool
* thread right after it starts.
*/
void watchWorkerThread(QThread *thread);
bool islConnectionExists(int _serverId) const; bool islConnectionExists(int _serverId) const;
void addIslInterface(int _serverId, IslInterface *interface); void addIslInterface(int _serverId, IslInterface *interface);
void removeIslInterface(int _serverId); void removeIslInterface(int _serverId);

View file

@ -30,6 +30,7 @@
#include <QDateTime> #include <QDateTime>
#include <QDebug> #include <QDebug>
#include <QElapsedTimer>
#include <QHostAddress> #include <QHostAddress>
#include <QJsonDocument> #include <QJsonDocument>
#include <QJsonObject> #include <QJsonObject>
@ -39,8 +40,10 @@
#include <QSqlQuery> #include <QSqlQuery>
#include <QString> #include <QString>
#include <game/server_player.h> #include <game/server_player.h>
#include <google/protobuf/descriptor.h>
#include <iostream> #include <iostream>
#include <libcockatrice/deck_list/deck_list.h> #include <libcockatrice/deck_list/deck_list.h>
#include <libcockatrice/protocol/get_pb_extension.h>
#include <libcockatrice/protocol/pb/command_deck_del.pb.h> #include <libcockatrice/protocol/pb/command_deck_del.pb.h>
#include <libcockatrice/protocol/pb/command_deck_del_dir.pb.h> #include <libcockatrice/protocol/pb/command_deck_del_dir.pb.h>
#include <libcockatrice/protocol/pb/command_deck_download.pb.h> #include <libcockatrice/protocol/pb/command_deck_download.pb.h>
@ -192,6 +195,77 @@ void AbstractServerSocketInterface::logDebugMessage(const QString &message)
logger->logMessage(message, this); logger->logMessage(message, this);
} }
void AbstractServerSocketInterface::processCommandContainer(const CommandContainer &cont)
{
QElapsedTimer timer;
timer.start();
Server_ProtocolHandler::processCommandContainer(cont);
const qint64 elapsedMs = timer.nsecsElapsed() / 1000000;
// The base dispatch is an if/else-if chain — at most one family is
// actually processed. Recording every family in the container would
// let an unauthenticated client stampforge developer/moderator/admin
// samples by batching them alongside a session command the server
// actually runs. Mirror the base's selection and skip entirely when
// deleted or when no family matched.
if (deleted) {
return;
}
// When getPbExtension returns -1 (no extension set) and the kind is
// non-zero, typeIdFor wraps into the previous kind's range instead of
// hitting the typeId < 0 guard in observeCommand. Skip such entries.
int kind = -1;
if (cont.game_command_size()) {
kind = 2;
} else if (cont.room_command_size()) {
kind = 1;
} else if (cont.session_command_size()) {
kind = 0;
} else if (cont.moderator_command_size()) {
kind = 3;
} else if (cont.admin_command_size()) {
kind = 4;
} else if (cont.developer_command_size()) {
kind = 5;
}
if (kind >= 0) {
auto recordDispatched = [&](int familyKind, const auto &cmds) {
for (const auto &cmd : cmds) {
const int ext = getPbExtension(cmd);
if (ext >= 0) {
servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(familyKind, ext),
elapsedMs);
}
}
};
if (kind == 0) {
recordDispatched(kind, cont.session_command());
} else if (kind == 1) {
recordDispatched(kind, cont.room_command());
} else if (kind == 2) {
recordDispatched(kind, cont.game_command());
} else if (kind == 3) {
recordDispatched(kind, cont.moderator_command());
} else if (kind == 4) {
recordDispatched(kind, cont.admin_command());
} else {
recordDispatched(kind, cont.developer_command());
}
}
const int slowCommandMs = servatrice->getMetricsSlowCommandMs();
if (slowCommandMs > 0 && elapsedMs >= slowCommandMs) {
const ServerInfo_User *info = getUserInfo();
const QString user = authState == PasswordRight && info ? QString::fromStdString(info->name())
: QStringLiteral("unauthenticated");
qCWarning(AbstractServerSocketInterfaceLog) << "slow command container from" << user << "processed in"
<< elapsedMs << "ms (" << cont.ByteSizeLong() << "bytes)";
}
}
Response::ResponseCode AbstractServerSocketInterface::processExtendedSessionCommand(int cmdType, Response::ResponseCode AbstractServerSocketInterface::processExtendedSessionCommand(int cmdType,
const SessionCommand &cmd, const SessionCommand &cmd,
ResponseContainer &rc) ResponseContainer &rc)
@ -1704,6 +1778,51 @@ Response::ResponseCode AbstractServerSocketInterface::cmdGetServerStats(const Co
re->set_uptime_secs(snapshot.uptimeSecs); re->set_uptime_secs(snapshot.uptimeSecs);
re->set_timest(snapshot.timest); re->set_timest(snapshot.timest);
// Live metrics from the in-process MetricsRegistry (resets on server restart)
re->set_cards_in_games(static_cast<google::protobuf::uint64>(servatrice->getCardsInGamesTotal()));
re->set_eventloop_stalls_total(static_cast<google::protobuf::uint64>(servatrice->getEventLoopStallsTotal()));
re->set_eventloop_last_stall_ms(static_cast<google::protobuf::uint64>(servatrice->getEventLoopLastStallMs()));
re->set_eventloop_max_stall_ms(static_cast<google::protobuf::uint64>(servatrice->getEventLoopMaxStallMs()));
re->set_total_commands(static_cast<google::protobuf::uint64>(servatrice->getMetricsRegistry().totalCommands()));
re->set_total_command_time_ms(
static_cast<google::protobuf::uint64>(servatrice->getMetricsRegistry().totalTimeMs()));
re->set_active_command_types(servatrice->getMetricsRegistry().activeTypeCount());
const auto gameStart = servatrice->getMetricsRegistry().getGameStartSnapshot();
re->set_game_start_count(static_cast<google::protobuf::uint64>(gameStart.count));
re->set_game_start_total_ms(static_cast<google::protobuf::uint64>(gameStart.totalMs));
// Per-command breakdown: resolve protobuf extension names via the descriptor pool
static const char *messageNames[] = {"SessionCommand", "RoomCommand", "GameCommand",
"ModeratorCommand", "AdminCommand", "DeveloperCommand"};
const auto activeStats = servatrice->getMetricsRegistry().collectActiveStats();
for (const auto &stat : activeStats) {
const int kind = stat.typeId / MetricsRegistry::KindStride;
const int number = stat.typeId % MetricsRegistry::KindStride;
QString label;
if (kind >= 0 && kind < MetricsRegistry::NumKinds) {
const google::protobuf::DescriptorPool *pool = google::protobuf::DescriptorPool::generated_pool();
const google::protobuf::Descriptor *message = pool->FindMessageTypeByName(messageNames[kind]);
const google::protobuf::FieldDescriptor *extension =
message ? pool->FindExtensionByNumber(message, number) : nullptr;
if (extension) {
label = QString::fromLatin1(MetricsRegistry::KindNames[kind]) + QStringLiteral("/") +
QString::fromStdString(std::string(extension->message_type()->name()));
}
}
if (label.isEmpty()) {
label = QString::number(stat.typeId);
}
CommandStats *cs = re->add_command_stats();
cs->set_kind_index(static_cast<google::protobuf::uint32>(kind));
cs->set_extension_number(static_cast<google::protobuf::uint32>(number));
cs->set_command_name(label.toStdString());
cs->set_count(static_cast<google::protobuf::uint64>(stat.count));
cs->set_total_ms(static_cast<google::protobuf::uint64>(stat.totalMs));
}
rc.setResponseExtension(re); rc.setResponseExtension(re);
return Response::RespOk; return Response::RespOk;
} }

View file

@ -81,6 +81,7 @@ signals:
protected: protected:
void logDebugMessage(const QString &message) override; void logDebugMessage(const QString &message) override;
bool tooManyRegistrationAttempts(const QString &ipAddress); bool tooManyRegistrationAttempts(const QString &ipAddress);
void processCommandContainer(const CommandContainer &cont) override;
virtual void writeToSocket(QByteArray &data) = 0; virtual void writeToSocket(QByteArray &data) = 0;
virtual void flushSocket() = 0; virtual void flushSocket() = 0;

View file

@ -15,6 +15,7 @@ add_test(NAME server_developer_role_test COMMAND server_developer_role_test)
add_test(NAME warning_categories_test COMMAND warning_categories_test) add_test(NAME warning_categories_test COMMAND warning_categories_test)
add_test(NAME lag_monitor_test COMMAND lag_monitor_test) add_test(NAME lag_monitor_test COMMAND lag_monitor_test)
add_test(NAME latency_tracker_test COMMAND latency_tracker_test) add_test(NAME latency_tracker_test COMMAND latency_tracker_test)
add_test(NAME metrics_registry_test COMMAND metrics_registry_test)
add_test(NAME deck_hash_performance_test COMMAND deck_hash_performance_test) add_test(NAME deck_hash_performance_test COMMAND deck_hash_performance_test)
set_tests_properties(deck_hash_performance_test PROPERTIES TIMEOUT 15) set_tests_properties(deck_hash_performance_test PROPERTIES TIMEOUT 15)
@ -36,6 +37,7 @@ 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) 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) target_include_directories(lag_monitor_test PRIVATE ${CMAKE_SOURCE_DIR}/cockatrice/src)
add_executable(latency_tracker_test latency_tracker_test.cpp) add_executable(latency_tracker_test latency_tracker_test.cpp)
add_executable(metrics_registry_test ../servatrice/src/metrics_registry.cpp metrics_registry_test.cpp)
find_package(GTest) find_package(GTest)
@ -76,6 +78,7 @@ if(NOT GTEST_FOUND)
add_dependencies(warning_categories_test gtest) add_dependencies(warning_categories_test gtest)
add_dependencies(lag_monitor_test gtest) add_dependencies(lag_monitor_test gtest)
add_dependencies(latency_tracker_test gtest) add_dependencies(latency_tracker_test gtest)
add_dependencies(metrics_registry_test gtest)
endif() endif()
include_directories(${GTEST_INCLUDE_DIRS}) include_directories(${GTEST_INCLUDE_DIRS})
@ -118,6 +121,8 @@ target_link_libraries(lag_monitor_test Threads::Threads ${GTEST_BOTH_LIBRARIES}
target_link_libraries( target_link_libraries(
latency_tracker_test libcockatrice_network Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES} latency_tracker_test libcockatrice_network Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES}
) )
target_include_directories(metrics_registry_test PRIVATE ${CMAKE_SOURCE_DIR}/servatrice/src)
target_link_libraries(metrics_registry_test ${TEST_QT_MODULES} Threads::Threads ${GTEST_BOTH_LIBRARIES})
add_subdirectory(card_zone_algorithms) add_subdirectory(card_zone_algorithms)
add_subdirectory(carddatabase) add_subdirectory(carddatabase)

View file

@ -0,0 +1,83 @@
#include <QCoreApplication>
#include <QList>
#include <gtest/gtest.h>
#include <metrics_registry.h>
TEST(MetricsRegistryTest, EmptyRegistryHasZeroedCounters)
{
MetricsRegistry registry;
EXPECT_EQ(0, registry.totalCommands());
EXPECT_EQ(0, registry.totalTimeMs());
EXPECT_EQ(0, registry.activeTypeCount());
EXPECT_EQ(0, registry.getGameStartSnapshot().count);
}
TEST(MetricsRegistryTest, SampleIsRecordedInTotalsAndSlot)
{
MetricsRegistry registry;
registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), 7);
EXPECT_EQ(1, registry.totalCommands());
EXPECT_EQ(7, registry.totalTimeMs());
EXPECT_EQ(1, registry.activeTypeCount());
const auto stats = registry.collectActiveStats();
ASSERT_EQ(1, stats.size());
EXPECT_EQ(MetricsRegistry::typeIdFor(0, 1000), stats[0].typeId);
EXPECT_EQ(1, stats[0].count);
EXPECT_EQ(7, stats[0].totalMs);
}
TEST(MetricsRegistryTest, KindEncodingSeparatesSameExtensionNumber)
{
MetricsRegistry registry;
const int sessionPing = MetricsRegistry::typeIdFor(0, 1000);
const int roomLeaveRoom = MetricsRegistry::typeIdFor(1, 1000);
ASSERT_NE(sessionPing, roomLeaveRoom);
registry.observeCommand(sessionPing, 1);
registry.observeCommand(roomLeaveRoom, 5000);
EXPECT_EQ(2, registry.activeTypeCount());
}
TEST(MetricsRegistryTest, OutOfRangeIdsLandInOverflowSlot)
{
MetricsRegistry registry;
registry.observeCommand(-1, 4);
registry.observeCommand(MetricsRegistry::MaxTypes + 12345, 4);
EXPECT_EQ(2, registry.totalCommands());
EXPECT_EQ(1, registry.activeTypeCount()); // both collapsed into one slot
EXPECT_EQ(8, registry.totalTimeMs());
}
TEST(MetricsRegistryTest, NegativeDurationsAreClamped)
{
MetricsRegistry registry;
registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), -50);
EXPECT_EQ(0, registry.totalTimeMs());
}
TEST(MetricsRegistryTest, GameStartTrackedSeparatelyFromCommands)
{
MetricsRegistry registry;
registry.observeGameStartDurationMs(120);
EXPECT_EQ(0, registry.totalCommands());
EXPECT_EQ(0, registry.totalTimeMs());
EXPECT_EQ(0, registry.activeTypeCount());
const auto snapshot = registry.getGameStartSnapshot();
EXPECT_EQ(1, snapshot.count);
EXPECT_EQ(120, snapshot.totalMs);
}
int main(int argc, char **argv)
{
QCoreApplication app(argc, argv);
::testing::InitGoogleTest(&argc, argv);
return RUN_ALL_TESTS();
}