diff --git a/cockatrice/CMakeLists.txt b/cockatrice/CMakeLists.txt index ed196e501..e3e88b70c 100644 --- a/cockatrice/CMakeLists.txt +++ b/cockatrice/CMakeLists.txt @@ -15,6 +15,7 @@ set(cockatrice_SOURCES src/client/network/update/client/client_update_checker.cpp src/client/network/update/client/release_channel.cpp src/client/network/update/card_spoiler/spoiler_background_updater.cpp + src/client/lag_monitor.cpp src/client/sound_engine.cpp src/client/settings/cache_settings.cpp src/client/settings/card_counter_settings.cpp diff --git a/cockatrice/src/client/lag_monitor.cpp b/cockatrice/src/client/lag_monitor.cpp new file mode 100644 index 000000000..383d64644 --- /dev/null +++ b/cockatrice/src/client/lag_monitor.cpp @@ -0,0 +1,63 @@ +#include "lag_monitor.h" + +#include +#include +#include + +LagMonitor::LagMonitor(QObject *parent) : QObject(parent) +{ + qApp->installEventFilter(this); + + timer = new QTimer(this); + timer->setInterval(TICK_INTERVAL_MS); + connect(timer, &QTimer::timeout, this, &LagMonitor::checkTick); + tickClock.start(); + timer->start(); +} + +QList LagMonitor::recentStalls() const +{ + return stalls; +} + +void LagMonitor::clearStalls() +{ + stalls.clear(); +} + +bool LagMonitor::eventFilter(QObject *obj, QEvent *event) +{ + if (event->type() == QEvent::ApplicationStateChange) { + // The transition may span a suspend or an arbitrary unfocused period; + // discard the gap so it cannot be mistaken for a stall. + tickClock.restart(); + } + return QObject::eventFilter(obj, event); +} + +void LagMonitor::checkTick() +{ + recordGap(tickClock.restart()); +} + +void LagMonitor::recordGap(qint64 gapMs) +{ + if (gapMs <= STALL_THRESHOLD_MS) { + return; + } + + if (gapMs > MAX_PLAUSIBLE_STALL_MS) { + qCDebug(LagMonitorLog, "Ignoring implausible %lld ms gap (likely suspend)", static_cast(gapMs)); + return; + } + + const StallRecord record{.timestampMsSinceEpoch = QDateTime::currentMSecsSinceEpoch(), .durationMs = gapMs}; + + stalls.append(record); + while (stalls.size() > MAX_RECORDED_STALLS) { + stalls.removeFirst(); + } + + qCWarning(LagMonitorLog, "Event loop stalled for %lld ms (threshold: %d ms)", static_cast(gapMs), + STALL_THRESHOLD_MS); +} diff --git a/cockatrice/src/client/lag_monitor.h b/cockatrice/src/client/lag_monitor.h new file mode 100644 index 000000000..9fdf6b283 --- /dev/null +++ b/cockatrice/src/client/lag_monitor.h @@ -0,0 +1,87 @@ +/** + * @file lag_monitor.h + * @ingroup Client + */ + +#ifndef LAG_MONITOR_H +#define LAG_MONITOR_H + +#include +#include +#include +#include +#include + +inline Q_LOGGING_CATEGORY(LagMonitorLog, "lag_monitor"); + +class QEvent; +class QTimer; + +/** + * @brief Detects main-thread event loop stalls ("UI freezes") from the inside. + * + * A timer is expected to fire every TICK_INTERVAL_MS of wall time. When the + * observed gap greatly exceeds that interval, some other task blocked the + * event loop for roughly the overshooting duration. This is what separates + * "my client froze" from "the network is lagging" in user reports. + * + * Gaps that span an application state change (suspend, minimize, focus + * loss) are discarded, and implausibly huge gaps are dropped, so operating + * system power events do not fabricate stalls. This handling is load-bearing + * on Windows, where the monotonic clock used by Qt counts sleep time. + * + * Healthy operation costs one timer wakeup per tick and two integer + * comparisons. Allocations happen only when a stall is actually recorded. + */ +class LagMonitor : public QObject +{ + Q_OBJECT + +public: + struct StallRecord + { + qint64 timestampMsSinceEpoch = 0; ///< when the stalled period ended + qint64 durationMs = 0; ///< approximate length of the freeze; measured tick to tick, so it can exceed the true + ///< stall by up to TICK_INTERVAL_MS + }; + + static constexpr int TICK_INTERVAL_MS = 500; + static constexpr int STALL_THRESHOLD_MS = 2000; + static constexpr int MAX_RECORDED_STALLS = 32; + + /// Gaps beyond this are treated as suspend artifacts rather than stalls. + static constexpr qint64 MAX_PLAUSIBLE_STALL_MS = 600000; + + explicit LagMonitor(QObject *parent = nullptr); + + /** + * @brief Stalls recorded during this session, oldest first. + * + * Intended consumers are log output and the diagnostics export. The list + * holds at most MAX_RECORDED_STALLS entries. + */ + QList recentStalls() const; + + void clearStalls(); + + /** + * @brief Feeds a measured tick-to-tick gap through the detection logic. + * + * Split out of checkTick so threshold, plausibility, and trim behavior + * stay unit-testable without real timing. + */ + void recordGap(qint64 gapMs); + +protected: + bool eventFilter(QObject *obj, QEvent *event) override; + +private slots: + void checkTick(); + +private: + QTimer *timer; + QElapsedTimer tickClock; ///< monotonic clock, so wall clock steps do not fabricate stalls + QList stalls; +}; + +#endif diff --git a/cockatrice/src/interface/window_main.h b/cockatrice/src/interface/window_main.h index fc0791832..3c0cc6302 100644 --- a/cockatrice/src/interface/window_main.h +++ b/cockatrice/src/interface/window_main.h @@ -25,6 +25,7 @@ #ifndef WINDOW_H #define WINDOW_H +#include "../client/lag_monitor.h" #include "connection_controller/remote_connection_controller.h" #include "widgets/dialogs/dlg_local_game_options.h" @@ -145,6 +146,7 @@ private: WndSets *wndSets; ConnectionController *connectionController; LocalServer *localServer; + LagMonitor lagMonitor; ///< watches the main thread for event loop stalls bool bHasActivated, askedForDbUpdater; QProcess *cardUpdateProcess; DlgViewLog *logviewDialog; diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index b0b959a51..29caf257e 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -12,6 +12,7 @@ add_test(NAME server_card_counter_test COMMAND server_card_counter_test) add_test(NAME server_counter_test COMMAND server_counter_test) add_test(NAME server_rate_limiter_test COMMAND server_rate_limiter_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 deck_hash_performance_test COMMAND deck_hash_performance_test) @@ -30,6 +31,8 @@ add_executable(server_card_counter_test server_card_counter_test.cpp) add_executable(server_counter_test server_counter_test.cpp) add_executable(server_rate_limiter_test server_rate_limiter_test.cpp) 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) find_package(GTest) @@ -68,6 +71,7 @@ if(NOT GTEST_FOUND) add_dependencies(server_counter_test gtest) add_dependencies(server_rate_limiter_test gtest) add_dependencies(warning_categories_test gtest) + add_dependencies(lag_monitor_test gtest) add_dependencies(latency_tracker_test gtest) endif() @@ -103,6 +107,7 @@ target_link_libraries( target_link_libraries( warning_categories_test libcockatrice_utility Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES} ) +target_link_libraries(lag_monitor_test Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES}) target_link_libraries( latency_tracker_test libcockatrice_network Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES} ) diff --git a/tests/lag_monitor_test.cpp b/tests/lag_monitor_test.cpp new file mode 100644 index 000000000..9948eeabb --- /dev/null +++ b/tests/lag_monitor_test.cpp @@ -0,0 +1,103 @@ +#include "client/lag_monitor.h" + +#include +#include +#include +#include +#include + +namespace +{ + +/// Timestamps are taken at recording time; allow generous scheduler slack. +constexpr qint64 TIMESTAMP_SLACK_MS = 10000; + +} // namespace + +class LagMonitorTest : public ::testing::Test +{ +protected: + LagMonitor monitor; +}; + +TEST_F(LagMonitorTest, GapAtOrBelowThresholdIsIgnored) +{ + monitor.recordGap(0); + monitor.recordGap(LagMonitor::TICK_INTERVAL_MS); + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +TEST_F(LagMonitorTest, GapAboveThresholdIsRecorded) +{ + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1); + + const QList stalls = monitor.recentStalls(); + ASSERT_EQ(1, stalls.size()); + EXPECT_EQ(LagMonitor::STALL_THRESHOLD_MS + 1, stalls.first().durationMs); +} + +TEST_F(LagMonitorTest, RecordedTimestampIsFresh) +{ + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1); + + const qint64 now = QDateTime::currentMSecsSinceEpoch(); + ASSERT_EQ(1, monitor.recentStalls().size()); + EXPECT_LE(qAbs(monitor.recentStalls().first().timestampMsSinceEpoch - now), TIMESTAMP_SLACK_MS); +} + +TEST_F(LagMonitorTest, RecordsAreTrimmedToMaxOldestFirst) +{ + for (int i = 0; i < LagMonitor::MAX_RECORDED_STALLS + 5; ++i) { + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1 + i); + } + + const QList stalls = monitor.recentStalls(); + ASSERT_EQ(LagMonitor::MAX_RECORDED_STALLS, stalls.size()); + EXPECT_EQ(LagMonitor::STALL_THRESHOLD_MS + 6, stalls.first().durationMs); + EXPECT_EQ(LagMonitor::STALL_THRESHOLD_MS + 5 + LagMonitor::MAX_RECORDED_STALLS, stalls.last().durationMs); +} + +TEST_F(LagMonitorTest, GapAtPlausibilityCapIsKept) +{ + monitor.recordGap(LagMonitor::MAX_PLAUSIBLE_STALL_MS); + + ASSERT_EQ(1, monitor.recentStalls().size()); + EXPECT_EQ(LagMonitor::MAX_PLAUSIBLE_STALL_MS, monitor.recentStalls().first().durationMs); +} + +TEST_F(LagMonitorTest, GapBeyondPlausibilityCapIsDropped) +{ + monitor.recordGap(LagMonitor::MAX_PLAUSIBLE_STALL_MS + 1); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +TEST_F(LagMonitorTest, ClearStallsEmptiesList) +{ + monitor.recordGap(LagMonitor::STALL_THRESHOLD_MS + 1); + ASSERT_EQ(1, monitor.recentStalls().size()); + + monitor.clearStalls(); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +TEST_F(LagMonitorTest, ApplicationStateChangeDoesNotRecordAStall) +{ + QObject probe; + QEvent event(QEvent::ApplicationStateChange); + + QCoreApplication::sendEvent(&probe, &event); + + EXPECT_TRUE(monitor.recentStalls().isEmpty()); +} + +int main(int argc, char **argv) +{ + QLoggingCategory::setFilterRules("lag_monitor.*=false"); + QCoreApplication app(argc, argv); + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); +}