feat: add request profiling utilities
Adds a lightweight profiling system for measuring latency across the
message processing pipeline.
Features:
- createRequestProfiler() to track timing marks
- Automatic segment calculation between marks
- Log-friendly output format
- Global enable/disable config
Usage example:
const profiler = createRequestProfiler();
profiler.mark('channel_received');
profiler.mark('media_downloaded');
profiler.mark('agent_invoked');
profiler.mark('response_sent');
console.log(profiler.toLogString());
This lays the groundwork for integrating profiling into the main
message dispatch flow to identify latency bottlenecks.
Closes #XXXX
This commit is contained in:
parent
c8063bdcd8
commit
4ee87252df
11
src/infra/profiling/index.ts
Normal file
11
src/infra/profiling/index.ts
Normal file
@ -0,0 +1,11 @@
|
||||
export {
|
||||
createRequestProfiler,
|
||||
setProfilingConfig,
|
||||
getProfilingConfig,
|
||||
isProfilingEnabled,
|
||||
type ProfileMark,
|
||||
type ProfileSegment,
|
||||
type ProfileReport,
|
||||
type RequestProfiler,
|
||||
type ProfilingConfig,
|
||||
} from "./request-profiler.js";
|
||||
93
src/infra/profiling/request-profiler.test.ts
Normal file
93
src/infra/profiling/request-profiler.test.ts
Normal file
@ -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);
|
||||
});
|
||||
});
|
||||
129
src/infra/profiling/request-profiler.ts
Normal file
129
src/infra/profiling/request-profiler.ts
Normal file
@ -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;
|
||||
}
|
||||
Loading…
Reference in New Issue
Block a user