"""Bounded, privacy preserving performance telemetry. Metrics are deliberately process local. RAG workers return one small envelope to the API process, rather than attempting to share an in-memory deque. """ from __future__ import annotations from contextvars import ContextVar from collections import deque import hashlib, threading, time _current: ContextVar[object | None] = ContextVar("perf_metrics", default=None) _lock = threading.Lock() _http = deque(maxlen=512) _sql = deque(maxlen=512) _rag = deque(maxlen=512) def _pct(values, p): if not values: return 0.0 vals = sorted(float(v) for v in values) return round(vals[min(len(vals)-1, int((len(vals)-1)*p))], 2) class RequestMetrics: def __init__(self, trace_id=""): self.trace_id = str(trace_id or "")[:64]; self.started = time.perf_counter() self.sql_count = self.sql_ms = self.sql_lock_errors = 0 def sql(self, elapsed, error=None): self.sql_count += 1; self.sql_ms += float(elapsed) if error and "locked" in str(error).lower(): self.sql_lock_errors += 1 def finish(self, method, path, status): elapsed = (time.perf_counter()-self.started)*1000 # route templates are supplied by the caller; raw paths are never stored row={"endpoint": f"{method} {path}", "status": int(status), "elapsed_ms": round(elapsed,2), "sql_count": self.sql_count, "sql_ms": round(self.sql_ms,2), "sql_lock_errors": self.sql_lock_errors, "at": time.time()} with _lock: _http.append(row) return row class request_scope: def __init__(self, trace_id=""): self.metrics=RequestMetrics(trace_id); self.token=None def __enter__(self): self.token=_current.set(self.metrics); return self.metrics def __exit__(self, *exc): _current.reset(self.token) def current(): return _current.get() def record_sql(elapsed, error=None): m=current() if m: m.sql(elapsed,error) def record_rag(row): if not isinstance(row,dict): return # Keep phase-level embedding diagnostics while excluding query text and # filesystem details. These fields let operators distinguish cold model # load, tokenizer, inference, serialization and IPC overhead. allowed = ("total_ms","validation_ms","embedding_ms","recall_ms","postprocess_ms", "cache_hit","result_count","error","embedding_total_ms", "embedding_process_start_ms","embedding_ipc_ms","embedding_model_load_ms", "embedding_tokenizer_ms","embedding_encode_ms","embedding_postprocess_ms", "embedding_source","embedding_count","embedding_model","embedding_version", "embedding_dim","embedding_dimension","embedding_pid","embedding_cache_hit", "embedding_cache_size","embedding_cache_hits","embedding_cache_misses","embedding_cache_hit_rate","worker_pid", "worker_reused","worker_start_ms","serialization_ms","merge_ms","dedup_ms","rrf_ms", "retrieval_scopes","warm_state","queue_wait_ms","transport_total_ms") clean={k: row.get(k) for k in allowed if k in row} with _lock: _rag.append(clean) def _summary(rows, rag=False): if not rows: return {"samples":0,"p50_ms":0.0,"p95_ms":0.0,"errors":0} total=[r.get("total_ms",r.get("elapsed_ms",0)) for r in rows] out={"samples":len(rows),"p50_ms":_pct(total,.5),"p95_ms":_pct(total,.95), "errors":sum(1 for r in rows if int(r.get("status",200))>=400 or r.get("error"))} if rag: out["cache_hit_rate"]=round(sum(bool(r.get("cache_hit")) for r in rows)/len(rows),4) return out def snapshot(): with _lock: h=list(_http); s=list(_sql); r=list(_rag) sql_ms=[x.get("sql_ms",0) for x in h] slowest = sorted(h, key=lambda row: float(row.get("elapsed_ms", 0)), reverse=True)[:10] status_counts = {} for row in h: group = f"{int(row.get('status', 200)) // 100}xx" status_counts[group] = status_counts.get(group, 0) + 1 return {"scope":"current_process","window_samples":len(h),"api":{**_summary(h),"p99_ms":_pct([x.get("elapsed_ms",0) for x in h],.99),"sql_count":sum(x.get("sql_count",0) for x in h),"sql_ms":round(sum(sql_ms),2),"sql_lock_errors":sum(x.get("sql_lock_errors",0) for x in h),"slowest":slowest,"status_counts":status_counts},"rag":{**_summary(r,True),"phases":{}},"resets_on_restart":True} def rag_snapshot(): with _lock: rows=list(_rag) out=_summary(rows,True) for phase in ("validation_ms","embedding_ms","recall_ms","postprocess_ms"): vals=[r.get(phase,0) for r in rows]; out.setdefault("phases",{})[phase]={"p50_ms":_pct(vals,.5),"p95_ms":_pct(vals,.95)} for phase in ("serialization_ms", "merge_ms", "dedup_ms", "rrf_ms", "queue_wait_ms", "transport_total_ms"): if any(phase in r for r in rows): vals = [r.get(phase, 0) for r in rows] out.setdefault("phases", {})[phase] = { "p50_ms": _pct(vals, .5), "p95_ms": _pct(vals, .95)} embedding_phases = ("embedding_total_ms", "embedding_process_start_ms", "embedding_ipc_ms", "embedding_model_load_ms", "embedding_tokenizer_ms", "embedding_encode_ms", "embedding_postprocess_ms") out["embedding"] = { phase: {"p50_ms": _pct([r.get(phase, 0) for r in rows], .5), "p95_ms": _pct([r.get(phase, 0) for r in rows], .95)} for phase in embedding_phases if any(phase in r for r in rows) } if rows: scoped = [r.get("retrieval_scopes") for r in rows if isinstance(r.get("retrieval_scopes"), list)] if scoped: latest = scoped[-1] out["scopes"] = latest[:12] warm_states = [r.get("warm_state") for r in rows if isinstance(r.get("warm_state"), dict)] if warm_states: out["warm_state"] = warm_states[-1] out["embedding"]["cache_hit_rate"] = round( sum(bool(r.get("embedding_cache_hit")) for r in rows if "embedding_cache_hit" in r) / max(1, sum(1 for r in rows if "embedding_cache_hit" in r)), 4) out["embedding"]["sources"] = sorted({str(r.get("embedding_source")) for r in rows if r.get("embedding_source")}) out["embedding"]["models"] = sorted({str(r.get("embedding_model")) for r in rows if r.get("embedding_model")}) out["embedding"]["pids"] = sorted({int(r["embedding_pid"]) for r in rows if str(r.get("embedding_pid", "")).isdigit()}) counts = [int(r.get("embedding_count", 0) or 0) for r in rows if "embedding_count" in r] if counts: out["embedding"]["count_p50"] = _pct(counts, .5) out["embedding"]["count_max"] = max(counts) out["embedding"]["batch_warning"] = max(counts) > 1 return out def ingest_http(row): if isinstance(row,dict): with _lock: _http.append(dict(row)) def ingest_rag(row): record_rag(row) def install_sql_hooks(engine): try: from sqlalchemy import event from sqlalchemy.engine import Engine if getattr(engine,"_perf_hooks_installed",False): return @event.listens_for(engine,"before_cursor_execute") def before(conn,cursor,statement,parameters,context,executemany): context._perf_started=time.perf_counter() @event.listens_for(engine,"after_cursor_execute") def after(conn,cursor,statement,parameters,context,executemany): record_sql((time.perf_counter()-getattr(context,"_perf_started",time.perf_counter()))*1000) @event.listens_for(engine,"handle_error") def error(exception_context): record_sql(0,exception_context.original_exception) engine._perf_hooks_installed=True except Exception: pass