diff --git a/cockatrice/src/interface/widgets/tabs/tab_developer.cpp b/cockatrice/src/interface/widgets/tabs/tab_developer.cpp index b8e6a8033..39652ef7d 100644 --- a/cockatrice/src/interface/widgets/tabs/tab_developer.cpp +++ b/cockatrice/src/interface/widgets/tabs/tab_developer.cpp @@ -6,40 +6,80 @@ #include "tab_developer.h" +#include #include +#include #include #include #include +#include #include +#include #include +#include #include #include #include #include +static constexpr int DEFAULT_AUTO_REFRESH_INTERVAL_SECS = 30; + TabDeveloper::TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_client) : Tab(_tabSupervisor), client(_client) { statsTable = new QTableWidget(0, 2); - statsTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Expanding); + statsTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Preferred); statsTable->setEditTriggers(QAbstractItemView::NoEditTriggers); statsTable->setSelectionBehavior(QAbstractItemView::SelectRows); statsTable->setSelectionMode(QAbstractItemView::SingleSelection); - statsTable->horizontalHeader()->setStretchLastSection(true); 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; + 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::of(&QSpinBox::valueChanged), this, + &TabDeveloper::refreshIntervalChanged); + refreshButton = new QPushButton; refreshButton->setAutoDefault(true); connect(refreshButton, &QPushButton::clicked, this, &TabDeveloper::refreshClicked); auto *buttonLayout = new QHBoxLayout; buttonLayout->addWidget(statusLabel, 1, Qt::AlignLeft); + buttonLayout->addWidget(autoRefreshCheckBox, 0, Qt::AlignRight); + buttonLayout->addWidget(refreshIntervalSpinBox, 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; - mainLayout->addWidget(statsTable); + mainLayout->addLayout(tableLayout, 1); mainLayout->addLayout(buttonLayout); auto *central = new QWidget; @@ -51,8 +91,13 @@ TabDeveloper::TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_clien 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")); statsTable->setHorizontalHeaderLabels(QString(tr("Statistic;Value")).split(";")); + commandTable->setHorizontalHeaderLabels(QString(tr("Command;Count;Total ms;Avg ms")).split(";")); if (statsTable->rowCount() == 0) { statusLabel->clear(); } @@ -75,6 +120,14 @@ QString TabDeveloper::formatBytes(quint64 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) { 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)); } +void TabDeveloper::appendSeparatorRow(const QString §ionTitle) +{ + 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() { + if (requestPending) { + return; + } + requestPending = true; Command_GetServerStats cmd; PendingCommand *pend = client->prepareDeveloperCommand(cmd); connect(pend, &PendingCommand::finished, this, &TabDeveloper::serverStatsResponse); 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) { + requestPending = false; if (resp.response_code() != Response::RespOk) { statusLabel->setText(tr("No server statistics available yet.")); return; @@ -101,6 +190,8 @@ void TabDeveloper::serverStatsResponse(const Response &resp) const Response_GetServerStats &response = resp.GetExtension(Response_GetServerStats::ext); statsTable->setRowCount(0); + + // Overview section appendStatRow(tr("Registered users online"), QString::number(response.users_count())); appendStatRow(tr("Moderators online"), QString::number(response.mods_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(response.timest())); 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(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(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 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(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(); + commandTable->resizeColumnsToContents(); + statusLabel->setText(tr("Updated %1").arg(QDateTime::currentDateTime().toString("yyyy-MM-dd HH:mm"))); } diff --git a/cockatrice/src/interface/widgets/tabs/tab_developer.h b/cockatrice/src/interface/widgets/tabs/tab_developer.h index 501b14e3e..727a56bcb 100644 --- a/cockatrice/src/interface/widgets/tabs/tab_developer.h +++ b/cockatrice/src/interface/widgets/tabs/tab_developer.h @@ -10,9 +10,12 @@ #include "tab.h" class AbstractClient; +class QCheckBox; class QLabel; class QPushButton; +class QSpinBox; class QTableWidget; +class QTimer; class Response; class TabDeveloper : public Tab @@ -21,15 +24,24 @@ class TabDeveloper : public Tab private: AbstractClient *client; QTableWidget *statsTable; + QTableWidget *commandTable; QPushButton *refreshButton; QLabel *statusLabel; + QCheckBox *autoRefreshCheckBox; + QSpinBox *refreshIntervalSpinBox; + QTimer *autoRefreshTimer; + bool requestPending = false; void appendStatRow(const QString &name, const QString &value); + void appendSeparatorRow(const QString §ionTitle); static QString formatBytes(quint64 bytes); + static QString formatDurationMs(qint64 ms); private slots: void refreshClicked(); void serverStatsResponse(const Response &resp); + void autoRefreshToggled(bool checked); + void refreshIntervalChanged(); public: explicit TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_client); diff --git a/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.cpp b/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.cpp index 957a89792..6b4101a99 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.cpp +++ b/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.cpp @@ -66,6 +66,15 @@ Server_AbstractPlayer::Server_AbstractPlayer(Server_Game *_game, 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() { delete deck; diff --git a/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.h b/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.h index 85fbc0557..4cc79c5fe 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.h +++ b/libcockatrice_network/libcockatrice/network/server/remote/game/server_abstract_player.h @@ -43,6 +43,8 @@ public: Server_AbstractUserInterface *_handler); ~Server_AbstractPlayer() 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 { return deck; 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 43209e994..799b1e7ee 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.cpp +++ b/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.cpp @@ -32,6 +32,7 @@ #include "server_spectator.h" #include +#include #include #include #include @@ -238,6 +239,17 @@ int Server_Game::getPlayerCount() const 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 { 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 if (lifecycleStrategy->onGameStarting(this) == Server_GameLifecycleStrategy::StartAction::Handled) { locker.unlock(); @@ -373,6 +388,7 @@ void Server_Game::doStartGameIfReady(bool forceStartGame) activePlayer = -1; nextTurn(); + room->getServer()->observeGameStartDurationMs(startupTimer.nsecsElapsed() / 1000000); locker.unlock(); diff --git a/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.h b/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.h index 1b9f651bd..1ed4fe4ca 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.h +++ b/libcockatrice_network/libcockatrice/network/server/remote/game/server_game.h @@ -123,6 +123,8 @@ public: return gameStarted; } int getPlayerCount() const; + /// Total cards across all players' zones. Takes gameMutex itself. + int getCardsInGame() const; int getSpectatorCount() const; QMap getPlayers() const; Server_AbstractPlayer *getPlayer(int id) const; diff --git a/libcockatrice_network/libcockatrice/network/server/remote/server.h b/libcockatrice_network/libcockatrice/network/server/remote/server.h index 0ded27afa..3d27f4210 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/server.h +++ b/libcockatrice_network/libcockatrice/network/server/remote/server.h @@ -180,6 +180,11 @@ public: { 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; int getNextLocalGameId() diff --git a/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h b/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h index d62213188..2c8efe50e 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h +++ b/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h @@ -136,7 +136,7 @@ public: return timeRunning - lastDataReceived; } bool addSaidMessageSize(int size); - void processCommandContainer(const CommandContainer &cont); + virtual void processCommandContainer(const CommandContainer &cont); void sendProtocolItem(const Response &item); void sendProtocolItem(const SessionEvent &item); diff --git a/libcockatrice_protocol/libcockatrice/protocol/pb/response_get_server_stats.proto b/libcockatrice_protocol/libcockatrice/protocol/pb/response_get_server_stats.proto index fb8a0cae2..bb8ff3c43 100644 --- a/libcockatrice_protocol/libcockatrice/protocol/pb/response_get_server_stats.proto +++ b/libcockatrice_protocol/libcockatrice/protocol/pb/response_get_server_stats.proto @@ -1,6 +1,14 @@ syntax = "proto2"; 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 { extend Response { optional Response_GetServerStats ext = 1220; @@ -16,4 +24,18 @@ message Response_GetServerStats { optional uint64 uptime_secs = 6; 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; } diff --git a/oracle/src/oracleimporter.cpp b/oracle/src/oracleimporter.cpp index 07aee0185..fdf11ef02 100644 --- a/oracle/src/oracleimporter.cpp +++ b/oracle/src/oracleimporter.cpp @@ -110,7 +110,7 @@ bool OracleImporter::readSetsFromByteArray(QByteArray data) * A lower index means a higher priority. */ static const QStringList MAIN_CARD_TYPE_PRIORITY = {"Planeswalker", "Creature", "Land", "Sorcery", - "Instant", "Artifact", "Enchantment"}; + "Instant", "Artifact", "Enchantment"}; /** * Returns the priority (index) of the given main card type. Known types map to their diff --git a/servatrice/CMakeLists.txt b/servatrice/CMakeLists.txt index 5d8089ad1..68e422d8c 100644 --- a/servatrice/CMakeLists.txt +++ b/servatrice/CMakeLists.txt @@ -6,7 +6,9 @@ project(Servatrice VERSION "${PROJECT_VERSION_MAJOR}.${PROJECT_VERSION_MINOR}.${ set(servatrice_SOURCES src/email_parser.cpp + src/event_loop_watchdog.cpp src/main.cpp + src/metrics_registry.cpp src/servatrice.cpp src/servatrice_connection_pool.cpp src/servatrice_database_interface.cpp diff --git a/servatrice/servatrice.ini.example b/servatrice/servatrice.ini.example index c1940c22f..23eca3f1b 100644 --- a/servatrice/servatrice.ini.example +++ b/servatrice/servatrice.ini.example @@ -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 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] ; 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. diff --git a/servatrice/src/event_loop_watchdog.cpp b/servatrice/src/event_loop_watchdog.cpp new file mode 100644 index 000000000..e50bd4201 --- /dev/null +++ b/servatrice/src/event_loop_watchdog.cpp @@ -0,0 +1,34 @@ +/** + * @file event_loop_watchdog.cpp + * @ingroup Servatrice + */ + +#include "event_loop_watchdog.h" + +#include "servatrice.h" + +#include + +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(0, elapsedMs - HeartbeatIntervalMs); + if (overshootMs < servatrice->getMetricsStallWarnMs()) { + return; + } + + servatrice->observeEventLoopStall(threadName, overshootMs); +} diff --git a/servatrice/src/event_loop_watchdog.h b/servatrice/src/event_loop_watchdog.h new file mode 100644 index 000000000..b9061ff97 --- /dev/null +++ b/servatrice/src/event_loop_watchdog.h @@ -0,0 +1,50 @@ +/** + * @file event_loop_watchdog.h + * @ingroup Servatrice + */ + +#ifndef EVENT_LOOP_WATCHDOG_H +#define EVENT_LOOP_WATCHDOG_H + +#include +#include +#include + +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 diff --git a/servatrice/src/metrics_registry.cpp b/servatrice/src/metrics_registry.cpp new file mode 100644 index 000000000..99ce390f1 --- /dev/null +++ b/servatrice/src/metrics_registry.cpp @@ -0,0 +1,70 @@ +#include "metrics_registry.h" + +#include + +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(typeId)]; +} + +const MetricsRegistry::TypeStats &MetricsRegistry::slotFor(int typeId) const +{ + return typeSlots[static_cast(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::collectActiveStats() const +{ + QList 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)}; +} \ No newline at end of file diff --git a/servatrice/src/metrics_registry.h b/servatrice/src/metrics_registry.h new file mode 100644 index 000000000..4df1057c2 --- /dev/null +++ b/servatrice/src/metrics_registry.h @@ -0,0 +1,120 @@ +/** + * @file metrics_registry.h + * @ingroup Servatrice + */ + +#ifndef METRICS_REGISTRY_H +#define METRICS_REGISTRY_H + +#include +#include +#include +#include + +/** + * @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 collectActiveStats() const; + + struct GameStartSnapshot + { + qint64 count; + qint64 totalMs; + }; + + GameStartSnapshot getGameStartSnapshot() const; + +private: + struct TypeStats + { + std::atomic count{0}; + std::atomic totalMs{0}; + }; + + TypeStats &slotFor(int typeId); + const TypeStats &slotFor(int typeId) const; + + std::array typeSlots{}; + TypeStats gameStartStats{}; + std::atomic totalCommandsCounter{0}; + std::atomic totalTimeCounter{0}; +}; + +#endif \ No newline at end of file diff --git a/servatrice/src/servatrice.cpp b/servatrice/src/servatrice.cpp index db8751658..26352ccd7 100644 --- a/servatrice/src/servatrice.cpp +++ b/servatrice/src/servatrice.cpp @@ -20,6 +20,7 @@ #include "servatrice.h" #include "email_parser.h" +#include "event_loop_watchdog.h" #include "isl_interface.h" #include "main.h" #include "servatrice_connection_pool.h" @@ -38,6 +39,7 @@ #include #include #include +#include #include #include #include @@ -63,6 +65,7 @@ Servatrice_GameServer::Servatrice_GameServer(Servatrice *_server, server->addDatabaseInterface(newThread, newDatabaseInterface); newThread->start(); + server->watchWorkerThread(newThread); QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection, Q_ARG(QSqlDatabase, _sqlDatabase)); @@ -86,7 +89,6 @@ void Servatrice_GameServer::incomingConnection(qintptr socketDescriptor) Servatrice_ConnectionPool *pool = findLeastUsedConnectionPool(); auto ssi = new TcpServerSocketInterface(server, pool->getDatabaseInterface()); - connect(ssi, SIGNAL(incTxBytes(qint64)), this, SLOT(incTxBytes(qint64))); ssi->moveToThread(pool->thread()); pool->addClient(); connect(ssi, SIGNAL(destroyed()), pool, SLOT(removeClient())); @@ -131,6 +133,7 @@ Servatrice_WebsocketGameServer::Servatrice_WebsocketGameServer(Servatrice *_serv server->addDatabaseInterface(newThread, newDatabaseInterface); newThread->start(); + server->watchWorkerThread(newThread); QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection, Q_ARG(QSqlDatabase, _sqlDatabase)); @@ -156,7 +159,6 @@ void Servatrice_WebsocketGameServer::onNewConnection() Servatrice_ConnectionPool *pool = findLeastUsedConnectionPool(); 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. * This will hopefully change in Qt6 if QtWebSocket will be integrated in QtNetwork @@ -226,6 +228,13 @@ bool Servatrice::initServer() { 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") { qDebug() << "Authenticating method: sql"; authenticationMethod = AuthenticationSql; @@ -470,9 +479,55 @@ bool Servatrice::initServer() } setRequiredFeatures(getRequiredFeatures()); + 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 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) { databaseInterfaces.insert(thread, databaseInterface); diff --git a/servatrice/src/servatrice.h b/servatrice/src/servatrice.h index 8b0f5ad60..8d964a52b 100644 --- a/servatrice/src/servatrice.h +++ b/servatrice/src/servatrice.h @@ -20,6 +20,8 @@ #ifndef SERVATRICE_H #define SERVATRICE_H +#include "metrics_registry.h" + #include #include #include @@ -30,6 +32,7 @@ #include #include #include +#include #include #include #include @@ -170,6 +173,12 @@ private: int uptime; QMutex txBytesMutex, rxBytesMutex; quint64 txBytes, rxBytes; + MetricsRegistry metricsRegistry; + int metricsSlowCommandMs = 500; + int metricsStallWarnMs = 2000; + std::atomic eventLoopStallsTotal{0}; ///< heartbeat overshoots past the warn threshold + std::atomic eventLoopLastStallMs{0}; ///< overshoot of the most recent stall + std::atomic eventLoopMaxStallMs{0}; ///< worst overshoot seen since process start QString shutdownReason; int shutdownMinutes; @@ -286,6 +295,49 @@ public: void incRxBytes(quint64 num); 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; void addIslInterface(int _serverId, IslInterface *interface); void removeIslInterface(int _serverId); diff --git a/servatrice/src/serversocketinterface.cpp b/servatrice/src/serversocketinterface.cpp index 4b1502a15..aeffd7081 100644 --- a/servatrice/src/serversocketinterface.cpp +++ b/servatrice/src/serversocketinterface.cpp @@ -30,6 +30,7 @@ #include #include +#include #include #include #include @@ -39,8 +40,10 @@ #include #include #include +#include #include #include +#include #include #include #include @@ -192,6 +195,77 @@ void AbstractServerSocketInterface::logDebugMessage(const QString &message) 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, const SessionCommand &cmd, ResponseContainer &rc) @@ -1704,6 +1778,51 @@ Response::ResponseCode AbstractServerSocketInterface::cmdGetServerStats(const Co re->set_uptime_secs(snapshot.uptimeSecs); re->set_timest(snapshot.timest); + // Live metrics from the in-process MetricsRegistry (resets on server restart) + re->set_cards_in_games(static_cast(servatrice->getCardsInGamesTotal())); + re->set_eventloop_stalls_total(static_cast(servatrice->getEventLoopStallsTotal())); + re->set_eventloop_last_stall_ms(static_cast(servatrice->getEventLoopLastStallMs())); + re->set_eventloop_max_stall_ms(static_cast(servatrice->getEventLoopMaxStallMs())); + re->set_total_commands(static_cast(servatrice->getMetricsRegistry().totalCommands())); + re->set_total_command_time_ms( + static_cast(servatrice->getMetricsRegistry().totalTimeMs())); + re->set_active_command_types(servatrice->getMetricsRegistry().activeTypeCount()); + + const auto gameStart = servatrice->getMetricsRegistry().getGameStartSnapshot(); + re->set_game_start_count(static_cast(gameStart.count)); + re->set_game_start_total_ms(static_cast(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(kind)); + cs->set_extension_number(static_cast(number)); + cs->set_command_name(label.toStdString()); + cs->set_count(static_cast(stat.count)); + cs->set_total_ms(static_cast(stat.totalMs)); + } + rc.setResponseExtension(re); return Response::RespOk; } diff --git a/servatrice/src/serversocketinterface.h b/servatrice/src/serversocketinterface.h index c7516b405..b464e6a9b 100644 --- a/servatrice/src/serversocketinterface.h +++ b/servatrice/src/serversocketinterface.h @@ -81,6 +81,7 @@ signals: protected: void logDebugMessage(const QString &message) override; bool tooManyRegistrationAttempts(const QString &ipAddress); + void processCommandContainer(const CommandContainer &cont) override; virtual void writeToSocket(QByteArray &data) = 0; virtual void flushSocket() = 0; diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index b7e712e3a..4f5dc88eb 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -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 lag_monitor_test COMMAND lag_monitor_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) 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) target_include_directories(lag_monitor_test PRIVATE ${CMAKE_SOURCE_DIR}/cockatrice/src) 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) @@ -76,6 +78,7 @@ if(NOT GTEST_FOUND) add_dependencies(warning_categories_test gtest) add_dependencies(lag_monitor_test gtest) add_dependencies(latency_tracker_test gtest) + add_dependencies(metrics_registry_test gtest) endif() include_directories(${GTEST_INCLUDE_DIRS}) @@ -118,6 +121,8 @@ target_link_libraries(lag_monitor_test Threads::Threads ${GTEST_BOTH_LIBRARIES} target_link_libraries( 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(carddatabase) diff --git a/tests/metrics_registry_test.cpp b/tests/metrics_registry_test.cpp new file mode 100644 index 000000000..1abef58e1 --- /dev/null +++ b/tests/metrics_registry_test.cpp @@ -0,0 +1,83 @@ +#include +#include +#include +#include + +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(); +} \ No newline at end of file