jeirmeister/Cockatrice
1
0
Fork 0
mirror of https://github.com/Cockatrice/Cockatrice.git synced 2026-09-21 09:05:10 -07:00
Code Issues Projects Releases Packages Wiki Activity Actions 3

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

Browse source 
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
This commit is contained in:
Lukas Brübach 2026-08-25 20:42:10 +02:00
parent 2b33cbfb66
commit a542831aad
18 changed files with 749 additions and 1 deletions
Download patch file Download diff file Expand all files Collapse all files

5
tests/CMakeLists.txt
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 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)

131
tests/metrics_registry_test.cpp Normal file
View file

@ -0,0 +1,131 @@
#include <QRegularExpression>
#include <gtest/gtest.h>
#include <metrics_registry.h>
TEST(MetricsRegistryTest, EmptyRegistryProducesNoHistogramLines)
{
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)")));
}
TEST(MetricsRegistryTest, SingleSampleIsRecordedInTotalsAndBuckets)
{
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 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"));
}
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, GaugesAndLabelEscapingAreRendered)
{
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());
}