From c54ad3c0b90df6fd29ad82c364c513bb27600b67 Mon Sep 17 00:00:00 2001 From: Etienne <45695613+etiennejouan@users.noreply.github.com> Date: Wed, 22 Jul 2026 17:51:06 +0200 Subject: [PATCH] feat(ai-instrumentation): fix AI histogram buckets & add tool-call duration instrumentation (#23173) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## What & why Two related observability fixes for AI chat / agent / MCP metrics. ### 1. Widen histogram buckets (`widden-ai-histo`) Latency percentiles for AI chat pinned at exactly **10s** on the dashboard — not because anything times out, but because the histogram buckets top out at 10,000. `recordHistogram` created histograms without explicit bucket boundaries, so the OTel SDK applied its defaults: `[0, 5, 10, 25, 50, 75, 100, 250, 500, 750, 1000, 2500, 5000, 7500, 10000]`. These were designed for small generic values; interpreted as **ms**, the last finite bucket is exactly 10s. Every observation above 10s falls into the `+Inf` overflow bucket, and quantile estimation clamps to the highest finite bound — so any percentile that lands in the overflow draws a flat line at 10s. Reality (gpt-5.5, last 30 days): 64% of turns exceed 10s (so even p50 pins at 10s), mean turn latency ~38s, max ~29min. The same 10k cap affects the token-unit `tool-output-tokens` histograms. **Changes:** - `recordHistogram` now accepts an optional `bucketBoundaries`, applied per-instrument via `advice.explicitBucketBoundaries` (supported in `@opentelemetry/api@1.9.1`). Colocated with the metric, no instrument-setup changes. - Added bucket-boundary constants: - `AI_LATENCY_MS_BUCKET_BOUNDARIES` — `[250, 500, 1000, 2500, 5000, 10000, 20000, 30000, 60000, 120000, 300000, 600000]` (250ms → 10min) - `TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES` — `[100, 250, 500, 1000, 2500, 5000, 10000, 25000, 50000, 100000, 250000, 500000]` (100 → 500k tokens) - Wired boundaries into `ai-chat/turn-latency-ms`, `ai-chat/step-latency-ms`, `ai-chat/ttft-ms` (latency) and `ai-chat/tool-output-tokens`, `workflow-agent/tool-output-tokens`, `mcp/tool-output-tokens` (tokens). ### 2. Instrument tool-call duration (`add-tool-duration-monitoring`) Previously we tracked tool success/failure counts and output tokens, but not how long each tool call took. Added a `*/tool-execution-duration-ms` histogram for each execution path. **Changes:** - New metric keys: `ai-chat/tool-execution-duration-ms`, `workflow-agent/tool-execution-duration-ms`, `mcp/tool-execution-duration-ms`. - New constant `TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES` — `[25, 50, 100, 250, 500, 1000, 2500, 5000, 10000, 30000, 60000, 120000]` (25ms → 2min). - **AI chat / agent node**: use the AI SDK's `experimental_onToolCallFinish` callback (`ai@6.0.97`), which reports an exact `durationMs` measured around the tool's `execute()`, plus `toolCall.toolName` and `success`. Attributes `{ model, tool }`. - **MCP**: measured directly around `tool.execute` with `performance.now()`, recorded on both success and failure paths. Attributes `{ tool }`. ## Notes - Backward-compatible: metrics without `bucketBoundaries` (e.g. `job/latency-ms`, `sdk-client-generation/duration-ms`) keep OTel defaults. - **Historical data stays clamped** — only writes after deploy use the new buckets, so percentile panels will show a step change at deploy time. For truth on existing data, use a mean panel (Sum/Count is exact) or Sentry trace span durations. - Provider-executed tools (e.g. native web search) run inside the provider, so they don't emit a local duration — same limitation as the existing tool counters. Review in cubic --- .../mcp/services/mcp-tool-executor.service.ts | 21 +++++++++++++++++++ ...i-latency-ms-bucket-boundaries.constant.ts | 4 ++++ ...-duration-ms-bucket-boundaries.constant.ts | 3 +++ ...utput-tokens-bucket-boundaries.constant.ts | 3 +++ .../core-modules/metrics/metrics.service.ts | 11 +++++++++- .../metrics/types/metrics-keys.type.ts | 3 +++ .../services/agent-async-executor.service.ts | 15 +++++++++++++ .../services/chat-execution.service.ts | 19 +++++++++++++++++ 8 files changed, 78 insertions(+), 1 deletion(-) create mode 100644 packages/twenty-server/src/engine/core-modules/metrics/constants/ai-latency-ms-bucket-boundaries.constant.ts create mode 100644 packages/twenty-server/src/engine/core-modules/metrics/constants/tool-execution-duration-ms-bucket-boundaries.constant.ts create mode 100644 packages/twenty-server/src/engine/core-modules/metrics/constants/tool-output-tokens-bucket-boundaries.constant.ts diff --git a/packages/twenty-server/src/engine/api/mcp/services/mcp-tool-executor.service.ts b/packages/twenty-server/src/engine/api/mcp/services/mcp-tool-executor.service.ts index 38b1cb416e..c8ac97bb4f 100644 --- a/packages/twenty-server/src/engine/api/mcp/services/mcp-tool-executor.service.ts +++ b/packages/twenty-server/src/engine/api/mcp/services/mcp-tool-executor.service.ts @@ -4,6 +4,8 @@ import { isNonEmptyString } from '@sniptt/guards'; import { type ToolSet } from 'ai'; import { isDefined } from 'twenty-shared/utils'; +import { TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES } from 'src/engine/core-modules/metrics/constants/tool-execution-duration-ms-bucket-boundaries.constant'; +import { TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES } from 'src/engine/core-modules/metrics/constants/tool-output-tokens-bucket-boundaries.constant'; import { MetricsService } from 'src/engine/core-modules/metrics/metrics.service'; import { MetricsKeys } from 'src/engine/core-modules/metrics/types/metrics-keys.type'; import { estimateToolOutputTokens } from 'src/engine/core-modules/tool-provider/utils/estimate-tool-output-tokens.util'; @@ -78,12 +80,22 @@ export class McpToolExecutorService { }), ); + const executionStartedAt = performance.now(); + try { const result = await tool.execute(params.arguments, { toolCallId: '1', messages: [], }); + this.metricsService.recordHistogram({ + key: MetricsKeys.McpToolExecutionDurationMs, + value: performance.now() - executionStartedAt, + unit: 'ms', + attributes: { tool: metricToolName }, + bucketBoundaries: TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES, + }); + const succeeded = isToolOutputSuccessful(result); this.metricsService.incrementCounterBy({ @@ -99,6 +111,7 @@ export class McpToolExecutorService { value: estimateToolOutputTokens(result), unit: 'token', attributes: { tool: metricToolName }, + bucketBoundaries: TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES, }); return wrapJsonRpcResponse(id, { @@ -108,6 +121,14 @@ export class McpToolExecutorService { }, }); } catch (executionError) { + this.metricsService.recordHistogram({ + key: MetricsKeys.McpToolExecutionDurationMs, + value: performance.now() - executionStartedAt, + unit: 'ms', + attributes: { tool: metricToolName }, + bucketBoundaries: TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES, + }); + this.metricsService.incrementCounterBy({ key: MetricsKeys.McpToolExecutionFailed, amount: 1, diff --git a/packages/twenty-server/src/engine/core-modules/metrics/constants/ai-latency-ms-bucket-boundaries.constant.ts b/packages/twenty-server/src/engine/core-modules/metrics/constants/ai-latency-ms-bucket-boundaries.constant.ts new file mode 100644 index 0000000000..7f41a260dc --- /dev/null +++ b/packages/twenty-server/src/engine/core-modules/metrics/constants/ai-latency-ms-bucket-boundaries.constant.ts @@ -0,0 +1,4 @@ +export const AI_LATENCY_MS_BUCKET_BOUNDARIES = [ + 250, 500, 1000, 2500, 5000, 10000, 20000, 30000, 60000, 120000, 300000, + 600000, +] as const; diff --git a/packages/twenty-server/src/engine/core-modules/metrics/constants/tool-execution-duration-ms-bucket-boundaries.constant.ts b/packages/twenty-server/src/engine/core-modules/metrics/constants/tool-execution-duration-ms-bucket-boundaries.constant.ts new file mode 100644 index 0000000000..86888cf212 --- /dev/null +++ b/packages/twenty-server/src/engine/core-modules/metrics/constants/tool-execution-duration-ms-bucket-boundaries.constant.ts @@ -0,0 +1,3 @@ +export const TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES = [ + 25, 50, 100, 250, 500, 1000, 2500, 5000, 10000, 30000, 60000, 120000, +] as const; diff --git a/packages/twenty-server/src/engine/core-modules/metrics/constants/tool-output-tokens-bucket-boundaries.constant.ts b/packages/twenty-server/src/engine/core-modules/metrics/constants/tool-output-tokens-bucket-boundaries.constant.ts new file mode 100644 index 0000000000..8972d2e6cd --- /dev/null +++ b/packages/twenty-server/src/engine/core-modules/metrics/constants/tool-output-tokens-bucket-boundaries.constant.ts @@ -0,0 +1,3 @@ +export const TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES = [ + 100, 250, 500, 1000, 2500, 5000, 10000, 25000, 50000, 100000, 250000, 500000, +] as const; diff --git a/packages/twenty-server/src/engine/core-modules/metrics/metrics.service.ts b/packages/twenty-server/src/engine/core-modules/metrics/metrics.service.ts index 4d6a538ded..d265a412c1 100644 --- a/packages/twenty-server/src/engine/core-modules/metrics/metrics.service.ts +++ b/packages/twenty-server/src/engine/core-modules/metrics/metrics.service.ts @@ -229,13 +229,22 @@ export class MetricsService { value, unit, attributes, + bucketBoundaries, }: { key: MetricsKeys; value: number; unit?: string; attributes?: Attributes; + bucketBoundaries?: readonly number[]; }): void { - this.getMeter().createHistogram(key, { unit }).record(value, attributes); + this.getMeter() + .createHistogram(key, { + unit, + ...(isDefined(bucketBoundaries) && { + advice: { explicitBucketBoundaries: [...bucketBoundaries] }, + }), + }) + .record(value, attributes); } async groupMetrics( diff --git a/packages/twenty-server/src/engine/core-modules/metrics/types/metrics-keys.type.ts b/packages/twenty-server/src/engine/core-modules/metrics/types/metrics-keys.type.ts index 7b7e9fdda2..2cc220098c 100644 --- a/packages/twenty-server/src/engine/core-modules/metrics/types/metrics-keys.type.ts +++ b/packages/twenty-server/src/engine/core-modules/metrics/types/metrics-keys.type.ts @@ -27,10 +27,13 @@ export enum MetricsKeys { WorkflowRunStuckRunningFalsePositive = 'workflow-run/stuck-running/false-positive', AiChatToolExecutionSucceeded = 'ai-chat/tool-execution-succeeded', AiChatToolExecutionFailed = 'ai-chat/tool-execution-failed', + AiChatToolExecutionDurationMs = 'ai-chat/tool-execution-duration-ms', WorkflowAgentToolExecutionSucceeded = 'workflow-agent/tool-execution-succeeded', WorkflowAgentToolExecutionFailed = 'workflow-agent/tool-execution-failed', + WorkflowAgentToolExecutionDurationMs = 'workflow-agent/tool-execution-duration-ms', McpToolExecutionSucceeded = 'mcp/tool-execution-succeeded', McpToolExecutionFailed = 'mcp/tool-execution-failed', + McpToolExecutionDurationMs = 'mcp/tool-execution-duration-ms', AiChatToolOutputTokens = 'ai-chat/tool-output-tokens', WorkflowAgentToolOutputTokens = 'workflow-agent/tool-output-tokens', McpToolOutputTokens = 'mcp/tool-output-tokens', diff --git a/packages/twenty-server/src/engine/metadata-modules/ai/ai-agent-execution/services/agent-async-executor.service.ts b/packages/twenty-server/src/engine/metadata-modules/ai/ai-agent-execution/services/agent-async-executor.service.ts index 3035db0500..32e07bca0d 100644 --- a/packages/twenty-server/src/engine/metadata-modules/ai/ai-agent-execution/services/agent-async-executor.service.ts +++ b/packages/twenty-server/src/engine/metadata-modules/ai/ai-agent-execution/services/agent-async-executor.service.ts @@ -18,6 +18,8 @@ import { type Repository } from 'typeorm'; import { isUserAuthContext } from 'src/engine/core-modules/auth/guards/is-user-auth-context.guard'; import { type WorkspaceAuthContext } from 'src/engine/core-modules/auth/types/workspace-auth-context.type'; import { BillingUsageService } from 'src/engine/core-modules/billing/services/billing-usage.service'; +import { TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES } from 'src/engine/core-modules/metrics/constants/tool-execution-duration-ms-bucket-boundaries.constant'; +import { TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES } from 'src/engine/core-modules/metrics/constants/tool-output-tokens-bucket-boundaries.constant'; import { MetricsService } from 'src/engine/core-modules/metrics/metrics.service'; import { MetricsKeys } from 'src/engine/core-modules/metrics/types/metrics-keys.type'; import { type ToolProviderContext } from 'src/engine/core-modules/tool-provider/interfaces/tool-provider-context.type'; @@ -237,6 +239,18 @@ export class AgentAsyncExecutorService { hasNoMoreAvailableCredits, providerOptions, experimental_telemetry: AI_TELEMETRY_CONFIG, + experimental_onToolCallFinish: (event) => { + this.metricsService.recordHistogram({ + key: MetricsKeys.WorkflowAgentToolExecutionDurationMs, + value: event.durationMs, + unit: 'ms', + attributes: { + model: registeredModel.modelId, + tool: getToolMetricName(event.toolCall.toolName), + }, + bucketBoundaries: TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES, + }); + }, onStepFinish: async (step) => { const { hasNoMoreAvailableCredits: stepHasNoMoreAvailableCredits } = await this.aiBillingService.decrementAndCheckAvailableCredits( @@ -283,6 +297,7 @@ export class AgentAsyncExecutorService { ), unit: 'token', attributes: toolAttributes, + bucketBoundaries: TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES, }); } }, diff --git a/packages/twenty-server/src/engine/metadata-modules/ai/ai-chat/services/chat-execution.service.ts b/packages/twenty-server/src/engine/metadata-modules/ai/ai-chat/services/chat-execution.service.ts index 4ddc781bb3..951fb74905 100644 --- a/packages/twenty-server/src/engine/metadata-modules/ai/ai-chat/services/chat-execution.service.ts +++ b/packages/twenty-server/src/engine/metadata-modules/ai/ai-chat/services/chat-execution.service.ts @@ -15,6 +15,9 @@ import { type APP_LOCALES } from 'twenty-shared/translations'; import { AppPath } from 'twenty-shared/types'; import { getAppPath, isDefined } from 'twenty-shared/utils'; +import { AI_LATENCY_MS_BUCKET_BOUNDARIES } from 'src/engine/core-modules/metrics/constants/ai-latency-ms-bucket-boundaries.constant'; +import { TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES } from 'src/engine/core-modules/metrics/constants/tool-execution-duration-ms-bucket-boundaries.constant'; +import { TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES } from 'src/engine/core-modules/metrics/constants/tool-output-tokens-bucket-boundaries.constant'; import { MetricsService } from 'src/engine/core-modules/metrics/metrics.service'; import { MetricsKeys } from 'src/engine/core-modules/metrics/types/metrics-keys.type'; import { UsageOperationType } from 'src/engine/core-modules/usage/enums/usage-operation-type.enum'; @@ -430,6 +433,7 @@ export class ChatExecutionService { value: performance.now() - streamStartedAt, unit: 'ms', attributes: modelAttr, + bucketBoundaries: AI_LATENCY_MS_BUCKET_BOUNDARIES, }); }; @@ -475,15 +479,29 @@ export class ChatExecutionService { value: performance.now() - streamStartedAt, unit: 'ms', attributes: { model: registeredModel.modelId }, + bucketBoundaries: AI_LATENCY_MS_BUCKET_BOUNDARIES, }); } }, + experimental_onToolCallFinish: (event) => { + this.metricsService.recordHistogram({ + key: MetricsKeys.AiChatToolExecutionDurationMs, + value: event.durationMs, + unit: 'ms', + attributes: { + model: registeredModel.modelId, + tool: getToolMetricName(event.toolCall.toolName), + }, + bucketBoundaries: TOOL_EXECUTION_DURATION_MS_BUCKET_BOUNDARIES, + }); + }, onStepFinish: async (step) => { this.metricsService.recordHistogram({ key: MetricsKeys.AiChatStepLatencyMs, value: performance.now() - stepStartedAt, unit: 'ms', attributes: { model: registeredModel.modelId }, + bucketBoundaries: AI_LATENCY_MS_BUCKET_BOUNDARIES, }); const { hasNoMoreAvailableCredits: stepHasNoMoreAvailableCredits } = @@ -544,6 +562,7 @@ export class ChatExecutionService { value: outputTokens, unit: 'token', attributes: executionAttributes, + bucketBoundaries: TOOL_OUTPUT_TOKENS_BUCKET_BOUNDARIES, }); } },