[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

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

servatrice/src/metrics_registry.cpp

@@ -2,33 +2,6 @@
 
 #include <QList>
 
-int MetricsRegistry::bucketIndexFor(qint64 elapsedMs)
-{
-    const int lastFiniteBucket = static_cast<int>(BucketBounds.size()) - 1;
-    int bucket = 0;
-    while (bucket < lastFiniteBucket && elapsedMs > BucketBounds[static_cast<size_t>(bucket)]) {
-        ++bucket;
-    }
-    return bucket;
-}
-
-void MetricsRegistry::appendCumulativeBuckets(QString &out,
-                                              const QString &bucketLine,
-                                              const std::array<std::atomic<qint64>, BucketCount> &buckets)
-{
-    // Cumulative buckets are required by the Prometheus histogram convention.
-    qint64 cumulative = 0;
-    for (int bucket = 0; bucket < static_cast<int>(BucketBounds.size()); ++bucket) {
-        cumulative += buckets[static_cast<size_t>(bucket)].load(std::memory_order_relaxed);
-        out += QStringLiteral("%1,le=\"%2\"} %3\n")
-                   .arg(bucketLine)
-                   .arg(BucketBounds[static_cast<size_t>(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<size_t>(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<size_t>(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<QString(int)> &nameForType,
-                                          const QHash<QString, qint64> &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::ActiveTypeStats> MetricsRegistry::collectActiveStats() const
 {
     QList<ActiveTypeStats> 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)};
-}
+}

servatrice/src/metrics_registry.h

@@ -6,11 +6,10 @@
 #ifndef METRICS_REGISTRY_H
 #define METRICS_REGISTRY_H
 
-#include <QHash>
+#include <QList>
 #include <QString>
 #include <array>
 #include <atomic>
-#include <functional>
 
 /**
  * @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<qint64, 11> 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<ActiveTypeStats> 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<QString(int)> &nameForType,
-                             const QHash<QString, qint64> &gauges) const;
-
 private:
-    static constexpr int BucketCount = static_cast<int>(BucketBounds.size()) + 1; ///< bounds + the +Inf bucket
-
     struct TypeStats
     {
         std::atomic<qint64> count{0};
         std::atomic<qint64> totalMs{0};
-        std::array<std::atomic<qint64>, 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<std::atomic<qint64>, BucketCount> &buckets);
-
     std::array<TypeStats, MaxTypes> typeSlots{};
     TypeStats gameStartStats{};
     std::atomic<qint64> totalCommandsCounter{0};
     std::atomic<qint64> totalTimeCounter{0};
 };
 
-#endif
+#endif

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;
 }
 

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

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<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"};
+    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;

tests/metrics_registry_test.cpp

@@ -1,22 +1,18 @@
-#include <QRegularExpression>
+#include <QList>
 #include <gtest/gtest.h>
 #include <metrics_registry.h>
 
-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<QString, qint64> 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);
+}