From e77a175fc93f2c09fff0cfa49ceea9a5d63abad7 Mon Sep 17 00:00:00 2001 From: ispyisail Date: Mon, 5 Oct 2026 18:32:42 +1300 Subject: [PATCH 1/2] Live mode: optional timing of each request (QET_LIVE_PERF_LOG) A request with "timing": true gets queue, confirm and exec times in its answer; with QET_LIVE_PERF_LOG set, QElectroTech also appends one JSON line per request, with the time until the folio is next painted. The qet MCP server logs its side of each live call to the same file. Co-Authored-By: Claude Opus 5.5 --- misc/qet-mcp/qet_mcp.py | 33 ++++++++- sources/scripting/liveserver.cpp | 113 ++++++++++++++++++++++++++++++- sources/scripting/liveserver.h | 2 +- 3 files changed, 143 insertions(+), 5 deletions(-) diff --git a/misc/qet-mcp/qet_mcp.py b/misc/qet-mcp/qet_mcp.py index df5c2a157..88aedbdd3 100755 --- a/misc/qet-mcp/qet_mcp.py +++ b/misc/qet-mcp/qet_mcp.py @@ -64,6 +64,8 @@ import shutil import subprocess import sys import tempfile +import time +import uuid import xml.etree.ElementTree as ET from pathlib import Path, PurePath, PurePosixPath, PureWindowsPath @@ -4016,9 +4018,21 @@ def _live_session() -> dict: return live +_live_last_end = None + + def _live_call(request: dict, timeout: float = 60.0) -> dict: + # QET_LIVE_PERF_LOG: append one JSON line per request with where its + # time went (tools/live-perf/monitor.py in the docker harness reads it; + # QElectroTech writes its own half when started with the same variable). + perf_log = os.environ.get("QET_LIVE_PERF_LOG", "").strip() + started = time.perf_counter() session = _live_session() - request = dict(request, token=session.get("token", ""), id=1) + request_id = uuid.uuid4().hex[:12] if perf_log else 1 + request = dict(request, token=session.get("token", ""), id=request_id) + if perf_log: + request["timing"] = True + t_session = time.perf_counter() line = (json.dumps(request) + "\n").encode("utf-8") name = session.get("socket", "") try: @@ -4052,6 +4066,23 @@ def _live_call(request: dict, timeout: float = 60.0) -> dict: raise ValueError("QElectroTech closed the live channel without answering") answer = json.loads(data.decode("utf-8")) answer.pop("id", None) + if perf_log: + global _live_last_end + ended = time.perf_counter() + line = {"src": "client", "id": request_id, "cmd": request.get("cmd"), + "label": "mcp", "t": time.time(), "pid": os.getpid(), + "gap_ms": round((started - _live_last_end) * 1000, 2) + if _live_last_end is not None else None, + "session_ms": round((t_session - started) * 1000, 2), + "total_ms": round((ended - started) * 1000, 2), + "answer_bytes": len(data), "ok": answer.get("ok"), + "server": answer.pop("timing", None)} + _live_last_end = ended + try: + with open(perf_log, "a", encoding="utf-8") as f: + f.write(json.dumps(line) + "\n") + except OSError: + pass return answer diff --git a/sources/scripting/liveserver.cpp b/sources/scripting/liveserver.cpp index 6eb679c18..7a77edf77 100644 --- a/sources/scripting/liveserver.cpp +++ b/sources/scripting/liveserver.cpp @@ -48,12 +48,86 @@ #include #include #include +#include +#include +#include +#include #include #include #include "../projectview.h" #include "../shortcutmanager.h" namespace { + /** + Timing of the live channel, for finding where an assistant's + request spends its time. Nothing is measured unless the request + asks for it ("timing": true, answered in "timing") or the + environment names a log file (QET_LIVE_PERF_LOG: one JSON line per + request, with the time until the folio is next painted). + */ + qint64 nowNs() + { + static QElapsedTimer clock; + if (!clock.isValid()) clock.start(); + return clock.nsecsElapsed(); + } + + double ms(qint64 ns) { return qRound(ns / 1e4) / 100.0; } + + QString perfLogPath() + { + static const QString path = qEnvironmentVariable("QET_LIVE_PERF_LOG"); + return path; + } + + void appendPerfLog(const QJsonObject &line) + { + QFile file(perfLogPath()); + if (file.open(QIODevice::WriteOnly | QIODevice::Append)) + file.write(QJsonDocument(line).toJson(QJsonDocument::Compact) + '\n'); + } + + /** + Waits for the next paint of a widget (the folio on screen) and + calls done with the time it started and the time the event loop + came back, or with -1 when nothing was painted within 2 s (a + request that changed nothing visible). + */ + class PaintProbe : public QObject + { + public: + PaintProbe(QWidget *widget, std::function done) : + QObject(widget), m_done(std::move(done)) + { + widget->installEventFilter(this); + QTimer::singleShot(2000, this, [this]() { finish(-1, -1); }); + } + + protected: + bool eventFilter(QObject *, QEvent *event) override + { + if (event->type() == QEvent::Paint && m_start < 0) { + m_start = nowNs(); + //Runs once the paint event has been handled + QTimer::singleShot(0, this, [this]() { finish(m_start, nowNs()); }); + } + return false; + } + + private: + void finish(qint64 start, qint64 end) + { + if (!m_done) return; + auto done = std::move(m_done); + m_done = nullptr; + done(start, end); + deleteLater(); + } + + std::function m_done; + qint64 m_start = -1; + }; + QString randomHex(int bytes) { QByteArray raw(bytes, Qt::Uninitialized); @@ -214,8 +288,9 @@ void LiveServer::readClient() return; } setState(Connected); + const qint64 received = nowNs(); //Out of the socket handler before anything runs (see class doc) - QTimer::singleShot(0, this, [this, request]() { handle(request); }); + QTimer::singleShot(0, this, [this, request, received]() { handle(request, received); }); } } @@ -227,8 +302,10 @@ void LiveServer::send(const QJsonObject &answer) } } -void LiveServer::handle(const QJsonObject &request) +void LiveServer::handle(const QJsonObject &request, qint64 received_ns) { + const qint64 started = nowNs(); + qint64 confirm_ns = 0; const QString cmd = request.value(QStringLiteral("cmd")).toString(); QJsonObject answer; if (m_busy) { @@ -243,7 +320,10 @@ void LiveServer::handle(const QJsonObject &request) //A script the assistant just wrote: the user sees it first, //unless they said "always" this session. A stored script //is one the user already has, so it runs as a click would. - if (m_ask_first && !confirm(name, source)) + const qint64 confirm_start = nowNs(); + const bool refused = m_ask_first && !confirm(name, source); + confirm_ns = nowNs() - confirm_start; + if (refused) answer = failure(QStringLiteral("refused by the user")); else answer = runScript(name, source); @@ -264,7 +344,14 @@ void LiveServer::handle(const QJsonObject &request) } if (request.contains(QStringLiteral("id"))) answer.insert(QStringLiteral("id"), request.value(QStringLiteral("id"))); + const qint64 done = nowNs(); + QJsonObject timing{{QStringLiteral("queue_ms"), ms(started - received_ns)}, + {QStringLiteral("confirm_ms"), ms(confirm_ns)}, + {QStringLiteral("exec_ms"), ms(done - started - confirm_ns)}}; + if (request.value(QStringLiteral("timing")).toBool()) + answer.insert(QStringLiteral("timing"), timing); send(answer); + timing.insert(QStringLiteral("reply_ms"), ms(nowNs() - received_ns)); //One request per connection: close it from this side once it is //answered. Waiting for the client to hang up raced the next //request on Windows, where a named pipe's disconnection reaches @@ -274,6 +361,26 @@ void LiveServer::handle(const QJsonObject &request) m_client->disconnectFromServer(); m_client = nullptr; } + if (!perfLogPath().isEmpty()) { + timing.insert(QStringLiteral("src"), QStringLiteral("qet")); + timing.insert(QStringLiteral("id"), request.value(QStringLiteral("id"))); + timing.insert(QStringLiteral("cmd"), cmd); + timing.insert(QStringLiteral("ok"), answer.value(QStringLiteral("ok"))); + timing.insert(QStringLiteral("t"), QDateTime::currentMSecsSinceEpoch() / 1000.0); + QETDiagramEditor *e = editor(); + DiagramView *view = e ? e->currentDiagramView() : nullptr; + if (!view) { + appendPerfLog(timing); + } else { + new PaintProbe(view->viewport(), [timing, received_ns](qint64 start, qint64 end) mutable { + timing.insert(QStringLiteral("paint_start_ms"), + start < 0 ? QJsonValue() : QJsonValue(ms(start - received_ns))); + timing.insert(QStringLiteral("paint_ms"), + start < 0 ? QJsonValue() : QJsonValue(ms(end - start))); + appendPerfLog(timing); + }); + } + } emit handled(request, answer); } diff --git a/sources/scripting/liveserver.h b/sources/scripting/liveserver.h index 2a8726a88..57d44bcd2 100644 --- a/sources/scripting/liveserver.h +++ b/sources/scripting/liveserver.h @@ -77,7 +77,7 @@ class LiveServer : public QObject void setState(State state); void newConnection(); void readClient(); - void handle(const QJsonObject &request); + void handle(const QJsonObject &request, qint64 received_ns); void send(const QJsonObject &answer); QJsonObject status(); QJsonObject runScript(const QString &name, const QString &source); From 9b775baf6eebb5c3950c6c9416867b80187c944e Mon Sep 17 00:00:00 2001 From: ispyisail Date: Mon, 5 Oct 2026 20:35:19 +1300 Subject: [PATCH 2/2] qet-mcp README: the live timing log Co-Authored-By: Claude Opus 5.5 --- misc/qet-mcp/README.md | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/misc/qet-mcp/README.md b/misc/qet-mcp/README.md index 0852d13a4..d1f75792a 100644 --- a/misc/qet-mcp/README.md +++ b/misc/qet-mcp/README.md @@ -356,6 +356,14 @@ action, with a *Stop* button that closes the channel for the rest of the session. Each action is one Ctrl+Z. A script's `qet.showMessage()` is logged instead of opening a box nobody asked for. +To see where a live request spends its time, start QElectroTech and this +server with the same `QET_LIVE_PERF_LOG=/path/to/log.jsonl`. Each side +appends one JSON line per request, with the same `id`: the server its +total, the time reading `qet-assistant.json` and the gap since its previous +call (the assistant's own turn); QElectroTech the time queued, waiting on +your answer, running, and until the folio is next repainted. Nothing is +written when the variable is unset. + The channel is a local socket only your user can open. QElectroTech puts its name and a random token in the `live` part of `qet-assistant.json`, and clears it when the channel closes; `qet_about` says whether one is