diff --git a/servatrice/servatrice.ini.example b/servatrice/servatrice.ini.example index 7e0789073..23eca3f1b 100644 --- a/servatrice/servatrice.ini.example +++ b/servatrice/servatrice.ini.example @@ -384,7 +384,9 @@ 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. +; 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 diff --git a/servatrice/src/metrics_registry.cpp b/servatrice/src/metrics_registry.cpp index 8e3769954..99ce390f1 100644 --- a/servatrice/src/metrics_registry.cpp +++ b/servatrice/src/metrics_registry.cpp @@ -2,33 +2,6 @@ #include -int MetricsRegistry::bucketIndexFor(qint64 elapsedMs) -{ - const int lastFiniteBucket = static_cast(BucketBounds.size()) - 1; - int bucket = 0; - while (bucket < lastFiniteBucket && elapsedMs > BucketBounds[static_cast(bucket)]) { - ++bucket; - } - return bucket; -} - -void MetricsRegistry::appendCumulativeBuckets(QString &out, - const QString &bucketLine, - const std::array, BucketCount> &buckets) -{ - // Cumulative buckets are required by the Prometheus histogram convention. - qint64 cumulative = 0; - for (int bucket = 0; bucket < static_cast(BucketBounds.size()); ++bucket) { - cumulative += buckets[static_cast(bucket)].load(std::memory_order_relaxed); - out += QStringLiteral("%1,le=\"%2\"} %3\n") - .arg(bucketLine) - .arg(BucketBounds[static_cast(bucket)]) - .arg(cumulative); - } - cumulative += buckets[BucketCount - 1].load(std::memory_order_relaxed); - out += QStringLiteral("%1,le=\"+Inf\"} %2\n").arg(bucketLine).arg(cumulative); -} - void MetricsRegistry::observeCommand(int typeId, qint64 elapsedMs) { if (typeId < 0 || typeId >= MaxTypes) { @@ -43,7 +16,6 @@ void MetricsRegistry::observeCommand(int typeId, qint64 elapsedMs) 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); - stats.buckets[static_cast(bucketIndexFor(elapsedMs))].fetch_add(1, std::memory_order_relaxed); } void MetricsRegistry::observeGameStartDurationMs(qint64 elapsedMs) @@ -54,7 +26,6 @@ void MetricsRegistry::observeGameStartDurationMs(qint64 elapsedMs) gameStartStats.count.fetch_add(1, std::memory_order_relaxed); gameStartStats.totalMs.fetch_add(elapsedMs, std::memory_order_relaxed); - gameStartStats.buckets[static_cast(bucketIndexFor(elapsedMs))].fetch_add(1, std::memory_order_relaxed); } MetricsRegistry::TypeStats &MetricsRegistry::slotFor(int typeId) @@ -78,49 +49,6 @@ int MetricsRegistry::activeTypeCount() const return active; } -QString MetricsRegistry::toPrometheusText(const std::function &nameForType, - const QHash &gauges) const -{ - QString out; - out.reserve(4096); - - for (auto it = gauges.constBegin(); it != gauges.constEnd(); ++it) { - out += QStringLiteral("# TYPE %1 gauge\n").arg(it.key()); - out += QStringLiteral("%1 %2\n").arg(it.key()).arg(it.value()); - } - - // Cumulative buckets are required by the Prometheus histogram convention. - out += QLatin1String("# TYPE servatrice_commands_duration_ms histogram\n"); - - 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; - } - - const QString label = nameForType ? nameForType(type) : QString::number(type); - appendCumulativeBuckets(out, QStringLiteral("servatrice_commands_duration_ms_bucket{command=\"%1\"").arg(label), - stats.buckets); - - out += QStringLiteral("servatrice_commands_duration_ms_sum{command=\"%1\"} %2\n") - .arg(label) - .arg(stats.totalMs.load(std::memory_order_relaxed)); - out += QStringLiteral("servatrice_commands_duration_ms_count{command=\"%1\"} %2\n").arg(label).arg(count); - } - - const qint64 startCount = gameStartStats.count.load(std::memory_order_relaxed); - if (startCount > 0) { - out += QLatin1String("# TYPE servatrice_game_start_duration_ms histogram\n"); - appendCumulativeBuckets(out, QLatin1String("servatrice_game_start_duration_ms_bucket"), gameStartStats.buckets); - out += QStringLiteral("servatrice_game_start_duration_ms_sum %1\n") - .arg(gameStartStats.totalMs.load(std::memory_order_relaxed)); - out += QStringLiteral("servatrice_game_start_duration_ms_count %1\n").arg(startCount); - } - - return out; -} - QList MetricsRegistry::collectActiveStats() const { QList result; @@ -139,4 +67,4 @@ 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 index cbca2a2c6..4df1057c2 100644 --- a/servatrice/src/metrics_registry.h +++ b/servatrice/src/metrics_registry.h @@ -6,11 +6,10 @@ #ifndef METRICS_REGISTRY_H #define METRICS_REGISTRY_H -#include +#include #include #include #include -#include /** * @brief Lock-free accumulation of command processing statistics. @@ -22,6 +21,10 @@ * * 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 { @@ -29,20 +32,23 @@ 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 = 2048; + static constexpr int KindStride = 1280; - static constexpr int NumKinds = 5; + static constexpr int NumKinds = 6; - static constexpr const char *KindNames[NumKinds] = {"session", "room", "game", "moderator", "admin"}; + 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; - /// Histogram bucket upper bounds in milliseconds. Anything above the last - /// bound lands in the trailing +Inf bucket. Constexpr so the recording - /// hot path never allocates. - static constexpr std::array BucketBounds{1, 5, 10, 25, 50, 100, 250, 500, 1000, 2500, 5000}; + /// 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) { @@ -82,8 +88,8 @@ public: /** * Returns stats for every type slot that has seen at least one sample. - * The caller-provided @p labelForType maps a numeric type id to a stable - * human-readable label. Pass nullptr to skip label resolution. + * Callers resolve the numeric type id to a human-readable label via + * typeIdFor()/KindNames as needed. */ QList collectActiveStats() const; @@ -95,41 +101,20 @@ public: GameStartSnapshot getGameStartSnapshot() const; - /** - * @brief Renders all recorded data in Prometheus text exposition format. - * - * @param nameForType maps a numeric command type id to a stable label - * value. Ids without a mapping are rendered as their number. - * @param gauges simple name/value pairs emitted as gauge samples. - */ - QString toPrometheusText(const std::function &nameForType, - const QHash &gauges) const; - private: - static constexpr int BucketCount = static_cast(BucketBounds.size()) + 1; ///< bounds + the +Inf bucket - struct TypeStats { std::atomic count{0}; std::atomic totalMs{0}; - std::array, BucketCount> buckets{}; }; TypeStats &slotFor(int typeId); const TypeStats &slotFor(int typeId) const; - /// Index of the histogram bucket the sample falls into. The last index is +Inf. - static int bucketIndexFor(qint64 elapsedMs); - - /// Appends one series of cumulative +Inf-terminated buckets to @p out. - static void appendCumulativeBuckets(QString &out, - const QString &bucketLine, - const std::array, BucketCount> &buckets); - std::array typeSlots{}; TypeStats gameStartStats{}; std::atomic totalCommandsCounter{0}; std::atomic totalTimeCounter{0}; }; -#endif +#endif \ No newline at end of file diff --git a/servatrice/src/servatrice.cpp b/servatrice/src/servatrice.cpp index 0929af97d..f08da973e 100644 --- a/servatrice/src/servatrice.cpp +++ b/servatrice/src/servatrice.cpp @@ -230,6 +230,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; @@ -475,11 +482,6 @@ bool Servatrice::initServer() setRequiredFeatures(getRequiredFeatures()); - // METRICS (always active. Slow-command logging and stall watchdogs are - // controlled by their respective thresholds below) - metricsSlowCommandMs = settingsCache->value("metrics/slow_command_ms", 500).toInt(); - metricsStallWarnMs = qMax(0, settingsCache->value("metrics/stall_warn_ms", 2000).toInt()); - return true; } diff --git a/servatrice/src/servatrice.h b/servatrice/src/servatrice.h index cfb5ff943..03cb46719 100644 --- a/servatrice/src/servatrice.h +++ b/servatrice/src/servatrice.h @@ -315,8 +315,11 @@ public: return uptime; } /** - * Sums cards across all zones of all running games. Locks rooms and games - * briefly per level, so scrape-time cost grows with live game count only. + * 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 diff --git a/servatrice/src/serversocketinterface.cpp b/servatrice/src/serversocketinterface.cpp index fbacc827f..8e1da7083 100644 --- a/servatrice/src/serversocketinterface.cpp +++ b/servatrice/src/serversocketinterface.cpp @@ -219,6 +219,9 @@ void AbstractServerSocketInterface::processCommandContainer(const CommandContain for (const auto &cmd : cont.admin_command()) { servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(4, getPbExtension(cmd)), elapsedMs); } + for (const auto &cmd : cont.developer_command()) { + servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(5, getPbExtension(cmd)), elapsedMs); + } const int slowCommandMs = servatrice->getMetricsSlowCommandMs(); if (slowCommandMs > 0 && elapsedMs >= slowCommandMs) { @@ -1757,8 +1760,8 @@ Response::ResponseCode AbstractServerSocketInterface::cmdGetServerStats(const Co 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"}; + 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; diff --git a/tests/metrics_registry_test.cpp b/tests/metrics_registry_test.cpp index 40eea4250..500e3ee6c 100644 --- a/tests/metrics_registry_test.cpp +++ b/tests/metrics_registry_test.cpp @@ -1,22 +1,18 @@ -#include +#include #include #include -TEST(MetricsRegistryTest, EmptyRegistryProducesNoHistogramLines) +TEST(MetricsRegistryTest, EmptyRegistryHasZeroedCounters) { MetricsRegistry registry; EXPECT_EQ(0, registry.totalCommands()); EXPECT_EQ(0, registry.totalTimeMs()); EXPECT_EQ(0, registry.activeTypeCount()); - - const QString text = registry.toPrometheusText([](int) { return QString("x"); }, {}); - // The family TYPE declaration may stand alone. What must not exist is a - // histogram sample without data behind it. - EXPECT_FALSE(text.contains(QRegularExpression("servatrice_commands_duration_ms_(bucket|sum|count)"))); + EXPECT_EQ(0, registry.getGameStartSnapshot().count); } -TEST(MetricsRegistryTest, SingleSampleIsRecordedInTotalsAndBuckets) +TEST(MetricsRegistryTest, SampleIsRecordedInTotalsAndSlot) { MetricsRegistry registry; registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), 7); @@ -25,31 +21,11 @@ TEST(MetricsRegistryTest, SingleSampleIsRecordedInTotalsAndBuckets) EXPECT_EQ(7, registry.totalTimeMs()); EXPECT_EQ(1, registry.activeTypeCount()); - const QString text = registry.toPrometheusText( - [](int typeId) { - return QString("%1/%2").arg(typeId / MetricsRegistry::KindStride).arg(typeId % MetricsRegistry::KindStride); - }, - {}); - // 7ms falls into the le="10" bucket. Smaller buckets stay empty - EXPECT_TRUE(text.contains("# TYPE servatrice_commands_duration_ms histogram\n")); - EXPECT_TRUE(text.contains(",le=\"10\"} 1")); - EXPECT_TRUE(text.contains(",le=\"5\"} 0")); - EXPECT_TRUE(text.contains("_sum{command=\"0/1000\"} 7")); - EXPECT_TRUE(text.contains("_count{command=\"0/1000\"} 1")); -} - -TEST(MetricsRegistryTest, BucketsAreCumulative) -{ - MetricsRegistry registry; - registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), 2); - registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), 30); - - const QString text = registry.toPrometheusText([](int) { return QString("cmd"); }, {}); - - // cumulative counts: <=25 -> 1 sample, <=50 -> 2 samples - EXPECT_TRUE(text.contains(",le=\"25\"} 1\n")); - EXPECT_TRUE(text.contains(",le=\"50\"} 2\n")); - EXPECT_TRUE(text.contains(",le=\"+Inf\"} 2\n")); + 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) @@ -84,48 +60,16 @@ TEST(MetricsRegistryTest, NegativeDurationsAreClamped) EXPECT_EQ(0, registry.totalTimeMs()); } -TEST(MetricsRegistryTest, GaugesAndLabelEscapingAreRendered) +TEST(MetricsRegistryTest, GameStartTrackedSeparatelyFromCommands) { MetricsRegistry registry; - - QHash gauges; - gauges.insert("servatrice_users_current", 42); - - const QString text = registry.toPrometheusText(nullptr, gauges); - EXPECT_TRUE(text.contains("# TYPE servatrice_users_current gauge\n")); - EXPECT_TRUE(text.contains("servatrice_users_current 42\n")); -} - -TEST(MetricsRegistryTest, UnnamedTypesFallBackToNumericLabel) -{ - MetricsRegistry registry; - registry.observeCommand(MetricsRegistry::typeIdFor(2, 1042), 9); - - const QString text = registry.toPrometheusText(nullptr, {}); - EXPECT_TRUE(text.contains("{command=\"" + QString::number(MetricsRegistry::typeIdFor(2, 1042)) + "\"}")); -} - -TEST(MetricsRegistryTest, GameStartHistogramOnlyAppearsAfterSamples) -{ - MetricsRegistry registry; - EXPECT_FALSE(registry.toPrometheusText(nullptr, {}).contains("servatrice_game_start_duration_ms")); - registry.observeGameStartDurationMs(120); - const QString text = registry.toPrometheusText(nullptr, {}); - // 120ms falls into the le="250" bucket - EXPECT_TRUE(text.contains("# TYPE servatrice_game_start_duration_ms histogram\n")); - EXPECT_TRUE(text.contains(",le=\"100\"} 0\n")); - EXPECT_TRUE(text.contains(",le=\"250\"} 1\n")); - EXPECT_TRUE(text.contains("servatrice_game_start_duration_ms_sum 120\n")); - EXPECT_TRUE(text.contains("servatrice_game_start_duration_ms_count 1\n")); -} - -TEST(MetricsRegistryTest, GameStartHistogramIsSeparateFromCommandTotals) -{ - MetricsRegistry registry; - registry.observeGameStartDurationMs(10); 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); +} \ No newline at end of file