diff --git a/misc/qet-mcp/README.md b/misc/qet-mcp/README.md index cfff5419a..c21ebeaa5 100644 --- a/misc/qet-mcp/README.md +++ b/misc/qet-mcp/README.md @@ -389,6 +389,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 diff --git a/misc/qet-mcp/qet_mcp.py b/misc/qet-mcp/qet_mcp.py index dd11523ae..1ceaad4b9 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 @@ -4236,9 +4238,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: @@ -4272,6 +4286,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 5327c0d95..da9ccc352 100644 --- a/sources/scripting/liveserver.cpp +++ b/sources/scripting/liveserver.cpp @@ -50,6 +50,10 @@ #include #include #include +#include +#include +#include +#include #include #include #include @@ -63,6 +67,76 @@ #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); @@ -234,8 +308,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); }); } } @@ -247,8 +322,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) { @@ -263,7 +340,10 @@ void LiveServer::handle(const QJsonObject &request) //A script the assistant just wrote: the user sees it first, //unless they chose "always" (remembered). 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); @@ -300,7 +380,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 @@ -310,6 +397,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 5a1211feb..71c72fdfb 100644 --- a/sources/scripting/liveserver.h +++ b/sources/scripting/liveserver.h @@ -79,7 +79,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);