From 7aeabb9f25da178d44df1842818b60f40c75417a Mon Sep 17 00:00:00 2001 From: jolavillette Date: Wed, 29 Jul 2026 12:58:12 +0200 Subject: [PATCH] gui(gxs): opt-in latency probes on the group statistics path Set RS_GUI_PROFILE to a threshold in milliseconds (0 reports everything) to get one line per measured operation on stderr. These probes are what turned every claim of this branch into a number: the 839-jobs-per-second storm, the 104 timeouts, the 172 s serial pass, and the 15 s bounded window were all read from their output rather than guessed. GxsPerfProbe.h is shared byte-for-byte with the branch instrumenting the forum read/unread path, so both merge cleanly whichever lands first. All probes are inert unless the environment variable is set. Co-Authored-By: Claude Opus 5 (1M context) --- retroshare-gui/src/gui/NewsFeed.cpp | 6 + .../src/gui/gxs/GxsGroupFrameDialog.cpp | 21 ++- retroshare-gui/src/gui/gxs/GxsPerfProbe.h | 140 ++++++++++++++++++ .../src/gui/gxsforums/GxsForumsDialog.cpp | 3 + 4 files changed, 169 insertions(+), 1 deletion(-) create mode 100644 retroshare-gui/src/gui/gxs/GxsPerfProbe.h diff --git a/retroshare-gui/src/gui/NewsFeed.cpp b/retroshare-gui/src/gui/NewsFeed.cpp index ee39a70e4..04138387e 100644 --- a/retroshare-gui/src/gui/NewsFeed.cpp +++ b/retroshare-gui/src/gui/NewsFeed.cpp @@ -21,6 +21,7 @@ #include #include "NewsFeed.h" +#include "gui/gxs/GxsPerfProbe.h" #include "ui_NewsFeed.h" #include @@ -275,6 +276,11 @@ void NewsFeed::handleForumEvent(std::shared_ptr event) const RsGxsForumEvent *pe = dynamic_cast(event.get()); if(!pe) return; + // Runs on the GUI thread and builds one full widget per incoming message, + // so a sync burst turns into a burst of widget construction here. + RsGuiPerf::Probe prof("newsFeed::handleForumEvent"); + prof.detail(QString("code=%1").arg(static_cast(pe->mForumEventCode))); + switch(pe->mForumEventCode) { case RsForumEventCode::MODERATOR_LIST_CHANGED: diff --git a/retroshare-gui/src/gui/gxs/GxsGroupFrameDialog.cpp b/retroshare-gui/src/gui/gxs/GxsGroupFrameDialog.cpp index 848a24541..fbb675f6f 100644 --- a/retroshare-gui/src/gui/gxs/GxsGroupFrameDialog.cpp +++ b/retroshare-gui/src/gui/gxs/GxsGroupFrameDialog.cpp @@ -38,6 +38,7 @@ #include "retroshare/rsgxsifacetypes.h" #include "GxsCommentDialog.h" #include "util/DateTime.h" +#include "gui/gxs/GxsPerfProbe.h" //#define DEBUG_GROUPFRAMEDIALOG @@ -982,6 +983,9 @@ void GxsGroupFrameDialog::insertGroupsData(const std::list adminList; @@ -1110,6 +1114,8 @@ void GxsGroupFrameDialog::updateMessageSummaryListReal(RsGxsGroupId groupId) return; } + RsGuiPerf::Probe prof("updateMessageSummaryListReal"); + if (groupId.isNull()) { QTreeWidgetItem *items[2] = { mYourGroups, mSubscribedGroups }; @@ -1157,6 +1163,8 @@ void GxsGroupFrameDialog::updateGroupSummary() RsQThreadUtils::postToObject( [this,groupInfo]() { + RsGuiPerf::Probe prof("groupSummary(UI apply)"); + /* Here it goes any code you want to be executed on the Qt Gui * thread, for example to update the data model with new information * after a blocking call to RetroShare API complete, note that @@ -1325,13 +1333,24 @@ void GxsGroupFrameDialog::startOneStatisticsJob(const RsGxsGroupId &groupId) RsThread::async([this,groupId]() { GxsGroupStatistic stats; - const bool ok = getGroupStatistics(groupId, stats); + bool ok = false; + + { + // Runs off the GUI thread, but holds the GXS engine for its whole + // duration, so it delays everything the interface waits for. + RsGuiPerf::Probe prof("getGroupStatistics"); + prof.detail(QString::fromStdString(groupId.toStdString())); + + ok = getGroupStatistics(groupId, stats); + } if(!ok) std::cerr << __PRETTY_FUNCTION__ << " failed to collect group statistics for group " << groupId << std::endl; RsQThreadUtils::postToObject( [this,stats,groupId,ok]() { + RsGuiPerf::Probe prof("groupStatistics(UI apply)"); + /* Here it goes any code you want to be executed on the Qt Gui * thread, for example to update the data model with new information * after a blocking call to RetroShare API complete, note that diff --git a/retroshare-gui/src/gui/gxs/GxsPerfProbe.h b/retroshare-gui/src/gui/gxs/GxsPerfProbe.h new file mode 100644 index 000000000..a41742412 --- /dev/null +++ b/retroshare-gui/src/gui/gxs/GxsPerfProbe.h @@ -0,0 +1,140 @@ +/******************************************************************************* + * retroshare-gui/src/gui/gxs/GxsPerfProbe.h * + * * + * Copyright 2026 by Retroshare Team * + * * + * This program is free software: you can redistribute it and/or modify * + * it under the terms of the GNU Affero General Public License as * + * published by the Free Software Foundation, either version 3 of the * + * License, or (at your option) any later version. * + * * + * This program 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 Affero General Public License for more details. * + * * + * You should have received a copy of the GNU Affero General Public License * + * along with this program. If not, see . * + * * + *******************************************************************************/ + +#pragma once + +// Opt-in latency probes, off unless RS_GUI_PROFILE is set in the environment. +// Its value is a reporting threshold in milliseconds, 0 reports everything: +// +// RS_GUI_PROFILE=0 ./retroshare +// +// Output goes through RsDbg(), i.e. stderr: launch from a terminal or the lines +// go nowhere. + +#include +#include +#include + +#include +#include + +#include "util/rsdebug.h" + +namespace RsGuiPerf { + +inline double threshold() +{ + // <0 means disabled. Read once, the environment does not change at runtime. + static const double t = []() -> double { + const char *v = getenv("RS_GUI_PROFILE"); + if(!v) + v = getenv("RS_FORUM_PROFILE"); // legacy name of the first investigation + return v ? atof(v) : -1.0; + }(); + + return t; +} + +inline bool enabled() { return threshold() >= 0; } + +/* Breadcrumb of the last operation a probe measured on the current thread. The + * stall watchdog prints it, so a stall can be attributed even when the probe + * that covered it stayed below the reporting threshold. */ +inline const char *& lastOp() { static thread_local const char *s = "none"; return s; } +inline double& lastOpMs() { static thread_local double d = 0; return d; } + +/*! + * \brief RAII timer around one operation. + * + * Report a probe placed on the GUI thread as time the interface stayed frozen. + */ +class Probe +{ +public: + explicit Probe(const char *what) + : mWhat(what), mStart(std::chrono::steady_clock::now()) {} + + ~Probe() + { + if(!enabled()) + return; + + const double ms = std::chrono::duration( + std::chrono::steady_clock::now() - mStart ).count(); + + lastOp() = mWhat; + lastOpMs() = ms; + + if(ms >= threshold()) + RsDbg() << "GUI-PROF " << mWhat << " " << mDetails.toStdString() + << " in " << ms << "ms"; + } + + void detail(const QString& s) { mDetails = s; } + +private: + const char *mWhat; + QString mDetails; + std::chrono::steady_clock::time_point mStart; +}; + +/*! + * \brief Watchdog for the GUI thread itself. + * + * The probes above only measure the code they wrap, so they cannot see a stall + * that happens anywhere else. This timer runs on the GUI thread and reports + * whenever the event loop failed to come back on time, whatever the reason and + * wherever the blocking code lives. It also names the last operation a probe + * measured, which points at the culprit when one covers it. + * + * Safe to call several times, only the first call installs anything. + */ +inline void installGuiStallWatchdog() +{ + static bool installed = false; + + if(installed || !enabled()) + return; + + installed = true; + + static const int TICK_MS = 50; + + QTimer *timer = new QTimer(QCoreApplication::instance()); + auto *last = new std::chrono::steady_clock::time_point( + std::chrono::steady_clock::now() ); + + QObject::connect(timer, &QTimer::timeout, QCoreApplication::instance(), [last]() + { + const auto now = std::chrono::steady_clock::now(); + const double ms = std::chrono::duration(now - *last).count(); + *last = now; + + // Anything above the tick plus a comfortable margin means the event loop + // was busy or blocked for that long. + if(ms > TICK_MS + 150) + RsDbg() << "GUI-PROF GUI-THREAD-STALL " << (ms - TICK_MS) + << "ms last_probe=" << lastOp() << " (" << lastOpMs() << "ms)"; + }); + + timer->start(TICK_MS); +} + +} // namespace RsGuiPerf diff --git a/retroshare-gui/src/gui/gxsforums/GxsForumsDialog.cpp b/retroshare-gui/src/gui/gxsforums/GxsForumsDialog.cpp index 2d3b28899..ce4a02229 100644 --- a/retroshare-gui/src/gui/gxsforums/GxsForumsDialog.cpp +++ b/retroshare-gui/src/gui/gxsforums/GxsForumsDialog.cpp @@ -19,6 +19,7 @@ *******************************************************************************/ #include "GxsForumsDialog.h" +#include "gui/gxs/GxsPerfProbe.h" #include "GxsForumGroupDialog.h" #include "GxsForumThreadWidget.h" #include "CreateGxsForumMsg.h" @@ -66,6 +67,8 @@ void GxsForumsDialog::flushPendingStatistics() void GxsForumsDialog::handleEvent_main_thread(std::shared_ptr event) { + RsGuiPerf::Probe prof("forumsDialog::handleEvent"); + if(event->mType == RsEventType::GXS_FORUMS) { const RsGxsForumEvent *e = dynamic_cast(event.get());