diff --git a/src/infra/profiling/index.ts b/src/infra/profiling/index.ts new file mode 100644 index 000000000..cb124edb3 --- /dev/null +++ b/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"; diff --git a/src/infra/profiling/request-profiler.test.ts b/src/infra/profiling/request-profiler.test.ts new file mode 100644 index 000000000..740609a68 --- /dev/null +++ b/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); + }); +}); diff --git a/src/infra/profiling/request-profiler.ts b/src/infra/profiling/request-profiler.ts new file mode 100644 index 000000000..01eeeeea4 --- /dev/null +++ b/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): void { + globalConfig = { ...globalConfig, ...config }; +} + +export function getProfilingConfig(): ProfilingConfig { + return { ...globalConfig }; +} + +export function isProfilingEnabled(): boolean { + return globalConfig.enabled; +}