Merge 4ee87252df into 613724c26e

src/infra/profiling/index.ts

@@ -0,0 +1,11 @@
+export {
+  createRequestProfiler,
+  setProfilingConfig,
+  getProfilingConfig,
+  isProfilingEnabled,
+  type ProfileMark,
+  type ProfileSegment,
+  type ProfileReport,
+  type RequestProfiler,
+  type ProfilingConfig,
+} from "./request-profiler.js";

src/infra/profiling/request-profiler.test.ts

@@ -0,0 +1,93 @@
+import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
+import {
+  createRequestProfiler,
+  setProfilingConfig,
+  getProfilingConfig,
+  isProfilingEnabled,
+} from "./request-profiler.js";
+
+describe("createRequestProfiler", () => {
+  beforeEach(() => {
+    vi.useFakeTimers();
+  });
+
+  afterEach(() => {
+    vi.useRealTimers();
+  });
+
+  it("creates a profiler with marks", () => {
+    const profiler = createRequestProfiler("test-1");
+    
+    profiler.mark("start");
+    vi.advanceTimersByTime(100);
+    profiler.mark("middle");
+    vi.advanceTimersByTime(200);
+    profiler.mark("end");
+
+    const report = profiler.getReport();
+    
+    expect(report.requestId).toBe("test-1");
+    expect(report.marks).toHaveLength(3);
+    expect(report.totalMs).toBe(300);
+  });
+
+  it("calculates segments correctly", () => {
+    const profiler = createRequestProfiler();
+    
+    profiler.mark("channel_received");
+    vi.advanceTimersByTime(50);
+    profiler.mark("media_downloaded");
+    vi.advanceTimersByTime(150);
+    profiler.mark("agent_invoked");
+    vi.advanceTimersByTime(800);
+    profiler.mark("response_sent");
+
+    const report = profiler.getReport();
+    
+    expect(report.segments).toHaveLength(3);
+    expect(report.segments[0]).toMatchObject({
+      from: "channel_received",
+      to: "media_downloaded",
+      durationMs: 50,
+    });
+    expect(report.segments[1]).toMatchObject({
+      from: "media_downloaded",
+      to: "agent_invoked",
+      durationMs: 150,
+    });
+    expect(report.segments[2]).toMatchObject({
+      from: "agent_invoked",
+      to: "response_sent",
+      durationMs: 800,
+    });
+  });
+
+  it("generates readable log string", () => {
+    const profiler = createRequestProfiler("log-test");
+    
+    profiler.mark("start");
+    vi.advanceTimersByTime(100);
+    profiler.mark("end");
+
+    const logStr = profiler.toLogString();
+    
+    expect(logStr).toContain("log-test");
+    expect(logStr).toContain("total=100ms");
+    expect(logStr).toContain("start → end");
+  });
+});
+
+describe("profiling config", () => {
+  it("manages global config", () => {
+    setProfilingConfig({ enabled: true, logThresholdMs: 500 });
+    
+    const config = getProfilingConfig();
+    expect(config.enabled).toBe(true);
+    expect(config.logThresholdMs).toBe(500);
+    expect(isProfilingEnabled()).toBe(true);
+    
+    // Reset
+    setProfilingConfig({ enabled: false });
+    expect(isProfilingEnabled()).toBe(false);
+  });
+});

src/infra/profiling/request-profiler.ts

@@ -0,0 +1,129 @@
+/**
+ * Request profiling utilities for measuring latency across the message pipeline.
+ * 
+ * Usage:
+ *   const profiler = createRequestProfiler();
+ *   profiler.mark("telegram_received");
+ *   // ... download media ...
+ *   profiler.mark("media_downloaded");
+ *   // ... invoke agent ...
+ *   profiler.mark("agent_invoked");
+ *   // ... get response ...
+ *   profiler.mark("response_ready");
+ *   profiler.mark("response_sent");
+ *   
+ *   const report = profiler.getReport();
+ *   // { totalMs: 2500, segments: [...], marks: [...] }
+ */
+
+export interface ProfileMark {
+  name: string;
+  timestamp: number;
+  delta?: number; // ms since previous mark
+}
+
+export interface ProfileSegment {
+  from: string;
+  to: string;
+  durationMs: number;
+  percentage: number;
+}
+
+export interface ProfileReport {
+  requestId: string;
+  startTime: number;
+  endTime: number;
+  totalMs: number;
+  marks: ProfileMark[];
+  segments: ProfileSegment[];
+}
+
+export interface RequestProfiler {
+  mark(name: string): void;
+  getReport(): ProfileReport;
+  toLogString(): string;
+}
+
+let requestCounter = 0;
+
+export function createRequestProfiler(requestId?: string): RequestProfiler {
+  const id = requestId ?? `req_${Date.now()}_${++requestCounter}`;
+  const marks: ProfileMark[] = [];
+  const startTime = Date.now();
+
+  return {
+    mark(name: string) {
+      const timestamp = Date.now();
+      const prevMark = marks[marks.length - 1];
+      const delta = prevMark ? timestamp - prevMark.timestamp : 0;
+      marks.push({ name, timestamp, delta });
+    },
+
+    getReport(): ProfileReport {
+      const endTime = marks[marks.length - 1]?.timestamp ?? startTime;
+      const totalMs = endTime - startTime;
+
+      const segments: ProfileSegment[] = [];
+      for (let i = 1; i < marks.length; i++) {
+        const from = marks[i - 1]!;
+        const to = marks[i]!;
+        const durationMs = to.timestamp - from.timestamp;
+        segments.push({
+          from: from.name,
+          to: to.name,
+          durationMs,
+          percentage: totalMs > 0 ? Math.round((durationMs / totalMs) * 100) : 0,
+        });
+      }
+
+      return {
+        requestId: id,
+        startTime,
+        endTime,
+        totalMs,
+        marks,
+        segments,
+      };
+    },
+
+    toLogString(): string {
+      const report = this.getReport();
+      const lines = [
+        `[profiler] ${report.requestId} total=${report.totalMs}ms`,
+        ...report.segments.map(
+          (s) => `  ${s.from} → ${s.to}: ${s.durationMs}ms (${s.percentage}%)`
+        ),
+      ];
+      return lines.join("\n");
+    },
+  };
+}
+
+/**
+ * Global profiling configuration
+ */
+export interface ProfilingConfig {
+  enabled: boolean;
+  logThresholdMs: number; // Only log if total exceeds this
+  includeInResponse: boolean; // Include timing in response metadata
+}
+
+const defaultConfig: ProfilingConfig = {
+  enabled: false,
+  logThresholdMs: 1000,
+  includeInResponse: false,
+};
+
+let globalConfig: ProfilingConfig = { ...defaultConfig };
+
+export function setProfilingConfig(config: Partial<ProfilingConfig>): void {
+  globalConfig = { ...globalConfig, ...config };
+}
+
+export function getProfilingConfig(): ProfilingConfig {
+  return { ...globalConfig };
+}
+
+export function isProfilingEnabled(): boolean {
+  return globalConfig.enabled;
+}