From 8a7ad67024ada15639e45661c706ab691944c95f Mon Sep 17 00:00:00 2001 From: Karl Power Date: Tue, 11 Aug 2026 11:09:46 +0100 Subject: [PATCH] feat(mcp): improve metric discovery, add quiet-saturation eval scenario --- .changeset/fair-walls-listen.md | 6 + .../api/src/mcp/__tests__/sources.int.test.ts | 103 ++ .../src/mcp/tools/sources/describeSource.ts | 186 +--- .../api/src/mcp/tools/sources/listSources.ts | 214 +++- .../api/src/mcp/tools/sources/metricNames.ts | 230 +++++ .../hdx-eval/src/__tests__/markdown.test.ts | 26 +- .../src/__tests__/programmatic.test.ts | 148 +++ .../src/__tests__/quiet-saturation.test.ts | 309 ++++++ packages/hdx-eval/src/grading/programmatic.ts | 14 +- packages/hdx-eval/src/grading/rubric.ts | 23 +- packages/hdx-eval/src/grading/types.ts | 15 +- packages/hdx-eval/src/reports/aggregate.ts | 21 +- packages/hdx-eval/src/reports/markdown.ts | 10 +- packages/hdx-eval/src/scenarios/index.ts | 2 + .../scenarios/quiet-saturation/generate.ts | 976 ++++++++++++++++++ .../quiet-saturation/ground-truth.json | 194 ++++ 16 files changed, 2281 insertions(+), 196 deletions(-) create mode 100644 .changeset/fair-walls-listen.md create mode 100644 packages/api/src/mcp/tools/sources/metricNames.ts create mode 100644 packages/hdx-eval/src/__tests__/quiet-saturation.test.ts create mode 100644 packages/hdx-eval/src/scenarios/quiet-saturation/generate.ts create mode 100644 packages/hdx-eval/src/scenarios/quiet-saturation/ground-truth.json diff --git a/.changeset/fair-walls-listen.md b/.changeset/fair-walls-listen.md new file mode 100644 index 0000000000..6684aefac0 --- /dev/null +++ b/.changeset/fair-walls-listen.md @@ -0,0 +1,6 @@ +--- +"@hyperdx/hdx-eval": patch +"@hyperdx/api": patch +--- + +feat(mcp): improve metric discovery, add quiet-saturation eval scenario diff --git a/packages/api/src/mcp/__tests__/sources.int.test.ts b/packages/api/src/mcp/__tests__/sources.int.test.ts index 4a442bd9eb..affe49d1e2 100644 --- a/packages/api/src/mcp/__tests__/sources.int.test.ts +++ b/packages/api/src/mcp/__tests__/sources.int.test.ts @@ -188,6 +188,109 @@ describe('MCP Source Tools', () => { await client2.close(); }); + + describe('metric-name previews', () => { + const createMetricSource = (name = 'Metrics') => + Source.create({ + kind: SourceKind.Metric, + team: team._id, + from: { databaseName: DEFAULT_DATABASE, tableName: '' }, + metricTables: { + [MetricsDataType.Gauge.toLowerCase()]: 'otel_metrics_gauge', + [MetricsDataType.Sum.toLowerCase()]: 'otel_metrics_sum', + }, + timestampValueExpression: 'TimeUnix', + connection: connection._id, + name, + }); + + it('includes metricNamesPreview and metricsUsage for metric sources with recent data', async () => { + const metricSource = await createMetricSource(); + const now = new Date(); + await bulkInsertMetricsGauge([ + { + MetricName: 'system.cpu.utilization', + ResourceAttributes: { 'service.name': 'svc-a' }, + ServiceName: 'svc-a', + TimeUnix: now, + Value: 0.42, + }, + ]); + await bulkInsertMetricsSum([ + { + MetricName: 'http.server.request.count', + AggregationTemporality: 1, + IsMonotonic: true, + ResourceAttributes: { 'service.name': 'svc-a' }, + ServiceName: 'svc-a', + TimeUnix: now, + Value: 100, + }, + ]); + + const result = await callTool(client, 'clickstack_list_sources'); + expect(result.isError).toBeFalsy(); + const output = JSON.parse(getFirstText(result)); + + const metric = output.sources.find( + (s: any) => s.id === metricSource._id.toString(), + ); + expect(metric).toBeDefined(); + expect(metric.metricNamesPreview).toBeDefined(); + expect(metric.metricNamesPreview.gauge).toEqual( + expect.arrayContaining(['system.cpu.utilization']), + ); + expect(metric.metricNamesPreview.sum).toEqual( + expect.arrayContaining(['http.server.request.count']), + ); + + // Top-level usage note explains direct metric querying. + expect(output.metricsUsage).toContain('metricType + metricName'); + }); + + it('falls back to a wider lookback when no metrics reported in the last 24h', async () => { + const metricSource = await createMetricSource('Sparse Metrics'); + const threeDaysAgo = new Date(Date.now() - 3 * 24 * 60 * 60 * 1000); + await bulkInsertMetricsGauge([ + { + MetricName: 'batch.job.duration', + ResourceAttributes: { 'service.name': 'batch-svc' }, + ServiceName: 'batch-svc', + TimeUnix: threeDaysAgo, + Value: 60, + }, + ]); + + const result = await callTool(client, 'clickstack_list_sources'); + expect(result.isError).toBeFalsy(); + const output = JSON.parse(getFirstText(result)); + + const metric = output.sources.find( + (s: any) => s.id === metricSource._id.toString(), + ); + expect(metric).toBeDefined(); + expect(metric.metricNamesPreview?.gauge).toEqual( + expect.arrayContaining(['batch.job.duration']), + ); + }); + + it('omits metricNamesPreview when the metric tables are empty', async () => { + const metricSource = await createMetricSource('Empty Metrics'); + + const result = await callTool(client, 'clickstack_list_sources'); + expect(result.isError).toBeFalsy(); + const output = JSON.parse(getFirstText(result)); + + const metric = output.sources.find( + (s: any) => s.id === metricSource._id.toString(), + ); + expect(metric).toBeDefined(); + expect(metric.metricTables).toBeDefined(); + expect(metric.metricNamesPreview).toBeUndefined(); + // The usage note still appears — a metric source exists. + expect(output.metricsUsage).toBeDefined(); + }); + }); }); // ── clickstack_describe_source ─────────────────────────────────────────────── diff --git a/packages/api/src/mcp/tools/sources/describeSource.ts b/packages/api/src/mcp/tools/sources/describeSource.ts index 9d97029424..efd0aa2027 100644 --- a/packages/api/src/mcp/tools/sources/describeSource.ts +++ b/packages/api/src/mcp/tools/sources/describeSource.ts @@ -1,10 +1,7 @@ import { - chSql, - concatChSql, convertCHDataTypeToJSType, filterColumnMetaByType, JSDataType, - tableExpr, } from '@hyperdx/common-utils/dist/clickhouse'; import { ClickhouseClient } from '@hyperdx/common-utils/dist/clickhouse/node'; import { getMetadata } from '@hyperdx/common-utils/dist/core/metadata'; @@ -25,6 +22,10 @@ import { type QueryableMetricKind, sanitizeMetricTables, } from './metricKinds'; +import { + type MetricNameSample, + sampleMetricNamesWithLookback, +} from './metricNames'; import { extractSourceConfig } from './schemas'; // How far back to look when querying the rollup tables for value samples. @@ -38,10 +39,6 @@ const MAX_LC_VALUES = 20; const MAX_MAP_KEY_VALUES = 5; const MAX_MAP_KEYS_TO_SAMPLE = 10; -// Max MetricName values returned per metric kind by the starter sample. -// clickstack_list_metrics provides paginated discovery beyond this cap. -const MAX_METRIC_NAMES_PER_KIND = 20; - /** * Pick the representative metric table to use as the starting point for * schema/attribute discovery on a metric source. Prefers gauge → sum → @@ -61,177 +58,6 @@ function pickRepresentativeMetricTable( return undefined; } -type MetricNameSample = { - name: string; - unit?: string; - description?: string; -}; - -/** - * Sample distinct MetricName values for a single metric kind. Optionally - * enriches each name with MetricUnit / MetricDescription when those - * columns are present on the table (the OTel Collector default schema - * includes them; custom schemas may not). - */ -async function sampleMetricNamesForKind({ - metadata, - clickhouseClient, - databaseName, - tableName, - connectionId, - dateRange, - timestampValueExpression, - signal, - cachedColumns, -}: { - metadata: ReturnType; - clickhouseClient: ClickhouseClient; - databaseName: string; - tableName: string; - connectionId: string; - dateRange: [Date, Date]; - timestampValueExpression: string; - signal: AbortSignal; - cachedColumns?: { name: string }[]; -}): Promise { - // Defensive column presence check for MetricUnit / MetricDescription. - const kindColumns = - cachedColumns ?? - (await metadata.getColumns({ databaseName, tableName, connectionId })); - const columnNames = new Set(kindColumns.map(c => c.name)); - const hasUnit = columnNames.has('MetricUnit'); - const hasDescription = columnNames.has('MetricDescription'); - - // First fetch the distinct metric names; this is the only step that - // strictly needs to succeed for the kind to appear in the response. - // Pass timestampValueExpression so the no-rollup fallback path scopes - // its scan to dateRange instead of going unbounded against the raw - // metric table on cold cache. - const nameResults = await metadata.getAllKeyValues({ - databaseName, - tableName, - keyExpressions: ['MetricName'], - maxValuesPerKey: MAX_METRIC_NAMES_PER_KIND, - connectionId, - dateRange, - timestampValueExpression, - signal, - }); - const names = nameResults[0]?.value.map(v => v.toString()) ?? []; - if (names.length === 0) return []; - - // Best-effort enrichment with unit + description. One small query - // returns one row per metric name with the most-recent unit / desc. - let enrichments: Record = {}; - if ((hasUnit || hasDescription) && !signal.aborted) { - try { - enrichments = await fetchMetricNameEnrichments({ - clickhouseClient, - databaseName, - tableName, - connectionId, - names, - dateRange, - hasUnit, - hasDescription, - signal, - }); - } catch (e) { - logger.warn( - { databaseName, tableName, error: e }, - 'Failed to enrich metric names with unit/description', - ); - } - } - - return names.map(name => { - const enrichment = enrichments[name] ?? {}; - const sample: MetricNameSample = { name }; - if (enrichment.unit) sample.unit = enrichment.unit; - if (enrichment.description) sample.description = enrichment.description; - return sample; - }); -} - -/** - * Fetch MetricUnit and MetricDescription for a batch of metric names. - * Uses `anyLast` so the most-recent value wins when a metric has changed - * unit/description over time. - */ -async function fetchMetricNameEnrichments({ - clickhouseClient, - databaseName, - tableName, - connectionId, - names, - dateRange, - hasUnit, - hasDescription, - signal, -}: { - clickhouseClient: ClickhouseClient; - databaseName: string; - tableName: string; - connectionId: string; - names: string[]; - dateRange: [Date, Date]; - hasUnit: boolean; - hasDescription: boolean; - signal: AbortSignal; -}): Promise> { - // Build the projection fragments via the parameterised chSql DSL so - // identifiers are quoted and the unit/description columns only appear - // when present on the source table. - const projections = [ - chSql`MetricName`, - ...(hasUnit - ? [chSql`anyLast(${{ Identifier: 'MetricUnit' }}) AS MetricUnit`] - : []), - ...(hasDescription - ? [ - chSql`anyLast(${{ Identifier: 'MetricDescription' }}) AS MetricDescription`, - ] - : []), - ]; - const namePlaceholders = concatChSql( - ',', - names.map(name => chSql`${{ String: name }}`), - ); - const sql = chSql` - SELECT ${concatChSql(', ', projections)} - FROM ${tableExpr({ database: databaseName, table: tableName })} - WHERE MetricName IN (${namePlaceholders}) - AND TimeUnix >= fromUnixTimestamp64Milli(${{ Int64: dateRange[0].getTime() }}) - AND TimeUnix <= fromUnixTimestamp64Milli(${{ Int64: dateRange[1].getTime() }}) - GROUP BY MetricName - `; - - type EnrichmentRow = { - MetricName: string; - MetricUnit?: string; - MetricDescription?: string; - }; - - const response = await clickhouseClient.query<'JSON'>({ - query: sql.sql, - query_params: sql.params, - format: 'JSON', - connectionId, - abort_signal: signal, - }); - const result = (await response.json()) as { data: EnrichmentRow[] }; - - const enrichments: Record = - {}; - for (const row of result.data) { - enrichments[row.MetricName] = { - ...(row.MetricUnit ? { unit: row.MetricUnit } : {}), - ...(row.MetricDescription ? { description: row.MetricDescription } : {}), - }; - } - return enrichments; -} - /** * Core schema-discovery logic. Extracted so the caller can wrap it in * Promise.race for wall-clock timeout enforcement. @@ -535,13 +361,13 @@ async function describeSourceSchema( const kindTableName = source.metricTables[kind]; if (!kindTableName) return; try { - const samples = await sampleMetricNamesForKind({ + const samples = await sampleMetricNamesWithLookback({ metadata, clickhouseClient, databaseName, tableName: kindTableName, connectionId, - dateRange, + now, timestampValueExpression, signal, // Reuse representative columns when the kind matches the diff --git a/packages/api/src/mcp/tools/sources/listSources.ts b/packages/api/src/mcp/tools/sources/listSources.ts index d4dcabeccc..2ba02d091b 100644 --- a/packages/api/src/mcp/tools/sources/listSources.ts +++ b/packages/api/src/mcp/tools/sources/listSources.ts @@ -1,11 +1,175 @@ +import { ClickhouseClient } from '@hyperdx/common-utils/dist/clickhouse/node'; +import { getMetadata } from '@hyperdx/common-utils/dist/core/metadata'; import { SourceKind } from '@hyperdx/common-utils/dist/types'; import { z } from 'zod'; -import { getConnectionsByTeam } from '@/controllers/connection'; +import { + getConnectionById, + getConnectionsByTeam, +} from '@/controllers/connection'; import { getSources } from '@/controllers/sources'; import type { ToolRegistrar } from '@/mcp/tools/types'; +import logger from '@/utils/logger'; import { sanitizeMetricTables } from './metricKinds'; +import { sampleMetricNamesWithLookback } from './metricNames'; + +// Wall-clock budget for the best-effort metric-name preview sampling. +// list_sources is usually the agent's first call — it must stay snappy, +// so sampling that doesn't finish in time is simply omitted. +const METRIC_PREVIEW_TIMEOUT_MS = 3_000; + +// Max metric names shown per kind in the lightweight catalog preview. +// clickstack_describe_source / clickstack_list_metrics list more. +const MAX_PREVIEW_NAMES_PER_KIND = 10; + +// Max concurrent ClickHouse sampling queries during preview collection. +const PREVIEW_CONCURRENCY = 6; + +/** Run tasks through a small worker pool, stopping early on abort. */ +async function runWithConcurrency( + tasks: Array<() => Promise>, + limit: number, + signal: AbortSignal, +): Promise { + let next = 0; + const workers = Array.from( + { length: Math.min(limit, tasks.length) }, + async () => { + while (next < tasks.length && !signal.aborted) { + const task = tasks[next++]; + try { + await task(); + } catch { + // Best-effort: individual sampling failures never fail the call. + } + } + }, + ); + await Promise.all(workers); +} + +/** + * Best-effort: attach a `metricNamesPreview` (kind → recently-reported + * metric names) to each metric-source summary so the agent can query + * metrics directly from the catalog — without spending discovery calls + * on describe_source / list_metrics just to learn what exists. + * + * Sampling runs under a hard wall-clock budget; whatever finished in + * time is attached, the rest is silently omitted (the summary still + * carries metricTables + the discovery nextSteps). + */ +async function attachMetricNamePreviews({ + teamId, + entries, +}: { + teamId: string; + entries: Array<{ + summary: Record; + databaseName: string; + connectionId: string; + timestampValueExpression: string; + metricTables: Record; + }>; +}): Promise { + if (entries.length === 0) return; + + // Resolve credentials once per distinct connection. + const connectionIds = [...new Set(entries.map(e => e.connectionId))]; + const clients = new Map< + string, + { + clickhouseClient: ClickhouseClient; + metadata: ReturnType; + } + >(); + await Promise.all( + connectionIds.map(async connectionId => { + const connection = await getConnectionById(teamId, connectionId, true); + if (!connection) return; + const clickhouseClient = new ClickhouseClient({ + host: connection.host, + username: connection.username, + password: connection.password, + }); + clients.set(connectionId, { + clickhouseClient, + metadata: getMetadata(clickhouseClient), + }); + }), + ); + + const controller = new AbortController(); + const timeoutId = setTimeout( + () => controller.abort(), + METRIC_PREVIEW_TIMEOUT_MS, + ); + + const now = new Date(); + // Multiple sources can point at the same physical table (e.g. cloned + // source configs) — dedupe the sampling per (connection, db, table, + // timestamp expression); the sampling query depends on all four. + const tableSampleCache = new Map>(); + const previews = new Map, Map>(); + + const tasks: Array<() => Promise> = []; + for (const entry of entries) { + const client = clients.get(entry.connectionId); + if (!client) continue; + for (const [kind, tableName] of Object.entries(entry.metricTables)) { + tasks.push(async () => { + const cacheKey = `${entry.connectionId}|${entry.databaseName}|${tableName}|${entry.timestampValueExpression}`; + let namesPromise = tableSampleCache.get(cacheKey); + if (!namesPromise) { + namesPromise = sampleMetricNamesWithLookback({ + metadata: client.metadata, + clickhouseClient: client.clickhouseClient, + databaseName: entry.databaseName, + tableName, + connectionId: entry.connectionId, + now, + timestampValueExpression: entry.timestampValueExpression, + signal: controller.signal, + maxNames: MAX_PREVIEW_NAMES_PER_KIND, + enrich: false, + }).then(samples => samples.map(s => s.name)); + tableSampleCache.set(cacheKey, namesPromise); + } + const names = await namesPromise; + if (names.length === 0) return; + let preview = previews.get(entry.summary); + if (!preview) { + preview = new Map(); + previews.set(entry.summary, preview); + } + preview.set(kind, names); + }); + } + } + + const abortedPromise = new Promise(resolve => { + controller.signal.addEventListener('abort', () => resolve(), { + once: true, + }); + }); + + try { + // Race the pool against the abort so a ClickHouse call that ignores + // the signal cannot hold list_sources past its budget. + await Promise.race([ + runWithConcurrency(tasks, PREVIEW_CONCURRENCY, controller.signal), + abortedPromise, + ]); + } finally { + clearTimeout(timeoutId); + } + + for (const [summary, preview] of previews) { + if (preview.size > 0) { + summary.metricNamesPreview = Object.fromEntries(preview); + } + } +} export function registerListSources({ context, @@ -20,7 +184,9 @@ export function registerListSources({ annotations: { readOnlyHint: true }, description: 'List all data sources (logs, metrics, traces) and database connections available to this team. ' + - 'Returns source IDs, names, kinds, and connection IDs as a lightweight catalog.\n\n' + + 'Returns source IDs, names, kinds, and connection IDs as a lightweight catalog. ' + + 'Metric sources additionally include metricNamesPreview — a sample of recently-reported ' + + 'metric names per kind — so metrics can be queried immediately.\n\n' + 'NEXT STEP: After identifying the source(s) you need, call clickstack_describe_source with the ' + 'sourceId to get the full column schema, attribute keys, and sampled values. ' + 'This two-step approach avoids fetching expensive schema details for sources you do not need.\n\n' + @@ -37,6 +203,14 @@ export function registerListSources({ getConnectionsByTeam(teamId.toString()), ]); + const metricPreviewEntries: Array<{ + summary: Record; + databaseName: string; + connectionId: string; + timestampValueExpression: string; + metricTables: Record; + }> = []; + const sourceSummaries = sources.map(s => { const meta: Record = { id: s._id.toString(), @@ -84,18 +258,52 @@ export function registerListSources({ const tables = sanitizeMetricTables( s.metricTables as Record | undefined, ); - if (tables) meta.metricTables = tables; + if (tables) { + meta.metricTables = tables; + metricPreviewEntries.push({ + summary: meta, + databaseName: s.from.databaseName, + connectionId: s.connection.toString(), + timestampValueExpression: s.timestampValueExpression, + metricTables: tables, + }); + } } return meta; }); + // Best-effort: never let preview sampling fail or stall the catalog. + try { + await attachMetricNamePreviews({ + teamId: teamId.toString(), + entries: metricPreviewEntries, + }); + } catch (e) { + logger.warn( + { teamId, error: e }, + 'Failed to attach metric-name previews to list_sources', + ); + } + const output = { sources: sourceSummaries, connections: connections.map(c => ({ id: c._id.toString(), name: c.name, })), + ...(metricPreviewEntries.length > 0 + ? { + metricsUsage: + 'Metric sources are queried with the same clickstack_timeseries / clickstack_table ' + + 'tools — set metricType + metricName on each select item (no describe call needed ' + + `first). metricNamesPreview shows up to ${MAX_PREVIEW_NAMES_PER_KIND} recently-reported ` + + 'metric names per kind; clickstack_describe_source or clickstack_list_metrics list the ' + + 'full catalog. During investigations, metrics corroborate incident onset timing, ' + + 'quantify impact (request/error counters), and rule resource saturation in or out ' + + '(cpu/memory gauges).', + } + : {}), nextStep: 'Call clickstack_describe_source with a sourceId above to get the full column schema, ' + 'attribute keys, and sampled low-cardinality values before writing queries. ' + diff --git a/packages/api/src/mcp/tools/sources/metricNames.ts b/packages/api/src/mcp/tools/sources/metricNames.ts new file mode 100644 index 0000000000..19802b6c15 --- /dev/null +++ b/packages/api/src/mcp/tools/sources/metricNames.ts @@ -0,0 +1,230 @@ +import { + chSql, + concatChSql, + tableExpr, +} from '@hyperdx/common-utils/dist/clickhouse'; +import { ClickhouseClient } from '@hyperdx/common-utils/dist/clickhouse/node'; +import { getMetadata } from '@hyperdx/common-utils/dist/core/metadata'; + +import logger from '@/utils/logger'; + +// Max MetricName values returned per metric kind by the starter sample. +// clickstack_list_metrics provides paginated discovery beyond this cap. +const MAX_METRIC_NAMES_PER_KIND = 20; + +/** + * Lookback windows tried in order when sampling metric names. The first + * window that yields any names wins. Metrics reported sparsely (batch + * jobs, low-traffic services) or backfilled historical data may have no + * points in the last 24h — falling back to a wider window keeps the + * sample useful instead of silently empty. + */ +const METRIC_NAME_LOOKBACK_WINDOWS_MS: readonly number[] = [ + 24 * 60 * 60 * 1000, // 24 hours + 30 * 24 * 60 * 60 * 1000, // 30 days +]; + +export type MetricNameSample = { + name: string; + unit?: string; + description?: string; +}; + +/** + * Sample distinct MetricName values for a single metric kind. Optionally + * enriches each name with MetricUnit / MetricDescription when those + * columns are present on the table (the OTel Collector default schema + * includes them; custom schemas may not). + */ +export async function sampleMetricNamesForKind({ + metadata, + clickhouseClient, + databaseName, + tableName, + connectionId, + dateRange, + timestampValueExpression, + signal, + cachedColumns, + maxNames = MAX_METRIC_NAMES_PER_KIND, + enrich = true, +}: { + metadata: ReturnType; + clickhouseClient: ClickhouseClient; + databaseName: string; + tableName: string; + connectionId: string; + dateRange: [Date, Date]; + timestampValueExpression: string; + signal: AbortSignal; + cachedColumns?: { name: string }[]; + maxNames?: number; + enrich?: boolean; +}): Promise { + // First fetch the distinct metric names; this is the only step that + // strictly needs to succeed for the kind to appear in the response. + // Pass timestampValueExpression so the no-rollup fallback path scopes + // its scan to dateRange instead of going unbounded against the raw + // metric table on cold cache. + const nameResults = await metadata.getAllKeyValues({ + databaseName, + tableName, + keyExpressions: ['MetricName'], + maxValuesPerKey: maxNames, + connectionId, + dateRange, + timestampValueExpression, + signal, + }); + const names = nameResults[0]?.value.map(v => v.toString()) ?? []; + if (names.length === 0) return []; + + if (!enrich) { + return names.map(name => ({ name })); + } + + // Defensive column presence check for MetricUnit / MetricDescription. + const kindColumns = + cachedColumns ?? + (await metadata.getColumns({ databaseName, tableName, connectionId })); + const columnNames = new Set(kindColumns.map(c => c.name)); + const hasUnit = columnNames.has('MetricUnit'); + const hasDescription = columnNames.has('MetricDescription'); + + // Best-effort enrichment with unit + description. One small query + // returns one row per metric name with the most-recent unit / desc. + let enrichments = new Map(); + if ((hasUnit || hasDescription) && !signal.aborted) { + try { + enrichments = await fetchMetricNameEnrichments({ + clickhouseClient, + databaseName, + tableName, + connectionId, + names, + dateRange, + hasUnit, + hasDescription, + signal, + }); + } catch (e) { + logger.warn( + { databaseName, tableName, error: e }, + 'Failed to enrich metric names with unit/description', + ); + } + } + + return names.map(name => { + const enrichment = enrichments.get(name) ?? {}; + const sample: MetricNameSample = { name }; + if (enrichment.unit) sample.unit = enrichment.unit; + if (enrichment.description) sample.description = enrichment.description; + return sample; + }); +} + +/** + * Sample metric names for a kind, widening the lookback window until a + * non-empty sample is found (see METRIC_NAME_LOOKBACK_WINDOWS_MS). + * Returns the first non-empty sample, or [] when every window is empty. + */ +export async function sampleMetricNamesWithLookback({ + now = new Date(), + windowsMs = METRIC_NAME_LOOKBACK_WINDOWS_MS, + ...rest +}: Omit[0], 'dateRange'> & { + now?: Date; + windowsMs?: readonly number[]; +}): Promise { + for (const windowMs of windowsMs) { + if (rest.signal.aborted) break; + const samples = await sampleMetricNamesForKind({ + ...rest, + dateRange: [new Date(now.getTime() - windowMs), now], + }); + if (samples.length > 0) return samples; + } + return []; +} + +/** + * Fetch MetricUnit and MetricDescription for a batch of metric names. + * Uses `anyLast` so the most-recent value wins when a metric has changed + * unit/description over time. + */ +async function fetchMetricNameEnrichments({ + clickhouseClient, + databaseName, + tableName, + connectionId, + names, + dateRange, + hasUnit, + hasDescription, + signal, +}: { + clickhouseClient: ClickhouseClient; + databaseName: string; + tableName: string; + connectionId: string; + names: string[]; + dateRange: [Date, Date]; + hasUnit: boolean; + hasDescription: boolean; + signal: AbortSignal; +}): Promise> { + // Build the projection fragments via the parameterised chSql DSL so + // identifiers are quoted and the unit/description columns only appear + // when present on the source table. + const projections = [ + chSql`MetricName`, + ...(hasUnit + ? [chSql`anyLast(${{ Identifier: 'MetricUnit' }}) AS MetricUnit`] + : []), + ...(hasDescription + ? [ + chSql`anyLast(${{ Identifier: 'MetricDescription' }}) AS MetricDescription`, + ] + : []), + ]; + const namePlaceholders = concatChSql( + ',', + names.map(name => chSql`${{ String: name }}`), + ); + const sql = chSql` + SELECT ${concatChSql(', ', projections)} + FROM ${tableExpr({ database: databaseName, table: tableName })} + WHERE MetricName IN (${namePlaceholders}) + AND TimeUnix >= fromUnixTimestamp64Milli(${{ Int64: dateRange[0].getTime() }}) + AND TimeUnix <= fromUnixTimestamp64Milli(${{ Int64: dateRange[1].getTime() }}) + GROUP BY MetricName + `; + + type EnrichmentRow = { + MetricName: string; + MetricUnit?: string; + MetricDescription?: string; + }; + + const response = await clickhouseClient.query<'JSON'>({ + query: sql.sql, + query_params: sql.params, + format: 'JSON', + connectionId, + abort_signal: signal, + }); + const result = (await response.json()) as { data: EnrichmentRow[] }; + + const enrichments = new Map< + string, + { unit?: string; description?: string } + >(); + for (const row of result.data) { + enrichments.set(row.MetricName, { + ...(row.MetricUnit ? { unit: row.MetricUnit } : {}), + ...(row.MetricDescription ? { description: row.MetricDescription } : {}), + }); + } + return enrichments; +} diff --git a/packages/hdx-eval/src/__tests__/markdown.test.ts b/packages/hdx-eval/src/__tests__/markdown.test.ts index a85ccbea92..c55ed5c572 100644 --- a/packages/hdx-eval/src/__tests__/markdown.test.ts +++ b/packages/hdx-eval/src/__tests__/markdown.test.ts @@ -8,7 +8,15 @@ function pair( mcp: string, i: number, plugin = 'none', - adoption?: { score: number; hits: Array<{ id: string; satisfied: boolean }> }, + adoption?: { + score: number; + hits: Array<{ + id: string; + satisfied: boolean; + informational?: boolean; + weight?: number; + }>; + }, ): GradedRunPair { const run: RunRecord = { schemaVersion: 1, @@ -64,9 +72,10 @@ function pair( score: adoption.score, hits: adoption.hits.map(h => ({ id: h.id, - weight: 1, + weight: h.weight ?? 1, matched: h.satisfied, satisfied: h.satisfied, + ...(h.informational ? { informational: true } : {}), })), }; } @@ -144,6 +153,12 @@ describe('renderMarkdownReport with adoption data', () => { hits: [ { id: 'used_metric_tool', satisfied: used }, { id: 'named_jvm_memory', satisfied: named }, + { + id: 'checked_supporting', + satisfied: false, + informational: true, + weight: 0, + }, ], }); const summary = buildAggregate({ @@ -172,6 +187,13 @@ describe('renderMarkdownReport with adoption data', () => { // hyperdx (challenger) adoption 1.0 vs clickhouse (baseline) 0.0 → +100%. expect(md).toContain('+100%'); }); + + it('labels informational checks with (info) and explains the exclusion', () => { + expect(md).toContain('checked_supporting (info)'); + expect(md).toContain('excluded from the adoption score'); + // Scoring checks must NOT get the label. + expect(md).not.toContain('used_metric_tool (info)'); + }); }); describe('renderMarkdownReport with plugin arms', () => { diff --git a/packages/hdx-eval/src/__tests__/programmatic.test.ts b/packages/hdx-eval/src/__tests__/programmatic.test.ts index 75a2cf8477..32da947bde 100644 --- a/packages/hdx-eval/src/__tests__/programmatic.test.ts +++ b/packages/hdx-eval/src/__tests__/programmatic.test.ts @@ -274,6 +274,154 @@ describe('runAdoptionChecks', () => { expect(result.hits[0].satisfied).toBe(false); }); + describe('quiet-saturation answer-check regexes (phrasings from real runs)', () => { + const check = (id: string, text: string): boolean => { + const rubric = loadScenarioRubric('quiet-saturation'); + const entry = rubric.programmatic.find(c => c.id === id)!; + const result = runProgrammaticChecks(text, [entry]); + return result.hits[0].satisfied; + }; + + it('names_uniform_latency accepts route enumeration and every-request phrasing', () => { + // Real phrasings that the original pattern missed: + expect( + check( + 'names_uniform_latency', + 'p95 went 185ms → 2.4s across `POST /api/orders`, `GET /api/orders/{orderId}`, `GET /api/cart`', + ), + ).toBe(true); + expect( + check( + 'names_uniform_latency', + 'since then every request queues behind connection acquisition', + ), + ).toBe(true); + expect( + check( + 'names_uniform_latency', + 'All order endpoints on `order-api` are affected — everything that needs an `orders-pg` connection', + ), + ).toBe(true); + // Still no credit for an answer that never conveys uniformity: + expect( + check('names_uniform_latency', 'POST /api/orders latency rose.'), + ).toBe(false); + }); + + it('distinguishes_true_onset accepts clock-time chains and fill-over-duration phrasing', () => { + expect( + check( + 'distinguishes_true_onset', + 'The pool filled up over the next hour, hit its max of 40 at ~15:38', + ), + ).toBe(true); + expect( + check( + 'distinguishes_true_onset', + 'The leak slowly drained the orders-pg connection pool (max 40) for about an hour with no visible impact', + ), + ).toBe(true); + expect( + check( + 'distinguishes_true_onset', + 'Leaked connections accumulated steadily until the pool was pinned at 40/40 by ~15:30', + ), + ).toBe(true); + expect( + check( + 'distinguishes_true_onset', + 'the feature flag was ramped 5% → 100% at 14:39 UTC; the pool was pinned at 40/40 by 15:30', + ), + ).toBe(true); + expect( + check( + 'distinguishes_true_onset', + '"used" was flat at ~8 all hour before, then climbs 11.7 → 14.7 → 19 between 14:40 and 15:45', + ), + ).toBe(true); + // No credit when the answer only reports the visible onset: + expect( + check( + 'distinguishes_true_onset', + 'Latency degraded starting around 15:40 and requests now time out.', + ), + ).toBe(false); + }); + + it('rules_out_batch_spike was removed — only the negative batch check remains', () => { + const rubric = loadScenarioRubric('quiet-saturation'); + expect( + rubric.programmatic.find(c => c.id === 'rules_out_batch_spike'), + ).toBeUndefined(); + expect( + rubric.programmatic.find(c => c.id === 'false_blame_batch'), + ).toBeDefined(); + }); + }); + + it('quiet-saturation rubric: supporting metrics are informational, pool metrics score', () => { + const rubric = loadScenarioRubric('quiet-saturation'); + const pool = rubric.adoption!.find(c => c.id === 'queried_pool_metrics')!; + const supporting = rubric.adoption!.find( + c => c.id === 'queried_supporting_metrics', + )!; + expect(pool.informational).toBeUndefined(); + expect(pool.weight).toBeGreaterThan(0); + expect(supporting.informational).toBe(true); + + // An agent that only queries the pool metrics scores 100% adoption. + const result = runAdoptionChecks( + [toolCall('t', { metricName: 'db.client.connections.usage' })], + rubric.adoption!, + ); + expect(result.score).toBeCloseTo(1, 5); + }); + + describe('informational checks', () => { + const infoCheck = { + id: 'queried_supporting_metrics', + informational: true, + metrics: ['system.cpu.utilization'], + }; + + it('excludes informational checks from the score — skipping them still reads 100%', () => { + const result = runAdoptionChecks( + [toolCall('t', { metricName: 'jvm.gc.pause' })], + [gcCheck, infoCheck], + ); + // gcCheck satisfied, informational check not — score is still 1.0. + expect(result.score).toBeCloseTo(1, 5); + const info = result.hits.find( + h => h.id === 'queried_supporting_metrics', + )!; + expect(info.satisfied).toBe(false); + expect(info.informational).toBe(true); + expect(info.weight).toBe(0); + }); + + it('still evaluates and reports informational hits when they match', () => { + const result = runAdoptionChecks( + [toolCall('t', { metricName: 'system.cpu.utilization' })], + [gcCheck, infoCheck], + ); + // Only the informational check matched — the score stays 0. + expect(result.score).toBe(0); + const info = result.hits.find( + h => h.id === 'queried_supporting_metrics', + )!; + expect(info.satisfied).toBe(true); + expect(info.informational).toBe(true); + }); + + it('does not flag scoring hits as informational', () => { + const result = runAdoptionChecks( + [toolCall('t', { metricName: 'jvm.gc.pause' })], + [gcCheck], + ); + expect(result.hits[0].informational).toBeUndefined(); + }); + }); + it('alsoPattern must match the SAME call as the metric key', () => { const grouped = { id: 'grouped_memory_by_pod_or_pool', diff --git a/packages/hdx-eval/src/__tests__/quiet-saturation.test.ts b/packages/hdx-eval/src/__tests__/quiet-saturation.test.ts new file mode 100644 index 0000000000..435505fd19 --- /dev/null +++ b/packages/hdx-eval/src/__tests__/quiet-saturation.test.ts @@ -0,0 +1,309 @@ +import { mulberry32 } from '@/rng/seeded'; +import { quietSaturationScenario } from '@/scenarios/quiet-saturation/generate'; +import { collectScenario } from '@/scenarios/types'; + +const NOW_MS = Date.parse('2026-06-01T12:00:00.000Z'); +// 2% volume keeps the test cheap while preserving every planted signal — +// metrics are fixed-volume and never scaled. +const TEST_VOLUME_FACTOR = 0.02; + +const WINDOW_MS = 3 * 60 * 60 * 1000; +const WINDOW_START_MS = NOW_MS - WINDOW_MS; +const FLAG_FLIP_MS = NOW_MS - 90 * 60 * 1000; +const NOTIFY_DEPLOY_MS = NOW_MS - 40 * 60 * 1000; +const TIMEOUT_WINDOW_START_MS = NOW_MS - 12 * 60 * 1000; +const LAST_SATURATION_MS = NOW_MS - 27 * 60 * 1000; +const POOL_MAX = 40; +const SUBJECT = 'order-api'; +const TWIN = 'catalog-api'; + +function run(seed: number, factor = TEST_VOLUME_FACTOR) { + return collectScenario( + quietSaturationScenario.generate({ + rng: mulberry32(seed), + nowMs: NOW_MS, + volumeFactor: factor, + }), + ); +} + +describe('quiet-saturation scenario', () => { + const result = run(42); + const m = result.metrics!; + + const poolUsedSeries = (service: string) => + m + .gauge!.filter( + g => + g.metricName === 'db.client.connections.usage' && + g.serviceName === service && + g.attributes?.state === 'used', + ) + .map(g => ({ + t: g.timeUnixMs, + value: g.value, + pod: g.resourceAttributes?.['k8s.pod.name'], + })); + + it('emits gauge, sum, and histogram metrics', () => { + expect(m).toBeDefined(); + expect(m.gauge!.length).toBeGreaterThan(0); + expect(m.sum!.length).toBeGreaterThan(0); + expect(m.histogram!.length).toBeGreaterThan(0); + }); + + it('is deterministic for a fixed seed (traces + metrics)', () => { + const b = run(42); + expect(b.traces.length).toBe(result.traces.length); + expect(b.logs.length).toBe(result.logs.length); + expect(b.traces[10]?.spanId).toBe(result.traces[10]?.spanId); + expect(JSON.stringify(b.metrics)).toBe(JSON.stringify(m)); + }); + + it('anchors every metric point at or before now, within the window', () => { + const all = [...m.gauge!, ...m.sum!, ...m.histogram!]; + for (const pt of all) { + expect(pt.timeUnixMs).toBeLessThanOrEqual(NOW_MS); + expect(pt.timeUnixMs).toBeGreaterThanOrEqual(WINDOW_START_MS); + } + }); + + describe('pool gauges — the load-bearing signal', () => { + const used = poolUsedSeries(SUBJECT); + const pods = [...new Set(used.map(p => p.pod))]; + + it('tracks 4 order-api pods', () => { + expect(pods).toHaveLength(4); + }); + + it('is flat at baseline before the flag flip, on every pod', () => { + for (const pod of pods) { + const pre = used.filter(p => p.pod === pod && p.t < FLAG_FLIP_MS); + expect(pre.length).toBeGreaterThan(0); + for (const p of pre) expect(p.value).toBe(8); + } + }); + + it('climbs MONOTONICALLY after the flip (a leak never dips)', () => { + for (const pod of pods) { + const series = used + .filter(p => p.pod === pod) + .sort((a, b) => a.t - b.t); + for (let i = 1; i < series.length; i++) { + expect(series[i].value).toBeGreaterThanOrEqual(series[i - 1].value); + } + } + }); + + it('pins every pod at the 40-connection cap before now', () => { + for (const pod of pods) { + const tail = used.filter( + p => p.pod === pod && p.t >= LAST_SATURATION_MS, + ); + expect(tail.length).toBeGreaterThan(0); + for (const p of tail) expect(p.value).toBe(POOL_MAX); + } + }); + + it('publishes the ceiling as db.client.connections.max = 40', () => { + const maxes = m.gauge!.filter( + g => + g.metricName === 'db.client.connections.max' && + g.serviceName === SUBJECT, + ); + expect(maxes.length).toBeGreaterThan(0); + for (const g of maxes) expect(g.value).toBe(POOL_MAX); + }); + + it('lifts pending_requests off zero only after saturation', () => { + const pending = m.gauge!.filter( + g => + g.metricName === 'db.client.connections.pending_requests' && + g.serviceName === SUBJECT, + ); + const before = pending.filter(g => g.timeUnixMs < FLAG_FLIP_MS); + expect(Math.max(...before.map(g => g.value))).toBeLessThanOrEqual(1); + const tail = pending.filter(g => g.timeUnixMs >= NOW_MS - 5 * 60 * 1000); + expect(Math.max(...tail.map(g => g.value))).toBeGreaterThan(10); + }); + + it('keeps the catalog-api twin healthy (same metric names, ~8/40)', () => { + const twin = poolUsedSeries(TWIN); + expect(twin.length).toBeGreaterThan(0); + for (const p of twin) expect(p.value).toBeLessThanOrEqual(11); + }); + }); + + describe('leak-vs-load discriminator', () => { + it('keeps the request-count slope perfectly flat', () => { + const counts = m + .sum!.filter( + s => + s.metricName === 'http.server.request.count' && + s.serviceName === SUBJECT, + ) + .sort((a, b) => a.timeUnixMs - b.timeUnixMs); + expect(counts.length).toBeGreaterThan(10); + const deltas = new Set(); + for (let i = 1; i < counts.length; i++) { + deltas.add(counts[i].value - counts[i - 1].value); + } + expect(deltas.size).toBe(1); // constant increments — traffic never moves + }); + + it('keeps order-api cpu/memory flat (rules out infra)', () => { + const cpu = m.gauge!.filter( + g => + g.metricName === 'system.cpu.utilization' && + g.serviceName === SUBJECT, + ); + for (const g of cpu) expect(g.value).toBeLessThan(0.35); + }); + }); + + describe('traces — the slow-but-viable path', () => { + const orderRoots = result.traces.filter( + t => t.serviceName === SUBJECT && t.spanKind === 'SPAN_KIND_SERVER', + ); + const acquires = result.traces.filter( + t => t.spanName === 'db.pool.acquire', + ); + const queries = result.traces.filter( + t => t.spanName === 'INSERT orders' || t.spanName === 'SELECT orders', + ); + + it('slows ALL routes together after saturation (uniform creep)', () => { + const routes = ['/api/orders', '/api/orders/{orderId}', '/api/cart']; + for (const route of routes) { + const of = (rows: typeof orderRoots) => + rows.length + ? rows.reduce((a, r) => a + r.durationNs, 0) / rows.length / 1e6 + : 0; + const early = orderRoots.filter( + r => + r.spanAttributes?.['http.route'] === route && + r.timestampMs < FLAG_FLIP_MS, + ); + const late = orderRoots.filter( + r => + r.spanAttributes?.['http.route'] === route && + r.timestampMs >= NOW_MS - 10 * 60 * 1000 && + r.spanAttributes?.['http.response.status_code'] === '200', + ); + expect(early.length).toBeGreaterThan(0); + expect(late.length).toBeGreaterThan(0); + expect(of(late)).toBeGreaterThan(of(early) + 300); // every route grew + } + }); + + it('grows db.pool.acquire while db.query stays fast (client-side wait)', () => { + const lateAcquires = acquires.filter( + a => + a.timestampMs >= NOW_MS - 10 * 60 * 1000 && + a.statusCode !== 'STATUS_CODE_ERROR', + ); + const meanMs = + lateAcquires.reduce((s, a) => s + a.durationNs, 0) / + lateAcquires.length / + 1e6; + expect(meanMs).toBeGreaterThan(300); + for (const q of queries) { + expect(q.durationNs / 1e6).toBeLessThanOrEqual(25.5); // the DB never slows + } + }); + + it('confines 503 acquire-timeouts to the final window, ~30s durations', () => { + const failures = orderRoots.filter( + r => r.statusCode === 'STATUS_CODE_ERROR', + ); + expect(failures.length).toBeGreaterThan(0); + for (const f of failures) { + expect(f.timestampMs).toBeGreaterThanOrEqual(TIMEOUT_WINDOW_START_MS); + expect(f.durationNs / 1e6).toBeGreaterThanOrEqual(30_000); + expect(f.spanAttributes?.['http.response.status_code']).toBe('503'); + } + }); + + it('introduces invoice.render_async only after the flag flip', () => { + const invoices = result.traces.filter( + t => t.spanName === 'invoice.render_async', + ); + expect(invoices.length).toBeGreaterThan(0); + for (const inv of invoices) { + expect(inv.timestampMs).toBeGreaterThanOrEqual(FLAG_FLIP_MS); + } + }); + }); + + describe('planted events + distractors', () => { + it('plants exactly one feature-flag flip event at T-90m', () => { + const flips = result.logs.filter( + l => l.logAttributes?.['event.name'] === 'feature_flag.update', + ); + expect(flips).toHaveLength(1); + expect(flips[0].timestampMs).toBe(FLAG_FLIP_MS); + expect(flips[0].body).toContain('orders.async-invoice'); + }); + + it('plants the innocent notification-service rollout near the visible onset', () => { + const rollouts = result.logs.filter( + l => + l.logAttributes?.['event.name'] === 'deployment.rollout' && + l.serviceName === 'notification-service', + ); + expect(rollouts.length).toBe(5); // start + 3 pods + complete + for (const r of rollouts) { + expect(r.timestampMs).toBeGreaterThanOrEqual(NOTIFY_DEPLOY_MS); + expect(r.timestampMs).toBeGreaterThan(FLAG_FLIP_MS); // after the leak began + } + }); + + it('emits pool-timeout ERROR logs only in the final window, with pool stats', () => { + const timeouts = result.logs.filter( + l => l.logAttributes?.['event.name'] === 'db.pool.acquire_timeout', + ); + expect(timeouts.length).toBeGreaterThan(0); + for (const l of timeouts) { + expect(l.timestampMs).toBeGreaterThanOrEqual(TIMEOUT_WINDOW_START_MS); + expect(l.body).toContain("pool 'orders-pg'"); + expect(l.body).toContain('pool size 40, in use 40'); + expect(l.traceId).toBeTruthy(); // trace-correlated + } + }); + + it('spikes inventory-service CPU only during the batch window', () => { + const cpu = m.gauge!.filter( + g => + g.metricName === 'system.cpu.utilization' && + g.serviceName === 'inventory-service', + ); + const inBatch = cpu.filter( + g => + g.timeUnixMs >= NOW_MS - 60 * 60 * 1000 && + g.timeUnixMs <= NOW_MS - 45 * 60 * 1000, + ); + const outside = cpu.filter( + g => + g.timeUnixMs < NOW_MS - 60 * 60 * 1000 || + g.timeUnixMs > NOW_MS - 45 * 60 * 1000, + ); + expect(Math.min(...inBatch.map(g => g.value))).toBeGreaterThan(0.8); + expect(Math.max(...outside.map(g => g.value))).toBeLessThan(0.35); + }); + }); + + describe('volume scaling', () => { + it('scales trace/log floors but keeps planted metric volume fixed', () => { + const tiny = run(42, 0.005); + expect(tiny.traces.length).toBeLessThan(result.traces.length); + expect(JSON.stringify(tiny.metrics!.gauge!.length)).toBe( + JSON.stringify(m.gauge!.length), + ); + // Fixed-volume planted events survive any factor. + const flips = tiny.logs.filter( + l => l.logAttributes?.['event.name'] === 'feature_flag.update', + ); + expect(flips).toHaveLength(1); + }); + }); +}); diff --git a/packages/hdx-eval/src/grading/programmatic.ts b/packages/hdx-eval/src/grading/programmatic.ts index 7a4a457904..8ed0f90513 100644 --- a/packages/hdx-eval/src/grading/programmatic.ts +++ b/packages/hdx-eval/src/grading/programmatic.ts @@ -61,6 +61,11 @@ export function metricKeyToRegex(key: string): RegExp { * * Result shape is identical to answer checks so reports can treat both * uniformly. + * + * Checks flagged `informational: true` are evaluated and included in + * `hits` (so per-check usage rates still report them) but contribute + * nothing to the weighted score — an agent that skips them still scores + * 100% on the remaining checks. */ export function runAdoptionChecks( toolCalls: ToolCallRecord[], @@ -73,7 +78,9 @@ export function runAdoptionChecks( let hitWeight = 0; for (const check of checks) { - totalWeight += check.weight; + const scoring = check.informational !== true; + const weight = check.weight ?? 0; + if (scoring) totalWeight += weight; const metricRegexes = check.metrics.map(metricKeyToRegex); let also: RegExp | null = null; if (check.alsoPattern !== undefined) { @@ -91,12 +98,13 @@ export function runAdoptionChecks( args => metricRegexes.some(rx => rx.test(args)) && (!also || also.test(args)), ); - if (matched) hitWeight += check.weight; + if (matched && scoring) hitWeight += weight; hits.push({ id: check.id, - weight: check.weight, + weight: scoring ? weight : 0, matched, satisfied: matched, + ...(scoring ? {} : { informational: true }), }); } diff --git a/packages/hdx-eval/src/grading/rubric.ts b/packages/hdx-eval/src/grading/rubric.ts index 4db5e79383..b5dae8164e 100644 --- a/packages/hdx-eval/src/grading/rubric.ts +++ b/packages/hdx-eval/src/grading/rubric.ts @@ -70,7 +70,7 @@ function validateAdoptionCheck( if (!entry || typeof entry !== 'object' || Array.isArray(entry)) { throw new Error( `rubric.adoption for '${scenarioName}': each check must be an object ` + - `{ id, weight, metrics[], alsoPattern? } — tuples/patterns are not supported`, + `{ id, weight, metrics[], alsoPattern?, informational? } — tuples/patterns are not supported`, ); } const check = entry as Record; @@ -79,7 +79,26 @@ function validateAdoptionCheck( `rubric.adoption for '${scenarioName}': each check needs a string 'id'`, ); } - if (typeof check.weight !== 'number' || check.weight <= 0) { + if ( + check.informational !== undefined && + typeof check.informational !== 'boolean' + ) { + throw new Error( + `rubric.adoption for '${scenarioName}': check '${check.id}' informational must be a boolean`, + ); + } + if (check.informational === true) { + // Informational checks are excluded from the score — weight is optional + // and ignored, but reject nonsense values to catch typos. + if ( + check.weight !== undefined && + (typeof check.weight !== 'number' || check.weight < 0) + ) { + throw new Error( + `rubric.adoption for '${scenarioName}': check '${check.id}' weight, when present on an informational check, must be a non-negative number`, + ); + } + } else if (typeof check.weight !== 'number' || check.weight <= 0) { throw new Error( `rubric.adoption for '${scenarioName}': check '${check.id}' weight must be a positive number`, ); diff --git a/packages/hdx-eval/src/grading/types.ts b/packages/hdx-eval/src/grading/types.ts index 1fbc8ad0ff..19136b59b7 100644 --- a/packages/hdx-eval/src/grading/types.ts +++ b/packages/hdx-eval/src/grading/types.ts @@ -20,7 +20,9 @@ export type ProgrammaticCheck = { */ export type AdoptionCheck = { id: string; - weight: number; + /** Required (positive) unless `informational: true`; ignored for + * informational checks. */ + weight?: number; /** * Any-of list of full metric names/keys (e.g. * `process.runtime.jvm.memory.used`). Matched case-insensitively with @@ -32,6 +34,14 @@ export type AdoptionCheck = { * `pool|pod` for "grouped the memory metric by pod/pool"). */ alsoPattern?: string; + /** + * When true, the check is evaluated and reported (per-check usage rate) + * but EXCLUDED from the weighted adoption score. Use for metrics whose + * facts have cheaper substitutes in other signals — querying them is + * thoroughness, not the behavior the score measures, and an efficient + * agent that skips them should still read 100%. + */ + informational?: boolean; }; type JudgeCriterion = { @@ -57,6 +67,9 @@ export type ProgrammaticHit = { matched: boolean; satisfied: boolean; negative?: boolean; + /** Present (true) on adoption hits whose check is informational — + * reported but excluded from the score. */ + informational?: boolean; }; export type ProgrammaticResult = { diff --git a/packages/hdx-eval/src/reports/aggregate.ts b/packages/hdx-eval/src/reports/aggregate.ts index 04aaed9499..c53b91a9fc 100644 --- a/packages/hdx-eval/src/reports/aggregate.ts +++ b/packages/hdx-eval/src/reports/aggregate.ts @@ -19,7 +19,12 @@ export type CellSummary = { columnKey: ColumnKey; n: number; programmatic: { mean: number; perCheck: Record }; - adoption?: { mean: number; perCheck: Record }; + adoption?: { + mean: number; + perCheck: Record; + /** Check ids that are informational — reported but excluded from mean. */ + informational?: string[]; + }; judge: { weightedMean: number; perCriterion: Record; @@ -262,8 +267,12 @@ function buildCellSummary( const adoptionMean = mean(adopted.map(p => p.grade.adoption!.score)); const adoptionPerCheck: Record = {}; const adoptionCheckIds = new Set(); + const adoptionInformational = new Set(); for (const p of adopted) - for (const h of p.grade.adoption!.hits) adoptionCheckIds.add(h.id); + for (const h of p.grade.adoption!.hits) { + adoptionCheckIds.add(h.id); + if (h.informational) adoptionInformational.add(h.id); + } for (const id of adoptionCheckIds) { const satisfied = adopted.map( p => p.grade.adoption!.hits.find(h => h.id === id)?.satisfied ?? false, @@ -271,7 +280,13 @@ function buildCellSummary( adoptionPerCheck[id] = satisfied.filter(Boolean).length / satisfied.length; } - adoption = { mean: adoptionMean, perCheck: adoptionPerCheck }; + adoption = { + mean: adoptionMean, + perCheck: adoptionPerCheck, + ...(adoptionInformational.size > 0 + ? { informational: [...adoptionInformational].sort() } + : {}), + }; } const perCriterion: Record = {}; diff --git a/packages/hdx-eval/src/reports/markdown.ts b/packages/hdx-eval/src/reports/markdown.ts index a82f969eb9..2401fdce75 100644 --- a/packages/hdx-eval/src/reports/markdown.ts +++ b/packages/hdx-eval/src/reports/markdown.ts @@ -239,9 +239,11 @@ function renderAdoptionBreakdown( columns: ColumnKey[], ): string | null { const allChecks = new Set(); + const informational = new Set(); for (const cell of Object.values(scenario.cells)) { if (!cell?.adoption) continue; for (const id of Object.keys(cell.adoption.perCheck)) allChecks.add(id); + for (const id of cell.adoption.informational ?? []) informational.add(id); } if (allChecks.size === 0) return null; @@ -249,7 +251,10 @@ function renderAdoptionBreakdown( const rows = [ '#### Adoption per-check (usage rate)', '', - 'Usage rate = share of runs whose tool-call args matched the check.', + 'Usage rate = share of runs whose tool-call args matched the check.' + + (informational.size > 0 + ? ' Checks marked (info) are informational — reported but excluded from the adoption score.' + : ''), '', `| Adoption check | ${colHeaders} |`, '|---' + '|---'.repeat(columns.length) + '|', @@ -259,7 +264,8 @@ function renderAdoptionBreakdown( const v = scenario.cells[m]?.adoption?.perCheck[id]; return fmtRate(v); }); - rows.push(`| ${id} | ${colCells.join(' | ')} |`); + const label = informational.has(id) ? `${id} (info)` : id; + rows.push(`| ${label} | ${colCells.join(' | ')} |`); } return rows.join('\n'); } diff --git a/packages/hdx-eval/src/scenarios/index.ts b/packages/hdx-eval/src/scenarios/index.ts index 74c0cc6b3c..4641399195 100644 --- a/packages/hdx-eval/src/scenarios/index.ts +++ b/packages/hdx-eval/src/scenarios/index.ts @@ -4,6 +4,7 @@ import { errorRootCauseScenario } from './error-root-cause/generate'; import { latencySpikeScenario } from './latency-spike/generate'; import { metricSaturationScenario } from './metric-saturation/generate'; import { noisySignalsScenario } from './noisy-signals/generate'; +import { quietSaturationScenario } from './quiet-saturation/generate'; import { segmentedRegressionScenario } from './segmented-regression/generate'; import { serviceHealthCheckScenario } from './service-health-check/generate'; import type { Scenario } from './types'; @@ -15,6 +16,7 @@ export const SCENARIOS: Record = { [latencySpikeScenario.name]: latencySpikeScenario, [metricSaturationScenario.name]: metricSaturationScenario, [noisySignalsScenario.name]: noisySignalsScenario, + [quietSaturationScenario.name]: quietSaturationScenario, [segmentedRegressionScenario.name]: segmentedRegressionScenario, [serviceHealthCheckScenario.name]: serviceHealthCheckScenario, }; diff --git a/packages/hdx-eval/src/scenarios/quiet-saturation/generate.ts b/packages/hdx-eval/src/scenarios/quiet-saturation/generate.ts new file mode 100644 index 0000000000..d6949f4c46 --- /dev/null +++ b/packages/hdx-eval/src/scenarios/quiet-saturation/generate.ts @@ -0,0 +1,976 @@ +/** + * quiet-saturation scenario + * + * Story: order-api (4 pods, Node.js) talks to Postgres through a fixed + * 40-connection pool per pod ('orders-pg'). 90 minutes before `now` a + * feature flag (`orders.async-invoice`) is rolled from 5% to 100%. The + * flag-gated async-invoice path LEAKS pooled connections — it acquires a + * connection and, on a common branch, never releases it. Pool usage climbs + * monotonically from ~8 toward the 40 cap on every pod (saturating between + * 36 and 27 minutes ago, staggered by traffic). Once a pod's pool is + * pinned at 40/40, every request on that pod queues waiting for a + * connection: latency creeps up UNIFORMLY across ALL order-api routes + * (the wait happens at acquire time, before any query runs), while the + * database itself stays fast. In the final ~12 minutes, acquire waits + * start hitting the 30s pool timeout: a trickle of 503s with distinctive + * ~30_000ms durations plus ERROR logs that carry the pool stats. + * + * DESIGN GOAL — the "metrics are the FAST PATH" middle tier: + * - metric-saturation: cause readable ONLY in metrics (forced use). + * - deploy-regression: metrics redundant (organic adoption ≈ 0 for + * budget-aware agents — measured, not assumed). + * - quiet-saturation (this): BOTH paths reach the full answer, but the + * metric path is decisively cheaper. Efficiency is read from the + * tool-calls / wall-clock columns and the adoption checks, and the + * excellence-tier answer facts are history that only metrics (or a + * long trace grind) can establish. + * + * The two solve paths: + * METRIC PATH (~5-7 calls): db.client.connections.usage{state=used} + * grouped by pod → monotonic climb from T-90m pinned at 40/40; + * db.client.connections.max = 40 names the ceiling; + * db.client.connections.pending_requests climbs once pools fill; + * http.server.request.count slope is FLAT (rules out a traffic spike — + * the climb is a leak, not load); cpu/memory flat (rules out infra). + * Join the climb onset to the single feature-flag log event at T-90m. + * + * TRACE/LOG PATH (~12-18 calls): all order-api routes slow together + * (no single culprit op — the uniformity IS the clue); slow-trace + * waterfalls show db.pool.acquire dominating while the db.query child + * stays 5-25ms (the DB is fast; the wait is client-side); the final- + * minutes ERROR logs state the pool stats outright ("pool size 40, in + * use 40"); the invoice.render span name first appears at the flag + * flip. Viable, but reconstructing WHEN the leak started and that + * traffic stayed flat takes many more windowed queries. + * + * Distractors: + * - INNOCENT completed notification-service deploy ~40 min ago — lands + * near the VISIBLE latency onset (~30 min ago). Healthy on both + * versions; not in the order path's failure chain. The pool climb + * predates it by ~50 minutes. + * - inventory-service CPU spike (0.85-0.95) from T-60m to T-45m: a + * nightly reconciliation batch, bracketed by INFO logs. Alarming on a + * chart, unrelated to order-api. + * - catalog-api pool TWIN: same db.client.connections.* metric names, + * healthy ~8/40 usage throughout — isolating order-api requires + * filtering by service, not keyword-hunting metric names. + * - Constant-rate NonFatalRetryableError caught-exception noise on + * order-api (rate does not change at any boundary). + * - The DB-is-slow trap: db.query children stay fast throughout, so + * "Postgres is overloaded" is a calibration failure the rubric + * penalizes. + * + * Consistency features copied from deploy-regression's hardening rounds: + * 26-turn cap with a soft answer checkpoint, the count-your-tool-calls + * budget note, the truncation-strict judge preamble, and a signalsNote + * byte-identical to metric-saturation's (adoption parity). + */ +import { makeLog } from '@/generators/logs'; +import { + bucketize, + makeGauge, + makeHistogram, + makeSum, +} from '@/generators/metrics'; +import { + buildResourcePool, + cacheHitLog, + caughtExceptionLog, + envoyAccessLog, + normalizeSeverityText, + pickResource, + serviceOpsDebugLog, + spreadTimestamp, + upstreamHealthProbeLog, +} from '@/generators/templates'; +import { makeSpan, msToNs, newSpanId, newTraceId } from '@/generators/traces'; +import type { + GaugeMetricRow, + HistogramMetricRow, + LogRow, + SumMetricRow, + TraceRow, +} from '@/generators/types'; +import { buildInvestigationSystemPrompt } from '@/harness/systemPrompt'; +import type { + GenerateContext, + MetricBatch, + Scenario, + ScenarioBatch, +} from '@/scenarios/types'; + +import groundTruth from './ground-truth.json'; + +// ─── Services ─────────────────────────────────────────────────────────────── + +const SUBJECT_SERVICE = 'order-api'; +const TWIN_SERVICE = 'catalog-api'; +const NOTIFY_SERVICE = 'notification-service'; +const NEIGHBOR_SERVICE = 'inventory-service'; +const PROXY_SERVICE = 'frontend-proxy'; + +// ─── Time model ───────────────────────────────────────────────────────────── +// 3-hour window so the pre-leak baseline is clearly visible. The flag flips +// 90 min before `now`; pod pools saturate 36..27 min before `now` +// (staggered by traffic); acquire timeouts appear in the last 12 min. + +const HISTORY_WINDOW_MS = 3 * 60 * 60 * 1000; +const SCRAPE_INTERVAL_MS = 60 * 1000; +const FLAG_FLIP_AGO_MS = 90 * 60 * 1000; +const TIMEOUT_ERRORS_AGO_MS = 12 * 60 * 1000; + +const POD_COUNT = 4; +/** Pod i's pool pins at 40/40 this long before `now` (staggered 3 min). */ +const POD_SATURATION_AGO_MS = [36, 33, 30, 27].map(m => m * 60 * 1000); + +// Innocent notification-service rollout: starts 40 min ago, one pod per +// minute (3 pods), completed 37 min ago — right next to the VISIBLE +// latency onset, 50 minutes after the actual leak began. +const NOTIFY_DEPLOY_AGO_MS = 40 * 60 * 1000; +const NOTIFY_ROLLOUT_STAGGER_MS = 60 * 1000; +const NOTIFY_POD_COUNT = 3; +const NOTIFY_OLD_VERSION = '2.14.0'; +const NOTIFY_NEW_VERSION = '2.15.0'; + +// inventory-service nightly batch (CPU-spike red herring): T-60m..T-45m. +const BATCH_START_AGO_MS = 60 * 60 * 1000; +const BATCH_END_AGO_MS = 45 * 60 * 1000; + +// ─── Pool model ───────────────────────────────────────────────────────────── + +const POOL_NAME = 'orders-pg'; +const POOL_MAX = 40; +const POOL_BASE_USED = 8; +const ACQUIRE_TIMEOUT_MS = 30_000; +/** Max acquire wait (ms) reached at `now` on the earliest-saturated pod. */ +const MAX_QUEUE_WAIT_MS = 2_600; +/** Fraction of requests on a saturated pod that hit the 30s acquire + * timeout during the final TIMEOUT_ERRORS_AGO_MS window. */ +const TIMEOUT_FRACTION = 0.05; + +const FLAG_KEY = 'orders.async-invoice'; +const FLAG_FLIP_BODY = + `Feature flag ${FLAG_KEY} rollout updated: 5% -> 100% ` + + '(actor: platform-team, change ORD-4112)'; + +const TIMEOUT_LOG_BODY = (pending: number) => + `Timeout: failed to acquire connection from pool '${POOL_NAME}' within ` + + `${ACQUIRE_TIMEOUT_MS}ms (pool size ${POOL_MAX}, in use ${POOL_MAX}, ` + + `pending ${pending})`; + +// ─── Metric constants ─────────────────────────────────────────────────────── + +const LATENCY_BOUNDS_MS = [5, 10, 25, 50, 100, 250, 500, 1000, 2500, 5000]; +const ORDER_REQS_PER_SCRAPE = 180; // flat — traffic never changes + +// ─── Volumes ──────────────────────────────────────────────────────────────── +// Root spans get acquire/query children, so the root count is lower than +// deploy-regression's to keep total rows comparable. Planted events (flag +// flip, rollout logs, batch markers) stay fixed. + +const TOTAL_TRACES = 220_000; +const TOTAL_LOGS = 700_000; + +const TRAFFIC_MIX = [ + { value: 'order_create', weight: 22 }, + { value: 'order_get', weight: 18 }, + { value: 'cart', weight: 15 }, + { value: 'catalog', weight: 30 }, + { value: 'notify', weight: 15 }, +] as const; + +const LOG_MIX = [ + { value: 'cache_hit', weight: 28 }, + { value: 'envoy', weight: 27 }, + { value: 'health_probe', weight: 10 }, + { value: 'inventory_ops', weight: 20 }, + { value: 'caught_exception', weight: 15 }, +] as const; + +type Rng = GenerateContext['rng']; + +// ─── Saturation model ─────────────────────────────────────────────────────── + +function podSaturationMs(nowMs: number, pod: number): number { + return nowMs - POD_SATURATION_AGO_MS[pod % POD_COUNT]; +} + +/** Pooled connections in use on `pod` at `t` — monotonic ramp, pinned at + * POOL_MAX after saturation. Deterministic (no jitter) so the "usage + * never decreases" invariant is exact. */ +function poolUsed(nowMs: number, pod: number, t: number): number { + const leakStart = nowMs - FLAG_FLIP_AGO_MS; + if (t < leakStart) return POOL_BASE_USED; + const full = podSaturationMs(nowMs, pod); + if (t >= full) return POOL_MAX; + const frac = (t - leakStart) / (full - leakStart); + return Math.min( + POOL_MAX, + POOL_BASE_USED + Math.round((POOL_MAX - POOL_BASE_USED) * frac), + ); +} + +/** Acquire queue wait (ms) on `pod` at `t`. Zero until the pod's pool is + * pinned; then grows super-linearly toward MAX_QUEUE_WAIT_MS at `now`. */ +function queueWaitMs(rng: Rng, nowMs: number, pod: number, t: number): number { + const full = podSaturationMs(nowMs, pod); + if (t < full) return rng.range(0.2, 2); // healthy acquire: sub-2ms + const frac = (t - full) / (nowMs - full); + const wait = Math.pow(frac, 1.5) * MAX_QUEUE_WAIT_MS; + return wait * rng.range(0.75, 1.25); +} + +/** Pending acquire requests gauge on `pod` at `t`. */ +function poolPending(rng: Rng, nowMs: number, pod: number, t: number): number { + const full = podSaturationMs(nowMs, pod); + if (t < full) return rng.next() < 0.05 ? 1 : 0; + const frac = (t - full) / (nowMs - full); + return Math.round(Math.pow(frac, 1.5) * 32 * rng.range(0.8, 1.2)); +} + +// ─── Metric generation ────────────────────────────────────────────────────── + +function generateMetrics(rng: Rng, nowMs: number): MetricBatch { + const windowStart = nowMs - HISTORY_WINDOW_MS; + const scrapeCount = Math.floor(HISTORY_WINDOW_MS / SCRAPE_INTERVAL_MS); + + const gauge: GaugeMetricRow[] = []; + const sum: SumMetricRow[] = []; + const histogram: HistogramMetricRow[] = []; + + const podResource = ( + service: string, + pod: number, + ): Record => ({ + 'service.name': service, + 'service.namespace': 'production', + 'k8s.namespace.name': 'production', + 'k8s.deployment.name': service, + 'k8s.pod.name': `${service}-7f${pod}d${pod * 3 + 1}c-${pod}q${pod + 4}z${pod * 2}`, + }); + const subjectPods = Array.from({ length: POD_COUNT }, (_, p) => + podResource(SUBJECT_SERVICE, p), + ); + const twinPods = Array.from({ length: 2 }, (_, p) => + podResource(TWIN_SERVICE, p), + ); + const neighborResource = podResource(NEIGHBOR_SERVICE, 0); + + let cumRequests = 0; + + for (let i = 0; i < scrapeCount; i++) { + const t = windowStart + i * SCRAPE_INTERVAL_MS; + + // ── order-api: the load-bearing pool gauges, per pod ───────────────── + for (let pod = 0; pod < POD_COUNT; pod++) { + const used = poolUsed(nowMs, pod, t); + const attrsBase = { 'pool.name': POOL_NAME, 'db.system': 'postgresql' }; + gauge.push( + makeGauge({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'db.client.connections.usage', + metricUnit: '{connection}', + metricDescription: 'Connections currently in use or idle, by state', + value: used, + resourceAttributes: subjectPods[pod], + attributes: { ...attrsBase, state: 'used' }, + }), + makeGauge({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'db.client.connections.usage', + metricUnit: '{connection}', + metricDescription: 'Connections currently in use or idle, by state', + value: POOL_MAX - used, + resourceAttributes: subjectPods[pod], + attributes: { ...attrsBase, state: 'idle' }, + }), + makeGauge({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'db.client.connections.max', + metricUnit: '{connection}', + metricDescription: 'Maximum configured pool size', + value: POOL_MAX, + resourceAttributes: subjectPods[pod], + attributes: attrsBase, + }), + makeGauge({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'db.client.connections.pending_requests', + metricUnit: '{request}', + metricDescription: + 'Requests currently waiting for an open connection', + value: poolPending(rng, nowMs, pod, t), + resourceAttributes: subjectPods[pod], + attributes: attrsBase, + }), + // Healthy infra gauges — rules out CPU/memory saturation. + makeGauge({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'system.cpu.utilization', + metricUnit: '1', + metricDescription: 'CPU utilization (0-1)', + value: Number(rng.range(0.18, 0.3).toFixed(3)), + resourceAttributes: subjectPods[pod], + attributes: { state: 'used' }, + }), + makeGauge({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'process.memory.usage', + metricUnit: 'By', + metricDescription: 'Process resident memory', + value: Math.round(rng.range(380, 430) * 1024 * 1024), + resourceAttributes: subjectPods[pod], + attributes: {}, + }), + ); + } + + // ── catalog-api: healthy pool TWIN (same metric names) ─────────────── + for (let pod = 0; pod < twinPods.length; pod++) { + const attrsBase = { + 'pool.name': 'catalog-pg', + 'db.system': 'postgresql', + }; + const used = rng.intRange(5, 11); + gauge.push( + makeGauge({ + timeUnixMs: t, + serviceName: TWIN_SERVICE, + metricName: 'db.client.connections.usage', + metricUnit: '{connection}', + metricDescription: 'Connections currently in use or idle, by state', + value: used, + resourceAttributes: twinPods[pod], + attributes: { ...attrsBase, state: 'used' }, + }), + makeGauge({ + timeUnixMs: t, + serviceName: TWIN_SERVICE, + metricName: 'db.client.connections.max', + metricUnit: '{connection}', + metricDescription: 'Maximum configured pool size', + value: POOL_MAX, + resourceAttributes: twinPods[pod], + attributes: attrsBase, + }), + makeGauge({ + timeUnixMs: t, + serviceName: TWIN_SERVICE, + metricName: 'db.client.connections.pending_requests', + metricUnit: '{request}', + metricDescription: + 'Requests currently waiting for an open connection', + value: 0, + resourceAttributes: twinPods[pod], + attributes: attrsBase, + }), + ); + } + + // ── inventory-service: nightly-batch CPU spike (red herring) ───────── + const inBatch = + t >= nowMs - BATCH_START_AGO_MS && t <= nowMs - BATCH_END_AGO_MS; + gauge.push( + makeGauge({ + timeUnixMs: t, + serviceName: NEIGHBOR_SERVICE, + metricName: 'system.cpu.utilization', + metricUnit: '1', + metricDescription: 'CPU utilization (0-1)', + value: Number( + (inBatch ? rng.range(0.85, 0.95) : rng.range(0.2, 0.3)).toFixed(3), + ), + resourceAttributes: neighborResource, + attributes: { state: 'used' }, + }), + ); + + // ── order-api request-duration histogram (delta) + flat traffic sum ── + // Aggregate across pods: sample the same per-request model the traces + // use so the two signals agree. + const samples: number[] = []; + for (let s = 0; s < ORDER_REQS_PER_SCRAPE; s++) { + const pod = s % POD_COUNT; + samples.push(rng.range(25, 220) + queueWaitMs(rng, nowMs, pod, t)); + } + histogram.push( + makeHistogram({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'http.server.request.duration', + metricUnit: 'ms', + metricDescription: 'HTTP server request duration', + aggregationTemporality: 1, + ...bucketize(samples, LATENCY_BOUNDS_MS), + explicitBounds: [...LATENCY_BOUNDS_MS], + resourceAttributes: { + 'service.name': SUBJECT_SERVICE, + 'service.namespace': 'production', + 'k8s.deployment.name': SUBJECT_SERVICE, + }, + attributes: {}, + }), + ); + // FLAT request-rate counter: the leak-vs-load discriminator. The + // pool climbs while this slope never changes. + cumRequests += ORDER_REQS_PER_SCRAPE; + sum.push( + makeSum({ + timeUnixMs: t, + serviceName: SUBJECT_SERVICE, + metricName: 'http.server.request.count', + metricDescription: 'Cumulative HTTP requests served', + value: cumRequests, + resourceAttributes: { + 'service.name': SUBJECT_SERVICE, + 'service.namespace': 'production', + 'k8s.deployment.name': SUBJECT_SERVICE, + }, + attributes: {}, + }), + ); + } + + return { gauge, sum, histogram }; +} + +// ─── Scenario ─────────────────────────────────────────────────────────────── + +const QUIET_MAX_TURNS = 26; +const SOFT_ANSWER_TURN_MARGIN = 8; + +const BUDGET_NOTE = ` +HARD BUDGETS: this run has a hard tool-call cap a few calls above the +soft checkpoint in the TURN BUDGET above, AND a hard wall-clock limit of +roughly five minutes. Neither budget waits for an unfinished +investigation — when either runs out, whatever you last wrote IS your +answer. You cannot see the wall clock; the only budget you can track is +your own tool-call count, so budget by COUNTING TOOL CALLS: +- Prefer aggregating queries over reading individual events. +- At the soft checkpoint, STOP opening new lines of investigation and + write the best-supported conclusion from the evidence you already have. +- Reserve the final turn for the answer — never let a verification query + be your last action. An answer grounded in partial evidence scores; an + unfinished investigation with no written answer scores zero.`; + +const JUDGE_PREAMBLE = `You are evaluating an SRE investigation. You will receive: +- the scenario question (what the candidate was asked) +- the ground-truth facts (the planted answer the candidate did NOT see) +- a rubric with weighted criteria +- the candidate's final answer (anonymized — tool names and product brands have been redacted so you cannot tell which tool the candidate used) + +For each rubric criterion, output an integer score from 0 to 5 plus a one-sentence rationale. Do not consider tool choice, query syntax, or implementation details — score only the quality of the candidate's final answer relative to the ground truth. + +SCORE ONLY WHAT IS WRITTEN. Credit a claim only if the candidate's answer +states it explicitly — never because the ground-truth facts contain it or +because the candidate seemed about to conclude it. Some answers are +truncated mid-investigation: a progress note, a plan, or a statement of +intent ("let me verify one more thing", "I now have the complete picture") +with no actual diagnosis. Such an answer scores 0 on every criterion +except conciseness (at most 1), no matter how promising the investigation +looked. + +Return STRICT JSON of shape: +{ "scores": { "": { "score": N, "rationale": "..." } } } +No prose outside the JSON. Include every criterion id from the rubric.`; + +export const quietSaturationScenario: Scenario = { + name: 'quiet-saturation', + agentPrompt: groundTruth.agentPrompt, + maxTurns: QUIET_MAX_TURNS, + description: + 'order-api DB connection-pool exhaustion via a slow leak: the orders.async-invoice ' + + 'feature flag goes 5%->100% 90 min ago and the flag-gated path leaks pooled ' + + 'connections; per-pod usage climbs monotonically to the 40-connection cap ' + + '(saturating 36-27 min ago), after which every request queues on acquire — ' + + 'UNIFORM latency creep across all routes with fast db.query children, and 30s ' + + 'acquire-timeout 503s in the final 12 min. The metrics-are-the-fast-path middle ' + + 'tier between metric-saturation (metrics forced) and deploy-regression (metrics ' + + 'redundant): both solve paths reach the full answer, but pool gauges + the flat ' + + 'request-count sum crack it in a handful of calls while the trace/log grind is ' + + 'viable but slow. Distractors: innocent notification-service deploy near the ' + + 'visible onset, inventory-service nightly-batch CPU spike, a healthy catalog-api ' + + 'pool twin with identical metric names, constant caught-exception noise, and the ' + + 'DB-is-slow trap (queries stay fast; the wait is client-side).', + buildSystemPrompt: ctx => { + const softAnswerTurn = Math.max( + 10, + (ctx.maxTurns ?? QUIET_MAX_TURNS) - SOFT_ANSWER_TURN_MARGIN, + ); + return ( + buildInvestigationSystemPrompt( + 'quiet-saturation', + ctx.anchorTimeIso, + ctx.variant, + softAnswerTurn, + { + // Byte-identical to metric-saturation / deploy-regression: + // discoverability is held constant across scenarios so adoption + // deltas measure inclination, not awareness. + signalsNote: + '- Metrics: a HyperDX metric source is available (gauge, sum, ' + + 'histogram, exponential histogram, and summary). Use the metric ' + + 'tools to explore it alongside traces and logs.', + }, + ) + BUDGET_NOTE + ); + }, + judgeSystemPreamble: JUDGE_PREAMBLE, + *generate(ctx): Iterable { + const { rng, nowMs } = ctx; + const factor = ctx.volumeFactor ?? 1; + const batchSize = ctx.batchSize ?? 10_000; + const windowStart = nowMs - HISTORY_WINDOW_MS; + const flagFlipMs = nowMs - FLAG_FLIP_AGO_MS; + + // Metrics first (fixed volume — the load-bearing signal never scales). + const metrics = generateMetrics(rng, nowMs); + yield { traces: [], logs: [], metrics }; + + const pinDeployment = (r: Record) => ({ + ...r, + 'service.namespace': 'production', + 'k8s.namespace.name': 'production', + 'deployment.environment.name': 'production', + 'cloud.region': 'us-east-1', + }); + const pinNode = ( + attrs: Record, + poolName: string, + ): Record => { + const node = `gke-prod-${poolName}-${rng.hex(8)}-${rng.hex(4)}`; + return { ...attrs, 'k8s.node.name': node, 'host.name': node }; + }; + + const orderPods = buildResourcePool({ + rng, + services: [SUBJECT_SERVICE], + instancesPerService: POD_COUNT, + })[SUBJECT_SERVICE].map(r => + pinNode( + pinDeployment({ ...r, 'telemetry.sdk.language': 'nodejs' }), + 'order', + ), + ); + + const notifyPods = buildResourcePool({ + rng, + services: [NOTIFY_SERVICE], + instancesPerService: NOTIFY_POD_COUNT, + })[NOTIFY_SERVICE].map(r => pinNode(pinDeployment(r), 'notify')); + const notifyVersion = (pod: number, t: number): string => + t >= nowMs - NOTIFY_DEPLOY_AGO_MS + pod * NOTIFY_ROLLOUT_STAGGER_MS + ? NOTIFY_NEW_VERSION + : NOTIFY_OLD_VERSION; + + const resourcePool = buildResourcePool({ + rng, + services: [PROXY_SERVICE, TWIN_SERVICE, NEIGHBOR_SERVICE], + instancesPerService: 8, + }); + + // ── Trace floor: order-api requests with acquire/query children ────── + const totalTraces = Math.max(50, Math.round(TOTAL_TRACES * factor)); + const traces: TraceRow[] = []; + const plantedLogs: LogRow[] = []; + + for (let i = 0; i < totalTraces; i++) { + const t = spreadTimestamp(i, totalTraces, windowStart, HISTORY_WINDOW_MS); + const kind = rng.weightedPick(TRAFFIC_MIX); + + if (kind === 'catalog') { + traces.push( + makeSpan({ + rng, + timestampMs: t, + traceId: newTraceId(rng), + spanId: newSpanId(rng), + spanName: 'GET /api/catalog/search', + spanKind: 'SPAN_KIND_SERVER', + serviceName: TWIN_SERVICE, + durationNs: msToNs(rng.range(10, 90)), + resourceAttributes: pickResource(rng, resourcePool, TWIN_SERVICE), + spanAttributes: { + 'http.route': '/api/catalog/search', + 'http.request.method': 'GET', + 'http.response.status_code': '200', + }, + }), + ); + } else if (kind === 'notify') { + const pod = rng.intRange(0, NOTIFY_POD_COUNT); + traces.push( + makeSpan({ + rng, + timestampMs: t, + traceId: newTraceId(rng), + spanId: newSpanId(rng), + spanName: 'notification.send', + spanKind: 'SPAN_KIND_SERVER', + serviceName: NOTIFY_SERVICE, + durationNs: msToNs(rng.range(12, 80)), + resourceAttributes: { + ...notifyPods[pod], + 'service.version': notifyVersion(pod, t), + }, + spanAttributes: { + 'messaging.system': 'sns', + 'notification.channel': rng.pick(['email', 'push', 'sms']), + }, + }), + ); + } else { + // order-api request + const pod = rng.intRange(0, POD_COUNT); + const resourceAttributes = orderPods[pod]; + const route = + kind === 'order_create' + ? '/api/orders' + : kind === 'order_get' + ? '/api/orders/{orderId}' + : '/api/cart'; + const method = kind === 'order_create' ? 'POST' : 'GET'; + const spanName = `${method} ${route}`; + + const baseMs = + kind === 'order_create' ? rng.range(60, 250) : rng.range(20, 120); + const waitMs = queueWaitMs(rng, nowMs, pod, t); + const queryMs = rng.range(5, 25); // the DB stays fast — always + + // Acquire-timeout failures: saturated pod, final window only. + const saturated = t >= podSaturationMs(nowMs, pod); + const inTimeoutWindow = t >= nowMs - TIMEOUT_ERRORS_AGO_MS; + const timedOut = + saturated && inTimeoutWindow && rng.next() < TIMEOUT_FRACTION; + + const traceId = newTraceId(rng); + const rootSpanId = newSpanId(rng); + + if (timedOut) { + // The request spends the full acquire timeout waiting, then 503s. + const totalMs = ACQUIRE_TIMEOUT_MS + rng.range(5, 40); + traces.push( + makeSpan({ + rng, + timestampMs: t, + traceId, + spanId: rootSpanId, + spanName, + spanKind: 'SPAN_KIND_SERVER', + serviceName: SUBJECT_SERVICE, + durationNs: msToNs(totalMs), + statusCode: 'STATUS_CODE_ERROR', + statusMessage: 'connection acquisition timeout', + resourceAttributes, + spanAttributes: { + 'http.route': route, + 'http.request.method': method, + 'http.response.status_code': '503', + }, + }), + makeSpan({ + rng, + timestampMs: t + 1, + traceId, + spanId: newSpanId(rng), + parentSpanId: rootSpanId, + spanName: 'db.pool.acquire', + spanKind: 'SPAN_KIND_INTERNAL', + serviceName: SUBJECT_SERVICE, + durationNs: msToNs(ACQUIRE_TIMEOUT_MS), + statusCode: 'STATUS_CODE_ERROR', + statusMessage: 'timed out waiting for connection', + resourceAttributes, + spanAttributes: { + 'db.system': 'postgresql', + 'pool.name': POOL_NAME, + }, + }), + ); + plantedLogs.push( + makeLog({ + timestampMs: t + ACQUIRE_TIMEOUT_MS, + traceId, + spanId: rootSpanId, + serviceName: SUBJECT_SERVICE, + severityText: 'ERROR', + body: TIMEOUT_LOG_BODY(rng.intRange(14, 34)), + resourceAttributes, + logAttributes: { + 'event.name': 'db.pool.acquire_timeout', + 'pool.name': POOL_NAME, + 'db.system': 'postgresql', + 'http.route': route, + 'log.iostream': 'stderr', + }, + }), + ); + } else { + const totalMs = baseMs + waitMs + queryMs; + traces.push( + makeSpan({ + rng, + timestampMs: t, + traceId, + spanId: rootSpanId, + spanName, + spanKind: 'SPAN_KIND_SERVER', + serviceName: SUBJECT_SERVICE, + durationNs: msToNs(totalMs), + resourceAttributes, + spanAttributes: { + 'http.route': route, + 'http.request.method': method, + 'http.response.status_code': '200', + ...(kind === 'order_create' + ? { + 'order.items': String(rng.intRange(1, 9)), + 'order.total_cents': String(rng.intRange(999, 74999)), + } + : {}), + }, + }), + // Child 1: pool acquire — THE growing wait (client-side). + makeSpan({ + rng, + timestampMs: t + 1, + traceId, + spanId: newSpanId(rng), + parentSpanId: rootSpanId, + spanName: 'db.pool.acquire', + spanKind: 'SPAN_KIND_INTERNAL', + serviceName: SUBJECT_SERVICE, + durationNs: msToNs(waitMs), + resourceAttributes, + spanAttributes: { + 'db.system': 'postgresql', + 'pool.name': POOL_NAME, + }, + }), + // Child 2: the actual query — fast the whole time (the DB + // itself is healthy; "Postgres is slow" is a trap). + makeSpan({ + rng, + timestampMs: t + 2 + Math.floor(waitMs), + traceId, + spanId: newSpanId(rng), + parentSpanId: rootSpanId, + spanName: + kind === 'order_create' ? 'INSERT orders' : 'SELECT orders', + spanKind: 'SPAN_KIND_CLIENT', + serviceName: SUBJECT_SERVICE, + durationNs: msToNs(queryMs), + resourceAttributes, + spanAttributes: { + 'db.system': 'postgresql', + 'db.name': 'orders', + 'server.address': 'orders-pg.prod.internal', + }, + }), + ); + // Post-flip: the flag-gated async-invoice child appears — a NEW + // span name whose first occurrence marks the flip boundary. + if (kind === 'order_create' && t >= flagFlipMs) { + traces.push( + makeSpan({ + rng, + timestampMs: t + 4 + Math.floor(waitMs), + traceId, + spanId: newSpanId(rng), + parentSpanId: rootSpanId, + spanName: 'invoice.render_async', + spanKind: 'SPAN_KIND_INTERNAL', + serviceName: SUBJECT_SERVICE, + durationNs: msToNs(rng.range(25, 80)), + resourceAttributes, + spanAttributes: { + 'feature_flag.key': FLAG_KEY, + 'invoice.format': 'pdf', + }, + }), + ); + } + } + } + + if (traces.length >= batchSize) { + yield { traces: traces.splice(0, traces.length), logs: [] }; + } + if (plantedLogs.length >= batchSize) { + yield { traces: [], logs: plantedLogs.splice(0, plantedLogs.length) }; + } + } + if (traces.length) + yield { traces: traces.splice(0, traces.length), logs: [] }; + + // ── Log floor ───────────────────────────────────────────────────────── + const totalLogs = Math.max(50, Math.round(TOTAL_LOGS * factor)); + const logs: LogRow[] = []; + for (let i = 0; i < totalLogs; i++) { + const t = spreadTimestamp( + i, + totalLogs, + windowStart, + HISTORY_WINDOW_MS, + 60_000, + ); + const kind = rng.weightedPick(LOG_MIX); + let service: string; + let resourceAttributes: Record; + let body: string; + let attrs: Record; + let sevText: string; + + if (kind === 'cache_hit' || kind === 'caught_exception') { + service = SUBJECT_SERVICE; + resourceAttributes = orderPods[rng.intRange(0, POD_COUNT)]; + const tmpl = + kind === 'cache_hit' + ? cacheHitLog({ rng, nowMs: t }) + : caughtExceptionLog({ rng, nowMs: t }); + body = tmpl.body; + attrs = tmpl.attrs; + sevText = tmpl.level; + } else if (kind === 'envoy' || kind === 'health_probe') { + service = PROXY_SERVICE; + resourceAttributes = pickResource(rng, resourcePool, PROXY_SERVICE); + const tmpl = + kind === 'envoy' + ? envoyAccessLog({ rng, nowMs: t }) + : upstreamHealthProbeLog({ rng, nowMs: t }); + body = tmpl.body; + attrs = tmpl.attrs; + sevText = 'info'; + } else { + service = NEIGHBOR_SERVICE; + resourceAttributes = pickResource(rng, resourcePool, NEIGHBOR_SERVICE); + const tmpl = serviceOpsDebugLog({ + rng, + nowMs: t, + serviceName: 'inventory-service', + }); + body = tmpl.body; + attrs = tmpl.attrs; + sevText = tmpl.level; + } + + logs.push( + makeLog({ + timestampMs: t, + serviceName: service, + severityText: normalizeSeverityText(sevText), + body, + resourceAttributes, + logAttributes: { ...attrs, _severity_raw: sevText }, + }), + ); + if (logs.length >= batchSize) { + yield { traces: [], logs: logs.splice(0, logs.length) }; + } + } + + // ── Planted events (fixed volume) ───────────────────────────────────── + + // The trigger: a single feature-flag change event at the leak onset. + plantedLogs.push( + makeLog({ + timestampMs: flagFlipMs, + serviceName: SUBJECT_SERVICE, + severityText: 'INFO', + body: FLAG_FLIP_BODY, + resourceAttributes: { + 'service.name': SUBJECT_SERVICE, + 'k8s.deployment.name': SUBJECT_SERVICE, + }, + logAttributes: { + 'event.name': 'feature_flag.update', + 'feature_flag.key': FLAG_KEY, + 'feature_flag.variant': '100%', + }, + }), + ); + + // Innocent notification-service rollout (near the VISIBLE onset). + const notifyDeployMs = nowMs - NOTIFY_DEPLOY_AGO_MS; + plantedLogs.push( + makeLog({ + timestampMs: notifyDeployMs, + serviceName: NOTIFY_SERVICE, + severityText: 'INFO', + body: `Deployment notification-service rolling update started: version ${NOTIFY_OLD_VERSION} -> ${NOTIFY_NEW_VERSION} (target ${NOTIFY_POD_COUNT} replicas)`, + resourceAttributes: { + 'service.name': NOTIFY_SERVICE, + 'k8s.deployment.name': NOTIFY_SERVICE, + }, + logAttributes: { + 'event.name': 'deployment.rollout', + 'service.version': NOTIFY_NEW_VERSION, + }, + }), + ); + for (let pod = 0; pod < NOTIFY_POD_COUNT; pod++) { + plantedLogs.push( + makeLog({ + timestampMs: notifyDeployMs + pod * NOTIFY_ROLLOUT_STAGGER_MS, + serviceName: NOTIFY_SERVICE, + severityText: 'INFO', + body: `Pod ${notifyPods[pod]['k8s.pod.name']} updated to version ${NOTIFY_NEW_VERSION} (${pod + 1}/${NOTIFY_POD_COUNT} pods updated)`, + resourceAttributes: notifyPods[pod], + logAttributes: { + 'event.name': 'deployment.rollout', + 'service.version': NOTIFY_NEW_VERSION, + 'k8s.pod.name': notifyPods[pod]['k8s.pod.name'], + }, + }), + ); + } + plantedLogs.push( + makeLog({ + timestampMs: + notifyDeployMs + NOTIFY_POD_COUNT * NOTIFY_ROLLOUT_STAGGER_MS, + serviceName: NOTIFY_SERVICE, + severityText: 'INFO', + body: `Rollout notification-service completed: ${NOTIFY_POD_COUNT}/${NOTIFY_POD_COUNT} pods updated to version ${NOTIFY_NEW_VERSION}`, + resourceAttributes: { + 'service.name': NOTIFY_SERVICE, + 'k8s.deployment.name': NOTIFY_SERVICE, + }, + logAttributes: { + 'event.name': 'deployment.rollout', + 'service.version': NOTIFY_NEW_VERSION, + }, + }), + ); + + // Nightly batch markers bracketing the inventory CPU spike. + plantedLogs.push( + makeLog({ + timestampMs: nowMs - BATCH_START_AGO_MS, + serviceName: NEIGHBOR_SERVICE, + severityText: 'INFO', + body: 'Nightly inventory reconciliation batch started (full-catalog scan)', + resourceAttributes: { 'service.name': NEIGHBOR_SERVICE }, + logAttributes: { 'event.name': 'batch.reconciliation.start' }, + }), + makeLog({ + timestampMs: nowMs - BATCH_END_AGO_MS, + serviceName: NEIGHBOR_SERVICE, + severityText: 'INFO', + body: 'Nightly inventory reconciliation batch completed in 900s (2,314,882 SKUs)', + resourceAttributes: { 'service.name': NEIGHBOR_SERVICE }, + logAttributes: { 'event.name': 'batch.reconciliation.end' }, + }), + ); + + if (logs.length || plantedLogs.length) { + yield { traces: [], logs: [...logs, ...plantedLogs] }; + } + }, + groundTruth, +}; diff --git a/packages/hdx-eval/src/scenarios/quiet-saturation/ground-truth.json b/packages/hdx-eval/src/scenarios/quiet-saturation/ground-truth.json new file mode 100644 index 0000000000..0c43b7a785 --- /dev/null +++ b/packages/hdx-eval/src/scenarios/quiet-saturation/ground-truth.json @@ -0,0 +1,194 @@ +{ + "scenario": "quiet-saturation", + "agentPrompt": "Customers are complaining that the storefront has been getting slower over the past half hour — order pages take noticeably longer to load, and in the last few minutes a handful of orders have failed outright. Figure out what's going on and explain the mechanism.", + "expected": { + "affectedService": "order-api", + "rootCause": "order-api's Postgres connection pool ('orders-pg', 40 connections per pod, 4 pods) is exhausted by a connection LEAK, not by load. 90 minutes ago the orders.async-invoice feature flag was rolled from 5% to 100%; the flag-gated async-invoice path acquires a pooled connection and never releases it. Per-pod pool usage climbs monotonically from ~8 toward the 40-connection cap and pins at 40/40 between 36 and 27 minutes ago (staggered by traffic). Once a pod's pool is pinned, every request on that pod queues waiting for a connection before any query runs — latency creeps up uniformly across ALL order-api routes while the database itself stays fast (query spans hold at 5-25ms). In the final ~12 minutes, acquire waits started hitting the 30s pool timeout, producing a trickle of 503s with ~30,000ms durations and ERROR logs carrying the pool stats.", + "mechanismChain": [ + "The feature_flag.update event (orders.async-invoice 5% -> 100%) lands exactly at the onset of the db.client.connections.usage{state=used} climb, 90 minutes before now — the timing join that attributes the leak to the flag-gated path. After the flip, the new invoice.render_async span appears under POST /api/orders.", + "Pool usage climbs MONOTONICALLY on every order-api pod — it never dips even though http.server.request.count's slope (traffic) is completely flat. Held connections that never return to the pool are a leak; increased demand would track load. This leak-vs-load discrimination is the core inference.", + "Each pod pins at 40/40 (db.client.connections.max = 40) between 36 and 27 minutes ago; db.client.connections.pending_requests lifts off zero at the same moments — the pool is the bottleneck, and the ceiling is 40.", + "From saturation onward, every request queues at acquire time BEFORE any query executes: db.pool.acquire child spans grow from sub-2ms into the seconds while db.query children (INSERT/SELECT orders) stay at 5-25ms throughout. The wait is client-side; Postgres is healthy. Because the wait precedes every DB operation, ALL routes slow together — the uniformity is the signature of pool starvation, not a slow endpoint.", + "In the last ~12 minutes acquire waits reach the 30s pool timeout: POST/GET requests fail with 503 and a distinctive ~30,000ms duration, and order-api logs 'Timeout: failed to acquire connection from pool orders-pg within 30000ms (pool size 40, in use 40, ...)' ERROR lines, trace-correlated to the failing spans." + ], + "loadBearingSignal": "metrics-fast-path", + "whyMetricsFaster": "Both solve paths reach the full answer, but they are not equally priced. METRIC PATH (~5-7 calls): db.client.connections.usage grouped by pod shows the monotonic climb pinned at 40/40 with its onset at the flag flip; db.client.connections.max names the ceiling; pending_requests lifts off at saturation; http.server.request.count's flat slope rules out a traffic spike; cpu/memory gauges rule out infra — then one log query finds the feature_flag.update event at the climb onset. TRACE/LOG PATH (viable but ~12-18 calls): notice all routes slowed together, open slow-trace waterfalls to find db.pool.acquire dominating while db.query stays fast, find the late acquire-timeout ERROR logs (which state the pool stats but only exist for the final 12 minutes), then reconstruct the onset and the flat-traffic fact with several more windowed aggregations. The pool's 90-minute history — when the climb started, that it is monotonic, and that traffic never changed — is cheap in metrics and expensive everywhere else.", + "metricsRole": { + "gauge": "db.client.connections.usage{state=used} per pod is THE story: flat at ~8 until the flag flip, monotonic climb to 40, pinned there from ~30 min ago. db.client.connections.max (40) names the ceiling; db.client.connections.pending_requests lifts off zero at saturation. system.cpu.utilization and process.memory.usage stay flat on order-api (rules out infra). catalog-api publishes the same db.client.* metric names with a healthy ~8/40 pool — filtering by service is required. inventory-service's CPU spike (0.85-0.95, T-60m to T-45m) is the nightly reconciliation batch, a red herring.", + "sum": "http.server.request.count (cumulative) has a perfectly constant slope across the whole window — the leak-vs-load discriminator. A traffic surge would bend it; nothing does.", + "histogram": "http.server.request.duration shifts right starting ~30 min ago and keeps degrading — corroborates the visible onset support reported, which is the SATURATION time, not the leak start.", + "adoptionNote": "This scenario is the 'metrics are the fast path' middle tier: metric use is neither forced (metric-saturation) nor redundant (deploy-regression). The adoption SCORE is driven solely by queried_pool_metrics — the load-bearing signal. queried_supporting_metrics is informational (reported, not scored): its facts have cheaper trace-side substitutes (span counts for traffic, span quantiles for latency), so efficient agents legitimately skip those metric names and still deserve 100% adoption. Efficiency is read from the tool-calls and wall-clock columns alongside the score." + } + }, + "distractors": [ + { + "kind": "innocent completed deploy near the VISIBLE onset", + "service": "notification-service", + "minutesAgo": 40, + "whyNotRootCause": "notification-service rolled 2.14.0 -> 2.15.0 starting 40 min ago and completed 3/3 pods by 37 min ago — right next to the visible latency onset (~30 min ago), which makes it the tempting 'a deploy just happened' answer. But notification.send spans are fast and error-free on both versions, notification-service is not in the order path's synchronous chain, and the pool climb began 90 minutes ago — 50 minutes BEFORE this rollout started." + }, + { + "kind": "co-timed CPU spike on a neighbor (alarm bait)", + "service": "inventory-service", + "minutesAgo": 60, + "durationMinutes": 15, + "whyNotRootCause": "inventory-service CPU jumps to 0.85-0.95 from T-60m to T-45m — visually the most alarming chart in the window. It is the nightly reconciliation batch, bracketed by INFO start/complete events, ends before the pools saturate, and touches nothing in the order path." + }, + { + "kind": "healthy pool twin (same metric names)", + "service": "catalog-api", + "whyNotRootCause": "catalog-api publishes the identical db.client.connections.* metric names against its own 'catalog-pg' pool, holding steady at ~8/40 with zero pending requests. A keyword hunt for connection-pool metrics returns two services; only per-service filtering isolates order-api." + }, + { + "kind": "the database-is-slow trap", + "service": "order-api", + "whyNotRootCause": "Every db.query child span (INSERT orders / SELECT orders) stays at 5-25ms through the entire incident — Postgres is never the bottleneck. The added time lives exclusively in db.pool.acquire, client-side, before any query runs. Blaming 'the database is overloaded' inverts the mechanism and is a calibration failure." + }, + { + "kind": "constant-rate caught-exception noise", + "service": "order-api", + "pattern": "NonFatalRetryableError (caught) worker stack traces", + "whyNotRootCause": "An error-looking log pattern that exists at the SAME steady rate before and after every boundary in the scenario, marked handled, with no trace correlation to slow or failing requests." + }, + { + "kind": "infra saturation (ruled out)", + "service": "order-api", + "whyNotRootCause": "order-api CPU (~24%) and process memory (~400MB) are flat and healthy throughout. The resource that saturates is the CONNECTION POOL, a configured application-level limit — not the host." + } + ], + "rubric": { + "programmatic": [ + ["names_affected_service", 1, "order-api"], + [ + "names_pool_exhaustion", + 3, + "(connection|conn|db)[- ]?pool[^.\\n]{0,60}?(exhaust|saturat|full|maxed|pinned|starv|at (its )?(cap|capacity|limit|max)|bottleneck)|pool[^.\\n]{0,50}?(exhaust|saturat|maxed|starv|pinned)|40\\s*/\\s*40|(all|every)[^.\\n]{0,30}?connections?[^.\\n]{0,30}?(in use|used|busy|held|taken)|exhaust(ed|ion)?[^.\\n]{0,40}?(connection|pool)" + ], + [ + "names_leak_mechanism", + 2, + "leak|never (releas|return|freed|give[sn]? back)|not (releas|return)|without releasing|fail(s|ed|ing)? to release|(held|kept|retained)[^.\\n]{0,40}?(indefinitely|forever|never)|monotonic" + ], + [ + "ties_onset_to_flag", + 2, + "async[- _]?invoice|orders\\.async|feature[- _]?flag[^.\\n]{0,80}?(100\\s?%|roll|flip|enabl|updat)|flag[^.\\n]{0,40}?(100\\s?%|flip|roll|enabl)|ORD-4112" + ], + [ + "cites_pool_ceiling", + 1, + "\\b40\\b[^.\\n]{0,40}?(connection|conn\\b|pool|cap\\b|capacity|max|limit)|(connection|conn\\b|pool|cap\\b|capacity|max|limit)[^.\\n]{0,40}?\\b40\\b" + ], + [ + "names_acquire_wait", + 2, + "pool\\.acquire|acquir(e|ing|ition)[^.\\n]{0,50}?(wait|queue|block|stall|time)|wait(ing)?[^.\\n]{0,50}?(for|on)[^.\\n]{0,20}?connection|queu(e|ed|ing)[^.\\n]{0,50}?(connection|acquire|pool)|(blocked|stalled)[^.\\n]{0,40}?(pool|connection)" + ], + [ + "notes_db_fast", + 2, + "(quer(y|ies)|database|postgres|db)\\b[^.\\n]{0,70}?(fast|quick|healthy|normal|fine|unchanged|not slow|not the bottleneck|stay(ed|s)? (at |around )?\\d)|not[^.\\n]{0,40}?(database|postgres|db server)[^.\\n]{0,40}?(slow|problem|fault|bottleneck|overload)|(wait|latency|delay|time)[^.\\n]{0,60}?(client[- ]side|before (the|any|a) quer|in the pool|acquiring)" + ], + [ + "names_uniform_latency", + 1, + "(all|every|each)\\s[^.\\n]{0,25}?(endpoint|route|operation)|every (request|order)[^.\\n]{0,50}?(queue|wait|block|stall|slow)|uniform|across[- ]the[- ]board|board[- ]wide|(no single|not (just |only )?one)[^.\\n]{0,30}?(route|endpoint|operation)|/api/orders[^\\n]{0,120}?/api/cart|/api/cart[^\\n]{0,120}?/api/orders|everything that (needs|uses|touches|acquires)" + ], + [ + "distinguishes_true_onset", + 2, + "(90|ninety)[- ](min|minute)|1\\.5[- ]?h|hour[- ]and[- ]a[- ]half|an hour (and a half|before)|(climb|leak|usage|pool)[^.\\n]{0,70}?(began|start|onset)[^.\\n]{0,60}?(before|earlier|90|flag|flip)|(long|well|far) before[^.\\n]{0,60}?(latency|slow|symptom|visible|users? notic)|(fill|drain|climb|leak|grow|grew|accumulat|ramp)\\w*[^.\\n]{0,70}?(over|for|across)[^.\\n]{0,25}?(the next |about |~ ?|roughly |nearly )?(an |one |1 )?hour|(climb|leak|accumulat|drain|fill|ramp|grew|grow)\\w*[^\\n]{0,100}?(until|then|before)[^\\n]{0,90}?(pinn?|hit|reach|saturat|cap\\b|max\\b|40/40)|(flag|flip|100\\s?%)[^\\n]{0,200}?(pinn?ed|hit (the |its )?(cap|max)|fill(ed|s)? (up|the pool)|saturat|40/40|max(ed)? out)|(flat|steady|baseline)[^\\n]{0,60}?(then|until)[^\\n]{0,50}?(climb|rise|rose|grew|ramp)|\\d{1,2}:\\d{2}[^\\n]{0,12}?(\u2192|->|to|\u2013)[^\\n]{0,12}?~?\\d{1,2}:\\d{2}[^\\n]{0,140}?(climb|fill|leak|ramp|drain|pinn?|cap|40)" + ], + [ + "notes_flat_traffic", + 2, + "(traffic|request (rate|count|volume)|load|throughput|rps|qps)[^.\\n]{0,70}?(flat|steady|constant|unchanged|stable|did ?n[o']?t (change|increase|grow|spike)|no (spike|increase|surge|change))|(no|not a|rul(e|ed|ing) out)[^.\\n]{0,40}?(traffic|load|demand)[^.\\n]{0,30}?(spike|increase|surge|growth)" + ], + [ + "cites_timeout_errors", + 1, + "30[,_ ]?000\\s?ms|30\\s?s(ec(ond)?s?)?\\b[^.\\n]{0,50}?(timeout|acquire|wait)|(acquire|acquisition)[- _]?timeout|timed? ?out[^.\\n]{0,50}?(acquir|connection|pool)|503" + ], + [ + "rules_out_deploy", + 1, + "notification[- ]service[^\\n]{0,140}?(innocent|unrelated|healthy|benign|not (the )?(cause|culprit|related)|ruled? out|red herring|coinciden|predates|error[- ]?free|clean)|(deploy|roll[- ]?out|2\\.15\\.0)[^\\n]{0,60}?notification[^\\n]{0,100}?(innocent|unrelated|healthy|benign|ruled? out|coinciden|not)|(leak|climb|pool usage)[^\\n]{0,80}?(began|started|predates)[^\\n]{0,60}?(before|prior to)[^\\n]{0,50}?(deploy|roll[- ]?out)" + ], + [ + "false_blame_deploy", + 2, + "(?