From 31dcda425d15e0e3014c26822279563ca959d7da Mon Sep 17 00:00:00 2001 From: aivibe <93047788+axisrow@users.noreply.github.com> Date: Mon, 23 Mar 2026 00:23:38 +0800 Subject: [PATCH 1/3] feat: add request timing middleware and /debug/timing page Add TimingMiddleware that measures per-request duration and stores results in a TimingBuffer. Slow requests (>500ms) are logged as WARNING. A new /debug/timing page displays the last 200 requests sorted by duration, with color-coded rows for slow/very-slow requests. Closes #203 Co-Authored-By: Claude Sonnet 4.6 --- src/web/app.py | 26 ++++++++++++++++++++++++++ src/web/assembly.py | 7 +++++++ src/web/bootstrap.py | 3 +++ src/web/container.py | 2 ++ src/web/deps.py | 6 ++++++ src/web/routes/debug.py | 18 ++++++++++++++++++ src/web/templates/_timing_rows.html | 11 +++++++++++ src/web/templates/debug.html | 5 ++++- src/web/templates/debug_timing.html | 28 ++++++++++++++++++++++++++++ src/web/timing.py | 28 ++++++++++++++++++++++++++++ 10 files changed, 133 insertions(+), 1 deletion(-) create mode 100644 src/web/templates/_timing_rows.html create mode 100644 src/web/templates/debug_timing.html create mode 100644 src/web/timing.py diff --git a/src/web/app.py b/src/web/app.py index b0f7f678..1d1c3532 100644 --- a/src/web/app.py +++ b/src/web/app.py @@ -4,6 +4,7 @@ import logging import re import secrets +import time from contextlib import asynccontextmanager from fastapi import FastAPI, Request @@ -14,6 +15,7 @@ from src.config import AppConfig, load_config from src.web.assembly import ( build_log_buffer, + build_timing_buffer, configure_app, register_builtin_endpoints, register_routes, @@ -77,6 +79,27 @@ def _resolve_action_label(path: str) -> str: return "" +class TimingMiddleware(BaseHTTPMiddleware): + async def dispatch(self, request: Request, call_next): + t0 = time.monotonic() + response = await call_next(request) + ms = int((time.monotonic() - t0) * 1000) + path = request.url.path + if not is_public_path(path) and not path.startswith("/static"): + buf = getattr(request.app.state, "timing_buffer", None) + if buf is not None: + buf.add({ + "time": time.strftime("%H:%M:%S"), + "method": request.method, + "path": path, + "status": response.status_code, + "ms": ms, + }) + if ms > 500: + logger.warning("SLOW %s %s %dms [%d]", request.method, path, ms, response.status_code) + return response + + class ActionLogMiddleware(BaseHTTPMiddleware): async def dispatch(self, request: Request, call_next): if request.method in _LOG_METHODS: @@ -137,6 +160,7 @@ async def lifespan(app: FastAPI): container = await build_container_with_templates( app.state.config, log_buffer=app.state.log_buffer, + timing_buffer=app.state.timing_buffer, templates=app.state.templates, ) configure_app(app, container) @@ -157,6 +181,7 @@ def create_app(config: AppConfig | None = None) -> FastAPI: app = FastAPI(title="TG Post Search", lifespan=lifespan) app.state.config = config app.state.log_buffer = build_log_buffer() + app.state.timing_buffer = build_timing_buffer() app.state.templates = configure_template_globals( Jinja2Templates(directory=str(TEMPLATES_DIR)), config, @@ -167,6 +192,7 @@ def create_app(config: AppConfig | None = None) -> FastAPI: app.add_middleware(BasicAuthMiddleware, password=config.web.password) app.add_middleware(OriginCSRFMiddleware) app.add_middleware(ActionLogMiddleware) + app.add_middleware(TimingMiddleware) @app.exception_handler(Exception) async def unhandled_exception_handler(request: Request, exc: Exception): diff --git a/src/web/assembly.py b/src/web/assembly.py index 7050279b..2e5adfe6 100644 --- a/src/web/assembly.py +++ b/src/web/assembly.py @@ -36,6 +36,7 @@ def configure_app(app: FastAPI, container: AppContainer | None) -> None: app.state.photo_task_service = container.photo_task_service app.state.photo_auto_upload_service = container.photo_auto_upload_service app.state.session_secret = container.session_secret + app.state.timing_buffer = container.timing_buffer elif not hasattr(app.state, "templates"): app.state.templates = configure_template_globals( Jinja2Templates(directory=str(TEMPLATES_DIR)), @@ -146,6 +147,12 @@ def register_routes(app: FastAPI) -> None: app.include_router(pipelines_router, prefix="/pipelines") +def build_timing_buffer(): + from src.web.timing import TimingBuffer + + return TimingBuffer(maxlen=200) + + def build_log_buffer() -> logging.Handler: from src.web.log_handler import LogBuffer diff --git a/src/web/bootstrap.py b/src/web/bootstrap.py index d836ee58..37c7d63f 100644 --- a/src/web/bootstrap.py +++ b/src/web/bootstrap.py @@ -39,6 +39,7 @@ from src.web.log_handler import LogBuffer from src.web.paths import TEMPLATES_DIR from src.web.template_globals import configure_template_globals +from src.web.timing import TimingBuffer logger = logging.getLogger(__name__) @@ -68,6 +69,7 @@ async def build_container_with_templates( config: AppConfig, *, log_buffer: LogBuffer, + timing_buffer: TimingBuffer | None = None, templates: Jinja2Templates | None, ) -> AppContainer: db = Database( @@ -194,6 +196,7 @@ async def build_container_with_templates( scheduler=scheduler, templates=_templates, log_buffer=log_buffer, + timing_buffer=timing_buffer, session_secret=session_secret, bg_tasks=set(), agent_manager=agent_manager, diff --git a/src/web/container.py b/src/web/container.py index c50da890..c1bc1e34 100644 --- a/src/web/container.py +++ b/src/web/container.py @@ -35,6 +35,7 @@ from src.telegram.collector import Collector from src.telegram.notifier import Notifier from src.web.log_handler import LogBuffer +from src.web.timing import TimingBuffer @dataclass(slots=True) @@ -67,6 +68,7 @@ class AppContainer: scheduler: SchedulerManager templates: Jinja2Templates log_buffer: LogBuffer | None + timing_buffer: TimingBuffer | None session_secret: str bg_tasks: set[asyncio.Task] agent_manager: AgentManager | None = None diff --git a/src/web/deps.py b/src/web/deps.py index 5185ffa0..453c1128 100644 --- a/src/web/deps.py +++ b/src/web/deps.py @@ -44,6 +44,7 @@ from src.web.container import AppContainer from src.web.log_handler import LogBuffer from src.web.paths import TEMPLATES_DIR +from src.web.timing import TimingBuffer T = TypeVar("T") _MISSING = object() @@ -133,6 +134,7 @@ def get_container(request: Request) -> AppContainer: scheduler=_require_app_state_attr(request, "scheduler"), templates=templates, log_buffer=getattr(request.app.state, "log_buffer", None), + timing_buffer=getattr(request.app.state, "timing_buffer", None), session_secret=_require_app_state_attr(request, "session_secret"), bg_tasks=getattr(request.app.state, "bg_tasks", set()), agent_manager=getattr(request.app.state, "agent_manager", None), @@ -246,6 +248,10 @@ def get_log_buffer(request: Request) -> LogBuffer | None: return get_container(request).log_buffer +def get_timing_buffer(request: Request) -> TimingBuffer | None: + return get_container(request).timing_buffer + + def is_shutting_down(request: Request) -> bool: return get_container(request).shutting_down diff --git a/src/web/routes/debug.py b/src/web/routes/debug.py index e20807ed..6a88e812 100644 --- a/src/web/routes/debug.py +++ b/src/web/routes/debug.py @@ -22,3 +22,21 @@ async def debug_logs_partial(request: Request): return deps.get_templates(request).TemplateResponse( request, "_debug_logs.html", {"records": records} ) + + +@router.get("/timing", response_class=HTMLResponse) +async def debug_timing(request: Request): + buf = deps.get_timing_buffer(request) + records = sorted(buf.get_records(), key=lambda r: r["ms"], reverse=True) if buf else [] + return deps.get_templates(request).TemplateResponse( + request, "debug_timing.html", {"records": records} + ) + + +@router.get("/timing/rows", response_class=HTMLResponse) +async def debug_timing_rows(request: Request): + buf = deps.get_timing_buffer(request) + records = sorted(buf.get_records(), key=lambda r: r["ms"], reverse=True) if buf else [] + return deps.get_templates(request).TemplateResponse( + request, "_timing_rows.html", {"records": records} + ) diff --git a/src/web/templates/_timing_rows.html b/src/web/templates/_timing_rows.html new file mode 100644 index 00000000..b2095a0b --- /dev/null +++ b/src/web/templates/_timing_rows.html @@ -0,0 +1,11 @@ +{% for r in records %} + 1000 %} class="table-danger"{% elif r.ms > 500 %} class="table-warning"{% endif %}> + {{ r.time }} + {{ r.ms }} ms + {{ r.method }} + {{ r.path }} + {{ r.status }} + +{% else %} +Записей нет — выполните несколько запросов к страницам. +{% endfor %} diff --git a/src/web/templates/debug.html b/src/web/templates/debug.html index 292b6ad1..68592f0c 100644 --- a/src/web/templates/debug.html +++ b/src/web/templates/debug.html @@ -1,7 +1,10 @@ {% extends "base.html" %} {% block title %}Дебаг — TG Agent{% endblock %} {% block content %} -

Консоль сервера

+
+

Консоль сервера

+ Тайминг запросов → +

Последние 500 записей.

diff --git a/src/web/templates/debug_timing.html b/src/web/templates/debug_timing.html new file mode 100644 index 00000000..aede8fdb --- /dev/null +++ b/src/web/templates/debug_timing.html @@ -0,0 +1,28 @@ +{% extends "base.html" %} +{% block title %}Тайминг запросов — TG Agent{% endblock %} +{% block content %} +
+

Тайминг запросов

+ ← Логи +
+

Последние 200 запросов, отсортированных по убыванию длительности. + красный >1000 ms, + жёлтый 500–999 ms. +

+
+
+ + + + + + + + + + + {% include "_timing_rows.html" %} + +
ВремяДлит., msМетодПутьСтатус
+
+{% endblock %} diff --git a/src/web/timing.py b/src/web/timing.py new file mode 100644 index 00000000..d8ebeceb --- /dev/null +++ b/src/web/timing.py @@ -0,0 +1,28 @@ +from __future__ import annotations + +import time +from collections import deque +from typing import TypedDict + + +class TimingRecord(TypedDict): + time: str # "HH:MM:SS" + method: str # GET / POST + path: str # /channels + status: int # 200 + ms: int # длительность в миллисекундах + + +class TimingBuffer: + def __init__(self, maxlen: int = 200): + self._records: deque[TimingRecord] = deque(maxlen=maxlen) + + def add(self, record: TimingRecord) -> None: + self._records.append(record) + + def get_records(self) -> list[TimingRecord]: + return list(self._records) + + @staticmethod + def now() -> str: + return time.strftime("%H:%M:%S") From 314c9b1aa1bc77699a14be5a5a1ef795ad57ceec Mon Sep 17 00:00:00 2001 From: aivibe <93047788+axisrow@users.noreply.github.com> Date: Mon, 23 Mar 2026 00:45:17 +0800 Subject: [PATCH 2/3] fix: wrap TimingMiddleware call_next in try/finally; drop redundant static check MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Use try/finally so timing is always recorded even when call_next raises (e.g. connection resets, streaming errors); status defaults to 500 in error case - Remove redundant `path.startswith("/static")` — is_public_path already covers /static/ paths, keeping public-path logic in one place Co-Authored-By: Claude Sonnet 4.6 --- src/web/app.py | 34 +++++++++++++++++++--------------- 1 file changed, 19 insertions(+), 15 deletions(-) diff --git a/src/web/app.py b/src/web/app.py index 1d1c3532..93754af0 100644 --- a/src/web/app.py +++ b/src/web/app.py @@ -82,21 +82,25 @@ def _resolve_action_label(path: str) -> str: class TimingMiddleware(BaseHTTPMiddleware): async def dispatch(self, request: Request, call_next): t0 = time.monotonic() - response = await call_next(request) - ms = int((time.monotonic() - t0) * 1000) - path = request.url.path - if not is_public_path(path) and not path.startswith("/static"): - buf = getattr(request.app.state, "timing_buffer", None) - if buf is not None: - buf.add({ - "time": time.strftime("%H:%M:%S"), - "method": request.method, - "path": path, - "status": response.status_code, - "ms": ms, - }) - if ms > 500: - logger.warning("SLOW %s %s %dms [%d]", request.method, path, ms, response.status_code) + response = None + try: + response = await call_next(request) + finally: + ms = int((time.monotonic() - t0) * 1000) + path = request.url.path + if not is_public_path(path): + status = response.status_code if response is not None else 500 + buf = getattr(request.app.state, "timing_buffer", None) + if buf is not None: + buf.add({ + "time": time.strftime("%H:%M:%S"), + "method": request.method, + "path": path, + "status": status, + "ms": ms, + }) + if ms > 500: + logger.warning("SLOW %s %s %dms [%d]", request.method, path, ms, status) return response From 1f77347c36260194eb8714a3c723f5abcedeff17 Mon Sep 17 00:00:00 2001 From: aivibe <93047788+axisrow@users.noreply.github.com> Date: Mon, 23 Mar 2026 00:57:37 +0800 Subject: [PATCH 3/3] chore: remove unused TimingBuffer.now() static method Co-Authored-By: Claude Sonnet 4.6 --- src/web/timing.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/src/web/timing.py b/src/web/timing.py index d8ebeceb..b24adae2 100644 --- a/src/web/timing.py +++ b/src/web/timing.py @@ -1,6 +1,5 @@ from __future__ import annotations -import time from collections import deque from typing import TypedDict @@ -22,7 +21,3 @@ def add(self, record: TimingRecord) -> None: def get_records(self) -> list[TimingRecord]: return list(self._records) - - @staticmethod - def now() -> str: - return time.strftime("%H:%M:%S")