mirror of
https://github.com/qelectrotech/qelectrotech-source-mirror.git
synced 2026-08-13 10:04:13 +02:00
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.
This commit is contained in:
@@ -118,6 +118,8 @@ set(QET_SRC_FILES
|
|||||||
${QET_DIR}/sources/cli_export.h
|
${QET_DIR}/sources/cli_export.h
|
||||||
${QET_DIR}/sources/logging/crashhandler.cpp
|
${QET_DIR}/sources/logging/crashhandler.cpp
|
||||||
${QET_DIR}/sources/logging/crashhandler.h
|
${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.cpp
|
||||||
${QET_DIR}/sources/logging/logring.h
|
${QET_DIR}/sources/logging/logring.h
|
||||||
${QET_DIR}/sources/logging/qetlogger.cpp
|
${QET_DIR}/sources/logging/qetlogger.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 <http://www.gnu.org/licenses/>.
|
||||||
|
*/
|
||||||
|
#include "eventloopwatchdog.h"
|
||||||
|
|
||||||
|
#include <QDebug>
|
||||||
|
#include <QProcessEnvironment>
|
||||||
|
|
||||||
|
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)";
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -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 <http://www.gnu.org/licenses/>.
|
||||||
|
*/
|
||||||
|
#ifndef EVENTLOOPWATCHDOG_H
|
||||||
|
#define EVENTLOOPWATCHDOG_H
|
||||||
|
|
||||||
|
#include <QElapsedTimer>
|
||||||
|
#include <QObject>
|
||||||
|
#include <QTimer>
|
||||||
|
|
||||||
|
/**
|
||||||
|
@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
|
||||||
@@ -16,6 +16,7 @@
|
|||||||
along with QElectroTech. If not, see <http://www.gnu.org/licenses/>.
|
along with QElectroTech. If not, see <http://www.gnu.org/licenses/>.
|
||||||
*/
|
*/
|
||||||
#include "cli_export.h"
|
#include "cli_export.h"
|
||||||
|
#include "logging/eventloopwatchdog.h"
|
||||||
#include "logging/qetlogger.h"
|
#include "logging/qetlogger.h"
|
||||||
#include "machine_info.h"
|
#include "machine_info.h"
|
||||||
#include "qet.h"
|
#include "qet.h"
|
||||||
@@ -209,6 +210,13 @@ QGuiApplication::setHighDpiScaleFactorRoundingPolicy(QetSettings::hdpiScaleFacto
|
|||||||
QetLogger::instance().pruneOldLogFiles(7);
|
QetLogger::instance().pruneOldLogFiles(7);
|
||||||
MachineInfo::instance()->send_info_to_debug();
|
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();
|
return app.exec();
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user