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);