[Client] Detect main-thread event loop stalls (#7155)

* [Client] Detect main-thread event loop stalls

LagMonitor ticks the GUI event loop every 500 ms and records gaps
beyond 2 s as stalls, warning with their duration and keeping a
bounded ring of recent records for diagnostics. Measurement uses a
monotonic QElapsedTimer so wall-clock steps and suspend do not
fabricate stalls. Recorded timestamps stay in wall time for
correlating with user reports.

Took 1 minute

Took 13 minutes


Took 2 minutes

* [Client] Rename LagMonitor constants to SCREAMING_SNAKE_CASE

Took 15 minutes

* [Client] Discard suspend-spanning gaps in LagMonitor

Windows counts sleep time in its monotonic clock, so a suspend would
fabricate one bogus stall per resume. Reset the clock on application
state changes and drop implausibly huge gaps; extract recordGap() for
testability.

Took 3 minutes

* [Client] Unit test LagMonitor stall recording

Drives recordGap() directly to cover the threshold, plausibility cap,
trim, and clear behavior without timing-dependent waits.

Took 36 seconds

---------

Co-authored-by: Lukas Brübach <Bruebach.Lukas@bdosecurity.de>

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

cockatrice/src/client/lag_monitor.cpp

@@ -0,0 +1,63 @@
+#include "lag_monitor.h"
+
+#include <QCoreApplication>
+#include <QEvent>
+#include <QTimer>
+
+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::StallRecord> 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<long long>(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<long long>(gapMs),
+              STALL_THRESHOLD_MS);
+}

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 <QDateTime>
+#include <QElapsedTimer>
+#include <QList>
+#include <QLoggingCategory>
+#include <QObject>
+
+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<StallRecord> 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<StallRecord> stalls;
+};
+
+#endif

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;

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

tests/lag_monitor_test.cpp

@@ -0,0 +1,103 @@
+#include "client/lag_monitor.h"
+
+#include <QCoreApplication>
+#include <QDateTime>
+#include <QEvent>
+#include <QLoggingCategory>
+#include <gtest/gtest.h>
+
+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<LagMonitor::StallRecord> 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<LagMonitor::StallRecord> 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();
+}