From da3a976b60ce1b29631123193d15b3f9750aa8fe Mon Sep 17 00:00:00 2001 From: ispyisail Date: Wed, 5 Aug 2026 20:28:18 +1200 Subject: [PATCH] Add an event-loop responsiveness watchdog (discussion #644 follow-up) QetLogger (discussion #644, steps 1-3) captures whatever an explicit qDebug()/qInfo()/qWarning() call already decided to report. Most of a session -- painting, dragging, a slow synchronous operation -- produces no log output at all, so a silent multi-second gap in the log is indistinguishable from the user simply not doing anything. That gap came up directly: investigating a user-reported "the program lagged" required inferring stalls from timestamp gaps between unrelated log lines, which can't tell a real freeze apart from normal idle time. EventLoopWatchdog closes that gap directly instead of inferring it. A QTimer::PreciseTimer repeating tick (every 50ms) measures the *actual* elapsed time since the previous tick via QElapsedTimer (monotonic, unaffected by system clock/NTP adjustments). Qt does not queue up missed fires for a normal repeating timer, so if the main thread is blocked for 600ms, the timer fires once as soon as the loop frees up, with ~600ms measured since the last tick -- that gap is the stall, measured at its source. Only logs (via the existing qWarning() path, so it reuses QetLogger's file/ring/rotation with no new plumbing) when a tick is late by more than 200ms, so a healthy session produces zero output from this class, in keeping with QetLogger's bounded-log design. Same QET_WATCHDOG_DISABLE=1 escape-hatch convention as QetLogger's own QET_LOG_DISABLE=1. Deliberately not included: attributing a stall to what caused it. This tells you a stall happened and how long -- pairing that timestamp with gdb attached to a running session (as used for the CLI hang, PR #661) is still how you get from "it stalled" to a root cause. Stacked on #647 (feature-diagnostic-logging-crash) for QetLogger/ qWarning() plumbing this depends on -- diff includes its commits until that merges. Verified against the compiled binary, not just read: temporarily injected a QThread::msleep(600) via a one-shot QTimer 2s after startup, confirmed the exact expected warning ("EventLoopWatchdog: main thread stalled for 620 ms") at the right severity through the real qWarning()/QetLogger path, then removed the test hook and reconfirmed a normal run produces no output from this class at all. --- cmake/qet_compilation_vars.cmake | 2 + sources/logging/eventloopwatchdog.cpp | 58 +++++++++++++++++ sources/logging/eventloopwatchdog.h | 92 +++++++++++++++++++++++++++ sources/main.cpp | 8 +++ 4 files changed, 160 insertions(+) create mode 100644 sources/logging/eventloopwatchdog.cpp create mode 100644 sources/logging/eventloopwatchdog.h diff --git a/cmake/qet_compilation_vars.cmake b/cmake/qet_compilation_vars.cmake index 014273dec..4c1ea84db 100644 --- a/cmake/qet_compilation_vars.cmake +++ b/cmake/qet_compilation_vars.cmake @@ -118,6 +118,8 @@ set(QET_SRC_FILES ${QET_DIR}/sources/cli_export.h ${QET_DIR}/sources/logging/crashhandler.cpp ${QET_DIR}/sources/logging/crashhandler.h + ${QET_DIR}/sources/logging/eventloopwatchdog.cpp + ${QET_DIR}/sources/logging/eventloopwatchdog.h ${QET_DIR}/sources/logging/logring.cpp ${QET_DIR}/sources/logging/logring.h ${QET_DIR}/sources/logging/qetlogger.cpp diff --git a/sources/logging/eventloopwatchdog.cpp b/sources/logging/eventloopwatchdog.cpp new file mode 100644 index 000000000..8d75c09a4 --- /dev/null +++ b/sources/logging/eventloopwatchdog.cpp @@ -0,0 +1,58 @@ +/* + Copyright 2006-2026 The QElectroTech Team + This file is part of QElectroTech. + + QElectroTech is free software: you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation, either version 2 of the License, or + (at your option) any later version. + + QElectroTech is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with QElectroTech. If not, see . +*/ +#include "eventloopwatchdog.h" + +#include +#include + +EventLoopWatchdog::EventLoopWatchdog(QObject *parent) : + QObject(parent) +{ + m_disabled = QProcessEnvironment::systemEnvironment() + .value(QStringLiteral("QET_WATCHDOG_DISABLE")) == QStringLiteral("1"); + + // Precise, not the default Coarse: Coarse explicitly trades timing + // accuracy for power/scheduling efficiency (platform-dependent, but + // commonly +/- a double-digit percentage), which would show up as + // noise indistinguishable from a real stall in exactly the + // measurement this class exists to make trustworthy. + m_timer.setTimerType(Qt::PreciseTimer); + connect(&m_timer, &QTimer::timeout, this, &EventLoopWatchdog::tick); +} + +void EventLoopWatchdog::start() +{ + if (m_disabled) + return; + + m_elapsed.start(); + m_timer.start(kTickIntervalMs); +} + +void EventLoopWatchdog::tick() +{ + // restart() returns the elapsed time and resets the clock in one + // call, so this tick's own cost is never counted against the next. + const qint64 actual_ms = m_elapsed.restart(); + + if (actual_ms > kStallThresholdMs) { + qWarning() << "EventLoopWatchdog: main thread stalled for" + << actual_ms << "ms (expected a tick every" + << kTickIntervalMs << "ms)"; + } +} diff --git a/sources/logging/eventloopwatchdog.h b/sources/logging/eventloopwatchdog.h new file mode 100644 index 000000000..4a0b43b47 --- /dev/null +++ b/sources/logging/eventloopwatchdog.h @@ -0,0 +1,92 @@ +/* + Copyright 2006-2026 The QElectroTech Team + This file is part of QElectroTech. + + QElectroTech is free software: you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation, either version 2 of the License, or + (at your option) any later version. + + QElectroTech is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with QElectroTech. If not, see . +*/ +#ifndef EVENTLOOPWATCHDOG_H +#define EVENTLOOPWATCHDOG_H + +#include +#include +#include + +/** + @brief The EventLoopWatchdog class + Detects when the main (GUI) thread's event loop goes unresponsive -- + QetLogger (discussion #644) can only see what an explicit qDebug()/ + qInfo()/qWarning() call already decided to report, and most of a + session (painting, dragging, a slow synchronous operation) produces + no log output at all, so a silent multi-second gap in the log is + indistinguishable from the user simply not doing anything. + + This closes that gap the direct way: a repeating QTimer::PreciseTimer + ticks on a short, fixed interval; each tick measures the *actual* + wall-clock time elapsed since the previous one via QElapsedTimer + (monotonic -- unaffected by system clock/NTP adjustments, unlike + QDateTime). Qt does not queue up missed fires for a normal repeating + timer, so if the event loop is blocked for 600ms, the timer fires + once as soon as the loop frees up, with ~600ms measured since the + last tick -- that gap *is* the stall, measured at its source rather + than inferred from log silence. + + Only fires a qWarning() (and so only touches the log at all) when a + tick is late by more than kStallThresholdMs, to stay within the + spirit of QetLogger's bounded-log design (see its class comment) -- + a healthy session should produce zero output from this class. This + tells you *that* a stall happened and *how long* it was, not what + caused it; pair a reported timestamp with `docker exec`+gdb the way + the CLI hang (PR #661) was diagnosed to go from "it lagged" to a + root cause. + + Escape hatch: if QET_WATCHDOG_DISABLE=1 is set in the environment at + construction time, start() does nothing. +*/ +class EventLoopWatchdog : public QObject +{ + Q_OBJECT + + public: + /// How often the watchdog checks in. Small enough to bound the + /// measurement's own granularity, large enough that the tick + /// itself is negligible overhead on the event loop it's watching. + static constexpr int kTickIntervalMs = 50; + + /// A tick arriving later than this many ms after the previous one + /// is logged as a stall. Comfortably above kTickIntervalMs so + /// ordinary OS scheduling noise doesn't produce a warning on every + /// tick, and in the range a user would actually notice as lag. + static constexpr int kStallThresholdMs = 200; + + explicit EventLoopWatchdog(QObject *parent = nullptr); + + /// Starts ticking. Must be called from the main thread, after the + /// event loop it watches is about to run (i.e. immediately before + /// QApplication::exec()) -- constructing this class earlier is + /// harmless, but start() before there is an event loop to tick + /// against would just measure the time until app.exec() is + /// reached. No-op if QET_WATCHDOG_DISABLE=1 was set at + /// construction time. + void start(); + + private slots: + void tick(); + + private: + QTimer m_timer; + QElapsedTimer m_elapsed; + bool m_disabled = false; +}; + +#endif // EVENTLOOPWATCHDOG_H diff --git a/sources/main.cpp b/sources/main.cpp index 1cce54e8e..4932b17b9 100644 --- a/sources/main.cpp +++ b/sources/main.cpp @@ -16,6 +16,7 @@ along with QElectroTech. If not, see . */ #include "cli_export.h" +#include "logging/eventloopwatchdog.h" #include "logging/qetlogger.h" #include "machine_info.h" #include "qet.h" @@ -209,6 +210,13 @@ QGuiApplication::setHighDpiScaleFactorRoundingPolicy(QetSettings::hdpiScaleFacto QetLogger::instance().pruneOldLogFiles(7); MachineInfo::instance()->send_info_to_debug(); }); + + // Constructed here rather than earlier: start() measures ticks against + // the event loop app.exec() is about to run, so there is no point + // (and no accurate baseline) before this line. + EventLoopWatchdog watchdog; + watchdog.start(); + return app.exec(); }