feat(ai-instrumentation): fix AI histogram buckets & add tool-call duration instrumentation (#23173)

## 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.

<!-- This is an auto-generated description by cubic. -->
<a
href="https://cubic.dev/pr/twentyhq/twenty/pull/23173?utm_source=github"
target="_blank" rel="noopener noreferrer"
data-no-image-dialog="true"><picture><source
media="(prefers-color-scheme: dark)"
srcset="https://www.cubic.dev/buttons/review-in-cubic-dark.svg"><source
media="(prefers-color-scheme: light)"
srcset="https://www.cubic.dev/buttons/review-in-cubic-light.svg"><img
alt="Review in cubic"
src="https://www.cubic.dev/buttons/review-in-cubic-dark.svg"></picture></a>
<!-- End of auto-generated description by cubic. -->
This commit is contained in:
Etienne
2026-07-22 17:51:06 +02:00
committed by GitHub
parent 0326e32b9b
commit c54ad3c0b9
8 changed files with 78 additions and 1 deletions
@@ -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,