From 95fd4c63742bbb10f3cb68f8d5487e40cd9e7ecb Mon Sep 17 00:00:00 2001 From: "wujiaming.ai" Date: Mon, 2 Nov 2026 11:33:27 +0800 Subject: [PATCH 1/3] fix(tracing): record standard streaming TTFT telemetry Add the actual SDK streaming flag and seconds-valued TTFT to per-request LLM spans, and record the existing TTFT histogram once at first output. Preserve legacy timestamps, omit absent observations, and keep metrics independent of usage and trace sampling. Add regression coverage and synchronize bilingual tracing documentation. Validation after rebase: 156 affected tests and pre-commit pass. Default regression: 8044 pass; one pre-existing Markdown MIME test still fails. Change-Id: If7113949389b8c5707feb20b8c67479700f0f19b --- docs/content/docs/framework/tracing.en.mdx | 8 +- docs/content/docs/framework/tracing.mdx | 6 +- .../apmplus-ttft/2026-11-02-apmplus-ttft.md | 126 ++++++++ .../2026-11-02-apmplus-ttft.zh.md | 126 ++++++++ .../2026-10-28-first-token-timestamps.md | 3 + .../2026-10-28-first-token-timestamps.zh.md | 3 + specs/model-timing/README.md | 16 +- specs/model-timing/README.zh.md | 16 +- tests/models/test_model_timing_adapters.py | 19 ++ tests/test_model_ttft.py | 285 ++++++++++++++++++ veadk/tracing/telemetry/portal_metrics.py | 21 +- veadk/tracing/telemetry/timing.py | 33 +- 12 files changed, 643 insertions(+), 19 deletions(-) create mode 100644 prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md create mode 100644 prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md create mode 100644 tests/test_model_ttft.py diff --git a/docs/content/docs/framework/tracing.en.mdx b/docs/content/docs/framework/tracing.en.mdx index 5b69bad3d..ffe573483 100644 --- a/docs/content/docs/framework/tracing.en.mdx +++ b/docs/content/docs/framework/tracing.en.mdx @@ -191,7 +191,7 @@ In a multi-agent scenario, spans are linked through `parent_span_id`, showing th ## Request, model, and first-token timestamps -VeADK's default LiteLLM and Ark Responses adapters add the following extension attributes to model spans when OpenTelemetry tracing is enabled. UTC Unix nanoseconds are used throughout. +VeADK's default LiteLLM and Ark Responses adapters add the following extension attributes to model spans when OpenTelemetry tracing is enabled. Timestamp attributes use UTC Unix nanoseconds. | Attribute | Meaning | | --- | --- | @@ -205,4 +205,8 @@ VeADK's default LiteLLM and Ark Responses adapters add the following extension a First-token capture excludes role/id/signature metadata, empty deltas, usage, heartbeats, and completion-only aggregates. It does not require token usage or content tracing. One chunk may contain several tokens, so this is an SDK-observed first-output timestamp. Non-streaming calls have no first-token timestamp; completion time is never substituted. -Each SDK request creates a `model_request` child span; the owning model span also receives the latest attempt's fields. VeADK-issued retries and fallbacks create separate attempts. Internal LiteLLM/provider retries remain within the observed SDK request (`veadk.model.request_scope=sdk_request`). Unsupported external/custom engines are explicitly marked; invocation span start is not used as model start. Applications outside the VeADK HTTP factories must install the request timing middleware or use VeADK Runner to establish a request timestamp. Client-render timing and TTFT/TPOT histogram reporting are separate capabilities. +Each SDK request creates a `model_request` child span; the owning model span also receives the latest attempt's custom timestamp/status fields. VeADK-issued retries and fallbacks create separate attempts. Internal LiteLLM/provider retries remain within the observed SDK request (`veadk.model.request_scope=sdk_request`). Unsupported external/custom engines are explicitly marked; invocation span start is not used as model start. Applications outside the VeADK HTTP factories must install the request timing middleware or use VeADK Runner to establish a request timestamp. Client-render timing and TPOT histogram reporting are separate capabilities. + +Each instrumented `model_request` child is labeled `gen_ai.span.kind=llm` and carries Boolean `gen_ai.request.stream` from the actual SDK request. When the first generated delta arrives, it also carries floating-point `gen_ai.chat_completions.streaming_time_to_first_token` in seconds: `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9`. These standard fields describe the individual SDK request, not the outer `call_llm` aggregate. Existing custom timestamps and legacy attributes remain available. + +The same observation is recorded once in the `gen_ai.chat_completions.streaming_time_to_first_token` Histogram, unit `s`, through the existing global MeterProvider. Metrics do not require token usage or a sampled trace; export still requires a configured metrics pipeline. Dimensions are `gen_ai.request.model` (the actual requested model) and `gen_ai.operation.name=chat`. Non-streaming, no-output, and unsupported requests produce no TTFT sample or attribute. Negative wall-clock intervals are omitted with a diagnostic; genuine zero elapsed time is valid. Retries/fallbacks have separate observations, and values observed before cancellation or failure remain recorded. diff --git a/docs/content/docs/framework/tracing.mdx b/docs/content/docs/framework/tracing.mdx index a03ca75ee..e16edcaa0 100644 --- a/docs/content/docs/framework/tracing.mdx +++ b/docs/content/docs/framework/tracing.mdx @@ -203,4 +203,8 @@ Tracing 数据由一系列 **Span** 组成，每个 Span 记录一次操作（ 首 Token 采集排除角色/id/签名元数据、空增量、usage、心跳和仅完成时返回的聚合内容。不依赖 token usage 或内容采集。一个 chunk 可含多个 token，因此这里表示 SDK 侧观测到首输出的时间。非流式调用没有首 Token 时间戳，不能用响应完成时间替代。 -每次 SDK 请求建立 `model_request` 子 Span，所属模型 Span 同时记录最近一次尝试的字段。VeADK 发起的重试和 fallback 分别记录尝试；LiteLLM/Provider 内部重试计入所观测的 SDK 请求（`veadk.model.request_scope=sdk_request`）。不支持的外部/自定义引擎明确标记，不用 invocation Span 起点替代模型开始。未使用 VeADK HTTP 工厂的应用需要安装请求计时中间件或使用 VeADK Runner，才能建立请求时间戳。客户端渲染计时和 TTFT/TPOT 直方图上报属于独立能力。 +每次 SDK 请求建立 `model_request` 子 Span，所属模型 Span 同时记录最近一次尝试的自定义时间戳/状态字段。VeADK 发起的重试和 fallback 分别记录尝试；LiteLLM/Provider 内部重试计入所观测的 SDK 请求（`veadk.model.request_scope=sdk_request`）。不支持的外部/自定义引擎明确标记，不用 invocation Span 起点替代模型开始。未使用 VeADK HTTP 工厂的应用需要安装请求计时中间件或使用 VeADK Runner，才能建立请求时间戳。客户端渲染计时和 TPOT 直方图上报属于独立能力。 + +每个已埋点 `model_request` 子 Span 标记 `gen_ai.span.kind=llm`，并由实际 SDK 请求设置布尔属性 `gen_ai.request.stream`。首个生成 delta 到达时，还会设置浮点属性 `gen_ai.chat_completions.streaming_time_to_first_token`，单位为秒，计算方式为 `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9`。这些标准字段描述单次 SDK 请求，不描述外层 `call_llm` 聚合。现有自定义时间戳和旧属性继续保留。 + +同一观测值通过现有全局 MeterProvider，在 `gen_ai.chat_completions.streaming_time_to_first_token` Histogram 中记录一次，单位为 `s`。指标不依赖 token usage 或 Trace 采样，但导出仍需配置指标链路。维度为 `gen_ai.request.model`（实际请求模型）和 `gen_ai.operation.name=chat`。非流式、无输出或不支持埋点的请求不产生 TTFT 样本或属性。负时钟间隔省略并产生诊断；真正测得的零耗时有效。重试/降级分别观测，取消或失败前已观测到的值仍保留。 diff --git a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md new file mode 100644 index 000000000..e50d9db73 --- /dev/null +++ b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md @@ -0,0 +1,126 @@ +# APMPlus streaming and TTFT telemetry + +[中文版](2026-11-02-apmplus-ttft.zh.md) + +Change ID: `apmplus-ttft`; created/revised: 2026-11-02; status: approved. +Component: [model-timing](../../../specs/model-timing/README.md). +Predecessor: [first-token-timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.md). +Inspected revision: `d9ef697b82fde94373737aae518148df348e60b0` on `feat/first-token-timestamps` (PR #1190). + +## Background and evidence + +The [PR review comment](https://github.com/volcengine/veadk-python/pull/1190#issuecomment-6514480806) requires the standard streaming flag, a seconds-valued TTFT span attribute, and actual TTFT Histogram recording. The supplied APMPlus Trace specification (revision 261) and Metrics specification (revision 17), read on 2026-11-02, agree with those requirements. + +`ModelTiming` currently records custom timestamps and actual SDK streaming mode. `PortalMetricRecorder` already creates the correctly named TTFT Histogram with unit `s`, but its recording remains TODO. `record_call_llm()` runs on response callbacks and places existing measurements behind a usage check; it cannot establish exactly one TTFT measurement per SDK request. The original design explicitly excluded Histograms; this successor proposes that narrowly scoped extension. + +## Goals and non-goals + +Add `gen_ai.request.stream` and `gen_ai.chat_completions.streaming_time_to_first_token` to each observable SDK request span, and record the same TTFT value once in the existing Histogram. Preserve custom timestamp fields and model behavior. + +Exclude TPOT, unrelated metric renaming, token accounting changes, client-render timing, hidden provider retries, new exporters/configuration/dependencies, frontend changes, and cloud deployment. Historical cloud evidence does not validate this new change. + +## Requirements and scenarios + +- FR-1: An instrumented `model_request` span has Boolean `gen_ai.request.stream` from the actual SDK request, independent of Runner streaming configuration. Preserve `veadk.model.streaming` and legacy attributes. +- FR-2: The first nonempty text, reasoning, or tool-call delta produces a floating-point seconds value `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9` under `gen_ai.chat_completions.streaming_time_to_first_token`. Reuse the same stored request-start timestamp used by custom attributes. Request ingress and outer span start are not calculation inputs. +- FR-3: At that first observation, record the identical value once in the existing same-name Histogram with unit `s`, even without usage or a recording trace span. Repeated chunks and final-response callbacks must not duplicate it. Every observable retry/fallback request owns its own latch and sample. +- FR-4: Non-streaming, no-output, and unsupported requests have no TTFT attribute/sample. Unknown actual SDK mode must not be invented from Runner configuration. A clock regression preserves raw timestamps but omits a negative duration with a bounded diagnostic; zero measured elapsed time is valid, not a missing-value placeholder. +- FR-5: Preserve samples observed before failure, cancellation, or close. Preserve original output, exception propagation, and resource cleanup. A metrics recording failure emits a bounded diagnostic without recording request content or replacing the model result/error. +- FR-6: New metric dimensions use dotted specification names and known stable values only. Include the actual requested model; omit unknown provider/response-model values. Never include prompt/output content, user/session/trace IDs, or response IDs. Continue using the existing global MeterProvider without installing an export pipeline. + +Given metadata followed by a generated delta, only the generated delta records TTFT. Given two requests sharing one outer model span, each SDK child has independent fields and measurements. Given tracing disabled but a configured metrics reader, an observed streaming request still records the Histogram. Given a request with no generated delta, completion cannot fabricate a sample. + +## Design, alternatives, and contract impact + +Keep one measurement owner in `ModelTiming.observe()`. Store the request-start timestamp and model locally so calculation and metric recording do not depend on readable span attributes. Add a focused typed `PortalMetricRecorder` method for recording this measurement; remove only the superseded TTFT TODO. Reuse the existing instrument, unit, and bucket boundaries. + +Use the per-SDK `model_request` child as the authoritative standard LLM span and label it `gen_ai.span.kind=llm`. This avoids presenting an aggregate/retry owner's lifetime as one SDK request. Existing custom timestamp mirroring to `call_llm` remains compatible; standard TTFT is not copied to an aggregate owner, avoiding stale observations after a later no-output attempt. Document this span boundary explicitly. Existing `gen_ai.is_streaming` is retained for compatibility. + +Alternative: record from `record_call_llm()`. Rejected because callback multiplicity, absent usage, and retries would require additional shared state and could duplicate or lose measurements. Alternative: rename/delete custom timestamps. Rejected because timestamps remain useful and removing them would break consumers without satisfying the duration requirement. + +Before implementation, update both model-timing spec languages: extend CON-2/4/6 and add a per-request Histogram contract covering FR-3/5/6. Add a predecessor note to the original design explaining this extension without rewriting historical acceptance. Update both tracing MDX pages. No persistence, permissions, HTTP/event payload, public model invocation signature, or database migration changes are needed. Rollback removes additive standard telemetry; existing custom timestamps remain usable. + +## Tasks and acceptance + +| Requirement | Task | Acceptance | Verification | Result | +| --- | --- | --- | --- | --- | +| FR-1..6 | T-1: reconcile bilingual design/spec and review | AC-1: consistent scope and approved design | Paired identifiers, links, direct design review | pass: approved on 2026-11-02 | +| FR-1/2/4 | T-2: add failing span contract tests, then implement | AC-2: actual Boolean mode; exact seconds; correct omissions | `tests/test_model_ttft.py`, `tests/test_model_timing.py`, `tests/models/test_model_timing_adapters.py` | pass: implemented and locally verified | +| FR-3/5/6 | T-3: add reader-backed metric tests, then wire recording | AC-3: real Histogram name/unit/count/sum/dimensions; no duplicate or missing samples | `tests/test_portal_metrics.py`, timing and adapter tests | pass: implemented and locally verified | +| FR-1..6 | T-4: run affected/regression/static/docs checks and review | AC-4: compatible outputs, cleanup, exports, and bilingual docs; changed production-line coverage >=95% | Commands below and coverage against inspected revision | local checks pass; default regression fail: one reproduced baseline MIME mismatch | + +Test cases include text/reasoning/tool output, metadata-only chunks, repeat chunks, no usage, actual SDK mode differing from Runner mode, non-streaming, no output, retries/fallbacks, concurrent requests, cancellation/close before and after output, disabled tracing, configured/unconfigured MeterProvider, clock regression, genuine zero elapsed time, and a failed metric recorder. Assert Histogram type, unit `s`, count, sum, dimensions, and exported span fields using controlled clocks and provider boundaries. + +Planned commands, discovered from repository guidance and manifests: + +- `uv run --extra dev pytest tests/test_model_ttft.py tests/test_model_timing.py tests/models/test_model_timing_adapters.py tests/test_portal_metrics.py -q` +- `uv run --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json` +- `uv run --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke"` +- `uv run --extra dev pre-commit run --all-files` (and explicit changed-file checks for untracked additions) +- `npm --prefix docs run types:check`; `npm --prefix docs run build`; `git diff --check` + +Use the repository-local environment; document any environment blockers rather than modifying machine-global settings. Two regression workers follow repository guidance. Actual provider/cloud calls are not part of this local change's acceptance; report local adapter/reader evidence separately from the predecessor's live tests. Commit/push remain subject to separate authorization. + +## Review, risks, and delivery record + +Direct review is used because `review-spec` is unavailable. Inspected calculation ownership, callback duplication, retry boundaries, missing observations, metric dimensions/privacy, failure isolation, compatibility, and bilingual equivalence. Design clarification: standard fields live on observable SDK-request children, not aggregate spans. Main risks are duplicate metric samples, wrong time boundaries/units, stale aggregate fields, and accidental dependency on trace sampling or usage. The acceptance cases directly exercise those risks. + +User approval: explicitly granted on 2026-11-02 to create a new branch and implement immediately. Created `fix/apmplus-ttft` and synchronized the PR base with `git pull --ff-only origin feat/first-token-timestamps`. Implementation and component-spec/MDX reconciliation are complete. The lifecycle remains approved because the repository-wide AC-4 gate has the pre-existing failure recorded below. Runtime verification is recorded below. Source reads and specification comparison passed on 2026-11-02; repository branch checkout and `git pull --ff-only` succeeded. Implementation evidence, eight verification Gates, Change Impact, and Test Portfolio tables are recorded below and in the Chinese counterpart. + +## Implementation verification (2026-11-02) + +Scope: the working diff on `fix/apmplus-ttft` against `d9ef697b82fde94373737aae518148df348e60b0`, including the new test and design files. Production changes are limited to `timing.py` and `portal_metrics.py`. No unrelated user changes were present. Standard per-request fields and Histogram recording are implemented; final repository-wide verification has one reproduced baseline failure, recorded below. + +### Gate status + +| Gate | Status | Evidence or blocking reason | +| --- | --- | --- | +| Change Basis | PASS | Inspected the complete tracked/untracked diff against the PR head; new branch synchronized from that head. | +| Contract | PASS | FR-1..6 and CON-7..9 preserve legacy fields and define standard SDK-request fields, units, omissions, and metric ownership. | +| Impact | PASS | R-1..4 below cover spans, metrics, lifecycle, and maintained documentation. No dependency metadata, UI, payload, or deployment change. | +| Portfolio | PASS | Controlled clocks, real OTel reader/exporter, real model adapters with controlled provider boundaries, fault injection, and existing regression. | +| Baseline | PASS | Before implementation: 13 failing and 5 passing new tests; missing attributes and missing measurements caused the expected failures. | +| Execution | BLOCKED | Default regression: 7950 passed, 1 reproduced baseline MIME failure. Targeted/affected, static, and documentation checks passed; the repository-wide gate is not claimed to pass. | +| Evaluation | PASS | All changed production executable lines and changed decision arcs exercised; assertions distinguish wrong units, duplicate/missing samples, and wrong span scope. | +| Handoff | PASS | Scoped implementation and evidence delivered with the baseline regression limitation; no commit or push performed. | + +### Change Impact + +| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | +| --- | --- | --- | --- | --- | --- | +| FR-1/2/4 | CON-7 per-request standard fields | LiteLLM/Ark request spans and export | `ModelTiming`, actual adapter tests | Wrong mode/type/unit/start boundary; fabricated or stale aggregate TTFT | R-1 Medium | +| FR-3/6 | CON-8/9 per-request Histogram | Global metrics pipeline | `record_model_ttft`, real `InMemoryMetricReader` | Duplicate/lost samples, usage/trace dependency, wrong dimensions | R-2 Medium | +| FR-4/5 | CON-8 lifecycle and failures | Streaming, retries, cancellation, close | Timing/adapter tests and metric fault injection | Telemetry replaces model error/output; attempts mix or leak | R-3 High | +| FR-1..6 | Additive compatibility and documentation | Existing attributes, tracing pages, component specs | Existing regression, bilingual checks, docs build | Consumers receive conflicting definitions or lose old attributes | R-4 Medium | + +R-1/2/4 cross observable contracts and are Medium. R-3 can affect model completion on a commonly executed path (High impact and exposure), so it is High before validation. No known material consumer remains untraced. Residual risks are bounded by local controlled-provider verification; no new live cloud export is claimed. + +### Test Portfolio + +| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | +| --- | --- | --- | --- | --- | --- | --- | +| R-1 | SDK timing and span exporter | Clock control and contract tests | Text/reasoning/tool output, mode, empty/unsupported, negative/zero interval, retry scope | Exact float seconds, Boolean mode, child-only fields, correct absence | New TTFT tests plus existing LiteLLM/Ark adapter assertions | VERIFIED | +| R-2 | Real OTel metrics reader | Integration/state transition | No usage, no recording span, no exporter, repeated chunks/final callbacks, retry/concurrency | Histogram type/name/unit, exact count/sum, model isolation, exact safe dimensions | New TTFT tests; existing Portal provider/late-provider tests | VERIFIED | +| R-3 | SDK stream and recorder boundary | Fault injection and lifecycle tests | Error/cancel/close before/after first output; metrics failure | Original exceptions and cleanup preserved; observed samples retained; bounded diagnostic without error details | New TTFT tests plus existing timing and adapter lifecycle tests | VERIFIED | +| R-4 | Consumers and documentation | Regression, type/build, static review | Legacy attributes, exports, bilingual identifiers/links | Existing assertions pass; equivalent definitions and valid documentation build | Affected suite, pre-commit, docs checks | VERIFIED | + +### Executed evidence + +- Before the production change, `uv run --extra dev pytest tests/test_model_ttft.py -q`: **13 failed, 5 passed** (18 collected/executed). This is the expected RED result. +- After adding final-callback and no-exporter cases, `uv run --extra dev pytest tests/test_model_ttft.py -q`: **20 passed**, zero failures/skips. Negative-clock diagnostics are asserted. +- `uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-ttft-coverage-final.json`: **156 passed**, zero failures/skips (156 collected/executed). +- Production changed-line coverage is the intersection of added working-diff lines and coverage.py executable lines: **21/21 (100%)**, with **4/4** changed decision arcs covered. No coverage exclusions were added. Existing uncovered unrelated Portal metrics branches are outside this diff. +- `uv run --extra dev pre-commit run --all-files` plus explicit checks for new files: **pass**. Ruff initially formatted test changes; the subsequent check passed. Hooks without applicable files were skipped, not counted as execution. +- `npm --prefix docs run types:check` and `npm --prefix docs run build`: **pass**. Bilingual code identifiers/commands, relative links, new-test function lengths, and `git diff --check`: **pass**. +- The existing `tests/frontend/server/runtime_artifacts/test_writer.py::test_success_uses_trusted_scope_and_hashes_utf8_bytes` fails on the untouched `d9ef697b` snapshot too: expected `text/markdown`, observed `application/octet-stream`. The snapshot imported its own unmodified `writer.py`, `service.py`, and `timing.py`; its targeted run had **1 failed**. No assertion or unrelated production code was changed to hide this failure. +- `uv run --extra dev --extra sandbox --extra extensions --extra codex pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`: **fail: 7950 passed, 1 failed, 53 skipped, 4 xfailed**, plus **6 passing subtests**, in 412.98s. 8008 selected; 7955 executed including expected failures; 53 skipped. The sole failure is the unchanged baseline MIME test above. The two-worker setting follows repository guidance; skipped/expected-failure tests do not prove behavior. Live cloud/provider tests: **not_run**, outside the approved local scope. External-engine smoke tests: **not_applicable**, those engines are unchanged. + +Final review confirms the existing first-output latch owns metric emission, duration calculation uses the stored SDK start rather than parent span timing, and metrics recording runs outside `span.is_recording()` guards. Only instrument recording failures are caught and diagnosed; model exceptions are not intercepted. Existing timestamps remain intact. The known baseline MIME mismatch is a repository-wide gate limitation, not TTFT acceptance evidence. + +## Commit and push verification (2026-11-02) + +The user explicitly authorized commit and push. PR #1190 had already been squash-merged as `c1d4096d`; the repair branch was rebased onto the fetched `origin/main` at `65f30f2881b5d09aca94ea0c5e3450852866748f`, without replaying the original PR commits. The production repair diff is unchanged. + +After synchronization, `uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q` passed all **156 tests**. `uv run --no-sync --extra dev pre-commit run --all-files` passed. + +`uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q` finished with **8044 passed, 1 failed, 55 skipped, 4 xfailed**, plus **6 passing subtests**, in 407.20s. The sole failure remains the previously reproduced baseline Markdown MIME mismatch; its production/test files are unchanged between the original PR head and the synchronized base. The repository-wide gate remains `fail`; no assertion was weakened. This authorization covers pushing `fix/apmplus-ttft`, not opening another PR. diff --git a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md new file mode 100644 index 000000000..2f0e258ee --- /dev/null +++ b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md @@ -0,0 +1,126 @@ +# APMPlus 流式与 TTFT 遥测 + +[English](2026-11-02-apmplus-ttft.md) + +变更 ID：`apmplus-ttft`；创建/修订日期：2026-11-02；状态：approved。 +组件：[model-timing](../../../specs/model-timing/README.zh.md)。 +前序设计：[first-token-timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md)。 +检查版本：`feat/first-token-timestamps` 的 `d9ef697b82fde94373737aae518148df348e60b0`（PR #1190）。 + +## 背景与证据 + +[PR 评论](https://github.com/volcengine/veadk-python/pull/1190#issuecomment-6514480806) 要求补齐标准流式标记、以秒为单位的 TTFT Span 属性及真正的 TTFT Histogram 记录。2026-11-02 读取的指定 APMPlus Trace 规范（revision 261）和 Metrics 规范（revision 17）与这些要求一致。 + +`ModelTiming` 当前记录自定义时间戳和实际 SDK 流式模式。`PortalMetricRecorder` 已创建名称正确、单位为 `s` 的 TTFT Histogram，但记录逻辑仍为 TODO。`record_call_llm()` 在响应回调中执行，现有观测还受 usage 检查限制，无法保证每次 SDK 请求恰好记录一次 TTFT。原设计明确排除了 Histogram；本后续设计提出这一有限扩展。 + +## 目标与非目标 + +为每次可观测 SDK 请求的 Span 添加 `gen_ai.request.stream` 和 `gen_ai.chat_completions.streaming_time_to_first_token`，并在现有 Histogram 中记录同一个 TTFT 值一次。保留自定义时间戳和模型行为。 + +不包含 TPOT、无关指标改名、token 计数变更、客户端渲染耗时、供应商内部不可观测重试、新 exporter/配置/依赖、前端变更和云部署。历史云端证据不证明本次新变更。 + +## 要求与场景 + +- FR-1：已埋点的 `model_request` Span 使用实际 SDK 请求的布尔值设置 `gen_ai.request.stream`，不依赖 Runner 流式配置。保留 `veadk.model.streaming` 和旧属性。 +- FR-2：首个非空文本、推理或工具调用 delta 产生浮点秒数 `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9`，写入 `gen_ai.chat_completions.streaming_time_to_first_token`。复用自定义属性所用的同一请求开始时间戳。请求入口时间和外层 Span 开始时间不参与计算。 +- FR-3：首次观测时，在现有同名、单位为 `s` 的 Histogram 中记录同一个值一次，即使没有 usage 或可记录的 Trace Span。后续 chunk 和最终响应回调不能重复记录。每次可观测重试/降级 SDK 请求独立持有首次观测状态和样本。 +- FR-4：非流式、无输出和不支持埋点的请求没有 TTFT 属性/样本。实际 SDK 模式未知时，不从 Runner 配置推造。时钟回退时保留原始时间戳，省略负耗时并产生有限诊断；真正测得的零耗时有效，不是缺失值占位。 +- FR-5：失败、取消或关闭前已观测的样本应保留。保持原始输出、异常传播和资源清理。指标记录失败时产生有限诊断，不记录请求内容，也不替换模型结果/异常。 +- FR-6：新指标维度使用规范中的点分名称，且仅填写已知稳定值。包含实际请求模型；未知供应商/响应模型省略。不得加入提示词/输出正文、用户/会话/Trace ID 或响应 ID。继续使用现有全局 MeterProvider，不安装导出链路。 + +当元数据后出现生成 delta 时，只由生成 delta 记录 TTFT。当两个请求共用一个外层模型 Span 时，各 SDK 子 Span 独立保存属性和观测。关闭 tracing 但已配置指标 reader 时，已观测流式请求仍记录 Histogram。没有生成 delta 时，完成响应不能伪造样本。 + +## 设计、方案取舍与契约影响 + +由 `ModelTiming.observe()` 唯一负责观测。在本地保存请求开始时间和模型，使计算和指标记录不依赖读取 Span 属性。为 `PortalMetricRecorder` 添加职责单一、带类型注解的记录方法；仅移除被替代的 TTFT TODO。复用现有 instrument、单位和桶边界。 + +每次 SDK 请求的 `model_request` 子 Span 是标准 LLM Span 的权威位置，并标记 `gen_ai.span.kind=llm`，避免将聚合/重试所属 Span 的生命周期当成单次 SDK 请求。继续兼容现有向 `call_llm` 镜像自定义时间戳的行为；不向聚合 Span 复制标准 TTFT，避免后续无输出尝试遗留旧观测。文档明确该 Span 边界。现有 `gen_ai.is_streaming` 保留兼容。 + +替代方案：在 `record_call_llm()` 记录。不采用，因为回调次数、usage 缺失和重试需要额外共享状态，可能重复或遗漏样本。替代方案：重命名/删除自定义时间戳。不采用，因为时间戳仍有价值，删除既破坏消费者兼容，也不能满足耗时要求。 + +实现前更新 model-timing 双语契约：扩展 CON-2/4/6，新增覆盖 FR-3/5/6 的逐请求 Histogram 契约。在原设计添加后续设计说明，保留历史验收事实。同步更新两份 tracing MDX。无需修改持久化、权限、HTTP/事件载荷、公开模型调用签名或数据库。回滚删除新增标准遥测即可，原自定义时间戳仍可使用。 + +## 任务与验收 + +| 要求 | 任务 | 验收 | 验证 | 结果 | +| --- | --- | --- | --- | --- | +| FR-1..6 | T-1：同步双语设计/契约并评审 | AC-1：范围一致且设计获批 | 双语标识符、链接、直接设计评审 | pass：2026-11-02 获批 | +| FR-1/2/4 | T-2：先添加失败的 Span 契约测试，再实现 | AC-2：实际布尔模式；精确秒数；正确省略 | `tests/test_model_ttft.py`、`tests/test_model_timing.py`、`tests/models/test_model_timing_adapters.py` | pass：已实现并完成本地验证 | +| FR-3/5/6 | T-3：先添加 reader 指标测试，再接入记录 | AC-3：真实 Histogram 名称/单位/count/sum/维度；无重复或遗漏 | `tests/test_portal_metrics.py`、timing 与适配器测试 | pass：已实现并完成本地验证 | +| FR-1..6 | T-4：受影响/回归/静态/文档检查及评审 | AC-4：输出、清理、导出兼容；双语文档一致；变更生产行覆盖率 >=95% | 下列命令及相对检查版本的覆盖率 | 本地检查通过；默认回归 fail：一项已复现的基线 MIME 不匹配 | + +测试包含文本/推理/工具输出、纯元数据 chunk、重复 chunk、无 usage、实际 SDK 模式与 Runner 模式不同、非流式、无输出、重试/降级、并发请求、输出前后取消/关闭、禁用 tracing、已配置/未配置 MeterProvider、时钟回退、真正零耗时、指标记录失败。使用受控时钟与供应商边界，断言 Histogram 类型、单位 `s`、count、sum、维度及导出的 Span 属性。 + +根据仓库指南和清单确认的计划命令： + +- `uv run --extra dev pytest tests/test_model_ttft.py tests/test_model_timing.py tests/models/test_model_timing_adapters.py tests/test_portal_metrics.py -q` +- `uv run --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json` +- `uv run --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke"` +- `uv run --extra dev pre-commit run --all-files`（另对未跟踪新增文件显式执行变更文件检查） +- `npm --prefix docs run types:check`；`npm --prefix docs run build`；`git diff --check` + +使用仓库本地环境；记录环境阻碍，不修改机器全局配置。两个回归 worker 遵循仓库要求。真实供应商/云调用不属于本次本地变更验收；分别报告本地适配器/reader 证据和前序设计的真实测试。提交/推送仍需单独授权。 + +## 评审、风险与交付记录 + +`review-spec` 不可用，因此执行直接评审。已检查计算归属、回调重复、重试边界、缺失观测、指标维度/隐私、故障隔离、兼容性及双语等价性。设计澄清：标准字段位于可观测 SDK 请求子 Span，不放在聚合 Span。主要风险是重复样本、错误时间边界/单位、聚合字段残留，以及意外依赖 Trace 采样或 usage；验收场景直接覆盖这些风险。 + +用户于 2026-11-02 明确批准“创建新分支，立即修改”。已创建 `fix/apmplus-ttft`，并通过 `git pull --ff-only origin feat/first-token-timestamps` 同步 PR 基线。实现、组件契约及 MDX 同步已完成。因仓库级 AC-4 检查存在下方记录的既有失败，生命周期保留 approved。运行验证记录见下方。2026-11-02 已完成源码读取和规范核对；分支切换及 `git pull --ff-only` 成功。本设计下方及英文版本已记录实现证据、八个验证 Gate、Change Impact 和 Test Portfolio 表。 + +## 实现验证（2026-11-02） + +范围：`fix/apmplus-ttft` 相对 `d9ef697b82fde94373737aae518148df348e60b0` 的工作区差异，包含新增测试和设计文件。生产代码仅修改 `timing.py` 和 `portal_metrics.py`。没有无关用户改动。逐请求标准属性和 Histogram 记录已实现；最终仓库级验证存在一项已复现的基线失败，详见下方。 + +### Gate 状态 + +| Gate | 状态 | 证据或阻碍原因 | +| --- | --- | --- | +| Change Basis | PASS | 已检查相对 PR head 的全部已跟踪/未跟踪差异；新分支已从该 head 同步。 | +| Contract | PASS | FR-1..6 与 CON-7..9 保留旧字段，并定义标准 SDK 请求字段、单位、省略规则及指标归属。 | +| Impact | PASS | 下方 R-1..4 覆盖 Span、指标、生命周期和维护文档。无依赖清单、UI、载荷或部署变更。 | +| Portfolio | PASS | 受控时钟、真实 OTel reader/exporter、受控供应商边界下的真实模型适配器、故障注入及既有回归。 | +| Baseline | PASS | 实现前新增测试 13 项失败、5 项通过；缺少属性和指标观测导致预期失败。 | +| Execution | BLOCKED | 默认回归 7950 项通过、1 项已复现基线 MIME 失败。定向/受影响、静态及文档检查通过；不声明仓库级检查通过。 | +| Evaluation | PASS | 覆盖全部变更生产可执行行和变更分支；断言能识别错误单位、重复/缺失样本和错误 Span 范围。 | +| Handoff | PASS | 交付范围内实现及证据，并明确基线回归限制；未提交或推送。 | + +### Change Impact + +| Change ID | 变更契约 | 受影响面 | 仓库证据 | 失败模式 | 风险 | +| --- | --- | --- | --- | --- | --- | +| FR-1/2/4 | CON-7 逐请求标准属性 | LiteLLM/Ark 请求 Span 及导出 | `ModelTiming`、真实适配器测试 | 模式/类型/单位/起点错误；伪造或聚合 Span 残留 TTFT | R-1 Medium | +| FR-3/6 | CON-8/9 逐请求 Histogram | 全局指标链路 | `record_model_ttft`、真实 `InMemoryMetricReader` | 重复/遗漏样本、依赖 usage/trace、维度错误 | R-2 Medium | +| FR-4/5 | CON-8 生命周期和失败 | 流式、重试、取消、关闭 | 计时/适配器测试及指标故障注入 | 遥测替换模型异常/输出；请求混淆或泄漏 | R-3 High | +| FR-1..6 | 增量兼容及文档 | 旧属性、tracing 页面、组件契约 | 既有回归、双语检查、文档构建 | 消费者获得冲突定义或丢失旧属性 | R-4 Medium | + +R-1/2/4 跨可观测契约，定为 Medium。R-3 可能影响常用路径的模型完成行为（影响和暴露均为 High），验证前定为 High。没有已知但未追踪的重要消费者。残余风险以本地受控供应商验证为界，不声明新增云端真实导出验证。 + +### Test Portfolio + +| Risk ID | 边界 | 方法 | 场景 | 判定依据 | 证据 | 状态 | +| --- | --- | --- | --- | --- | --- | --- | +| R-1 | SDK 计时及 Span exporter | 时钟控制、契约测试 | 文本/推理/工具输出、模式、空/不支持、负/零间隔、重试范围 | 精确浮点秒数、布尔模式、仅子 Span 标准字段、正确缺失 | 新增 TTFT 测试及既有 LiteLLM/Ark 适配器断言 | VERIFIED | +| R-2 | 真实 OTel metrics reader | 集成/状态转换 | 无 usage、无录制 Span、无 exporter、重复 chunk/最终回调、重试/并发 | Histogram 类型/名称/单位、精确 count/sum、模型隔离、安全维度全集 | 新增 TTFT 测试；既有 Portal provider/延迟 provider 测试 | VERIFIED | +| R-3 | SDK 流及 recorder 边界 | 故障注入、生命周期测试 | 首输出前后异常/取消/关闭；指标失败 | 保留原异常与清理；已观测样本保留；有限诊断不含错误详情 | 新增 TTFT 测试及既有计时、适配器生命周期测试 | VERIFIED | +| R-4 | 消费者与文档 | 回归、类型/构建、静态评审 | 旧属性、导出、双语标识符/链接 | 既有断言通过；定义等价且文档构建有效 | 受影响套件、pre-commit、文档检查 | VERIFIED | + +### 已执行证据 + +- 生产修改前，`uv run --extra dev pytest tests/test_model_ttft.py -q`：**13 failed、5 passed**（收集/执行 18 项）。这是预期 RED 结果。 +- 增加最终回调及无 exporter 场景后，`uv run --extra dev pytest tests/test_model_ttft.py -q`：**20 passed**，零失败/跳过。已断言负时钟诊断。 +- `uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-ttft-coverage-final.json`：**156 passed**，零失败/跳过（收集/执行 156 项）。 +- 生产变更行覆盖率取工作区新增行与 coverage.py 可执行行的交集：**21/21（100%）**，变更分支 **4/4** 已覆盖。没有新增覆盖率排除。Portal metrics 既有无关分支缺口不在本次差异中。 +- `uv run --extra dev pre-commit run --all-files` 及新增文件显式检查：**pass**。Ruff 首次格式化测试改动后，后续检查通过。不适用的 hook 标为跳过，不算已执行。 +- `npm --prefix docs run types:check` 与 `npm --prefix docs run build`：**pass**。双语代码标识符/命令、相对链接、新增测试函数长度以及 `git diff --check`：**pass**。 +- 既有 `tests/frontend/server/runtime_artifacts/test_writer.py::test_success_uses_trusted_scope_and_hashes_utf8_bytes` 在未修改的 `d9ef697b` 快照同样失败：预期 `text/markdown`，实际 `application/octet-stream`。快照加载了自身未修改的 `writer.py`、`service.py`、`timing.py`；定向运行结果为 **1 failed**。没有修改断言或无关生产代码来隐藏该失败。 +- `uv run --extra dev --extra sandbox --extra extensions --extra codex pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`：**fail：7950 passed、1 failed、53 skipped、4 xfailed**，另有 **6 项子测试通过**，耗时 412.98s。选中 8008 项；执行 7955 项（含预期失败）；跳过 53 项。唯一失败为上述未修改的基线 MIME 测试。两个 worker 遵循仓库要求；跳过/预期失败不证明相关行为。真实云/供应商测试：**not_run**，不在批准的本地范围内。外部执行引擎 smoke：**not_applicable**，这些引擎未变更。 + +最终评审确认：指标由既有首次输出状态唯一触发；耗时从保存的 SDK 起点计算，不使用父 Span 计时；指标记录不受 `span.is_recording()` 限制。仅捕获并诊断 instrument 记录异常，不拦截模型异常。保留现有时间戳。已知基线 MIME 不匹配是仓库级检查限制，不属于 TTFT 验收证据。 + +## 提交与推送验证（2026-11-02） + +用户已明确授权提交和推送。PR #1190 已通过 squash 合并为 `c1d4096d`；修复分支已 rebase 到 fetch 后的 `origin/main`：`65f30f2881b5d09aca94ea0c5e3450852866748f`，没有重复应用原 PR 提交。生产修复差异保持不变。 + +同步后，`uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q` 的 **156 项测试全部通过**。`uv run --no-sync --extra dev pre-commit run --all-files` 通过。 + +`uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q` 结果为 **8044 passed、1 failed、55 skipped、4 xfailed**，另有 **6 项子测试通过**，耗时 407.20s。唯一失败仍为此前已复现的基线 Markdown MIME 不匹配；其生产/测试文件在原 PR head 与同步后基线之间没有变化。仓库级检查仍为 `fail`，没有放宽断言。本次授权包含推送 `fix/apmplus-ttft`，不包含新建另一个 PR。 diff --git a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md b/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md index 6f33deb28..ba3ef90c6 100644 --- a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md +++ b/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md @@ -2,6 +2,9 @@ [中文版](2026-10-28-first-token-timestamps.zh.md) + +Successor: [APMPlus streaming and TTFT telemetry](../../bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md) adds standard per-request attributes and TTFT Histogram recording. The historical scope and evidence below predate that extension. + Change ID: `first-token-timestamps`; created/revised: 2026-10-28; status: approved (implementation and local verification complete; current publication checks are tracked in PR #1190). Component: [model-timing](../../../specs/model-timing/README.md). Base: `23014771`. diff --git a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md b/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md index 6d4676eac..2c2a8b664 100644 --- a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md +++ b/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md @@ -2,6 +2,9 @@ [English](2026-10-28-first-token-timestamps.md) + +后续设计：[APMPlus 流式与 TTFT 遥测](../../bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md) 添加逐请求标准属性和 TTFT Histogram 记录。下列历史范围与证据早于该扩展。 + 变更 ID：`first-token-timestamps`；创建/修订：2026-10-28；状态：approved（实现与本地验证已完成；当前发布检查由 PR #1190 记录）。 组件：[model-timing](../../../specs/model-timing/README.zh.md)。基线：`23014771`。 diff --git a/specs/model-timing/README.md b/specs/model-timing/README.md index b3e838d33..4c30dbc44 100644 --- a/specs/model-timing/README.md +++ b/specs/model-timing/README.md @@ -2,7 +2,7 @@ [中文版](README.zh.md) -Component ID: `model-timing`; revision: 2026-10-28; status: active. +Component ID: `model-timing`; revision: 2026-11-02; status: active. ## Responsibility and interfaces @@ -11,7 +11,7 @@ Own SDK-observed request/model/first-output timestamps in `veadk/tracing/telemet ## Contracts - CON-1: `veadk.request.start_time_unix_ns` is captured at HTTP ASGI entry, before request parsing, in VeADK AgentKit/Harness applications. `veadk.request.start_source` is `http`. Direct VeADK Runner calls use Runner execution entry and source `runner`. An inherited HTTP timestamp takes precedence. This excludes client/network/gateway delays before ASGI entry. -- CON-2: `veadk.model.start_time_unix_ns` is captured immediately before each adapter SDK request (`LiteLLMClient.acompletion` or Ark `aresponses`). Each request has a child `model_request` span under the owning model span; its model attribute identifies the requested model. Internal provider/LiteLLM retry/fallback activity is opaque and included in that SDK request. VeADK-issued retries/fallbacks create separate child spans. Successful/latest attempt fields also annotate the owning model span. This is not provider inference start. +- CON-2: `veadk.model.start_time_unix_ns` is captured immediately before each adapter SDK request (`LiteLLMClient.acompletion` or Ark `aresponses`). Each request has a child `model_request` span under the owning model span; its model attribute identifies the requested model. Internal provider/LiteLLM retry/fallback activity is opaque and included in that SDK request. VeADK-issued retries/fallbacks create separate child spans. Successful/latest attempt custom timestamp/status fields also annotate the owning model span. This is not provider inference start. - CON-3: For streaming requests, `veadk.model.first_token_time_unix_ns` is the local receipt time of the first nonempty generated content delta. `veadk.model.first_token_type` is `text`, `reasoning`, or `tool_call`. Empty deltas, role/id/signature metadata, heartbeats, usage, and completion-only aggregates do not count. A chunk can contain several tokens; no provider-side token generation timestamp is claimed. Record once, without requiring usage or storing content. - CON-4: `veadk.model.streaming` describes the actual SDK request. `veadk.model.first_token_status` is `observed`, `non_streaming`, `no_output`, or `unsupported`. Non-streaming requests never synthesize a first-token timestamp from their complete response. Unsupported/custom/external engines explicitly expose absent model timing rather than treating an invocation span start as model start. - CON-5: Each attempt ends on completion, error, cancellation, or generator closure. Already observed timestamps survive interruption. Model/request context does not leak between concurrent invocations or through async-generator yields. Original outputs, exceptions, cancellation, retry rules, and close behavior remain intact. @@ -27,4 +27,14 @@ CON-1/5: ASGI boundary, async-generator/context/cancellation tests. CON-2/3/4/5: Change design and evidence: [first-token-timestamps](../../prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md). -Contract verification: 55 focused timing/adapter tests, 244 affected tests and 6 real cloud cases passed; changed production-line coverage is 100% (208/208). The unrelated default-regression failure is documented in the linked PRD. +Predecessor verification: 55 focused timing/adapter tests, 244 affected tests and 6 real cloud cases passed; changed production-line coverage is 100% (208/208). The unrelated default-regression failure is documented in the linked PRD. + +## Standard streaming and TTFT (2026-11-02) + +[APMPlus TTFT design](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md) extends CON-2/4/6. Existing verification above covers the predecessor only. + +- CON-7: Each instrumented SDK `model_request` child is labeled `gen_ai.span.kind=llm` and carries Boolean `gen_ai.request.stream` from the actual SDK request. Its `gen_ai.chat_completions.streaming_time_to_first_token` is a float in seconds, calculated from the same locally stored model-start and first-output timestamps. These standard fields belong to individual SDK children, not aggregate owner spans. Keep existing custom and legacy attributes compatible. Unsupported SDK mode is unknown, not inferred from Runner configuration. +- CON-8: On the first valid streaming output, record the identical TTFT once in the existing same-name Histogram with unit `s`. This does not depend on usage or trace sampling. Each SDK retry/fallback is independent. Non-streaming/no-output/unsupported requests produce no sample. Negative wall-clock intervals produce a bounded diagnostic and no duration; measured zero is valid. Already recorded observations survive error/cancellation/close. Metric-recording errors are diagnosed without content or exception details and do not replace model results/errors. +- CON-9: TTFT metrics use known stable dotted dimensions: `gen_ai.request.model` for the actual requested model and `gen_ai.operation.name=chat` for the existing conversational operation. Unknown provider/response-model values are omitted. No content or per-request identifiers are dimensions. The existing global MeterProvider owns export; no new provider, credentials, or configuration is installed. Verify CON-7..9 with controlled clocks, SDK adapters, in-memory span export, and a real metrics reader. + +Local CON-7..9 verification: 20 focused TTFT tests and 156 affected tests passed; changed production-line coverage is 100% (21/21), with 4/4 changed decision arcs covered. See the linked APMPlus TTFT design for the repository regression result and its baseline limitation. No new live cloud verification is claimed. diff --git a/specs/model-timing/README.zh.md b/specs/model-timing/README.zh.md index eb283de3e..c7bf64539 100644 --- a/specs/model-timing/README.zh.md +++ b/specs/model-timing/README.zh.md @@ -2,7 +2,7 @@ [English](README.md) -组件 ID：`model-timing`；修订日期：2026-10-28；状态：active。 +组件 ID：`model-timing`；修订日期：2026-11-02；状态：active。 ## 职责与接口 @@ -11,7 +11,7 @@ ## 契约 - CON-1：VeADK AgentKit/Harness 应用在 HTTP ASGI 入口、请求解析前记录 `veadk.request.start_time_unix_ns`，`veadk.request.start_source` 为 `http`。直接调用 VeADK Runner 时以 Runner 执行入口为起点，来源为 `runner`。继承的 HTTP 时间戳优先。不包含 ASGI 入口之前的客户端、网络和网关耗时。 -- CON-2：每次适配器 SDK 请求（`LiteLLMClient.acompletion` 或 Ark `aresponses`）之前记录 `veadk.model.start_time_unix_ns`。每次请求在所属模型 Span 下建立 `model_request` 子 Span，其模型属性标识请求模型。Provider/LiteLLM 内部重试和 fallback 不可见，计入本次 SDK 请求；VeADK 发起的重试和 fallback 分别建立子 Span。成功或最近一次尝试的字段同时写入所属模型 Span。这不是模型服务端开始推理的时间。 +- CON-2：每次适配器 SDK 请求（`LiteLLMClient.acompletion` 或 Ark `aresponses`）之前记录 `veadk.model.start_time_unix_ns`。每次请求在所属模型 Span 下建立 `model_request` 子 Span，其模型属性标识请求模型。Provider/LiteLLM 内部重试和 fallback 不可见，计入本次 SDK 请求；VeADK 发起的重试和 fallback 分别建立子 Span。成功或最近一次尝试的自定义时间戳/状态字段同时写入所属模型 Span。这不是模型服务端开始推理的时间。 - CON-3：流式请求的 `veadk.model.first_token_time_unix_ns` 为首个非空生成内容增量在本地收到的时间，`veadk.model.first_token_type` 为 `text`、`reasoning` 或 `tool_call`。空增量、角色/id/签名元数据、心跳、usage 和仅完成时返回的聚合内容不计入。一个 chunk 可含多个 token，不声称取得服务端生成 token 的时间。仅记录一次，不依赖 usage，也不存储内容。 - CON-4：`veadk.model.streaming` 表示实际 SDK 请求模式。`veadk.model.first_token_status` 为 `observed`、`non_streaming`、`no_output` 或 `unsupported`。非流式请求不使用完整响应时间伪造首 Token 时间。不支持的自定义/外部执行引擎明确标记模型计时缺失，不把 invocation Span 起点当成模型开始。 - CON-5：每次尝试在完成、异常、取消或生成器关闭时结束。已观测到的时间戳在中断后保留。模型/请求上下文不会在并发调用之间或通过异步生成器 yield 泄漏。原有输出、异常、取消、重试规则和关闭行为保持一致。 @@ -27,4 +27,14 @@ CON-1/5：ASGI 入口、异步生成器/上下文/取消测试。CON-2/3/4/5： 变更设计与证据：[first-token-timestamps](../../prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md)。 -契约验证：55 项计时/适配器测试、244 项受影响测试及 6 项真实云端用例通过；生产变更行覆盖率为 100%（208/208）。无关的默认回归失败记录于所链接 PRD。 +前序变更验证：55 项计时/适配器测试、244 项受影响测试及 6 项真实云端用例通过；生产变更行覆盖率为 100%（208/208）。无关的默认回归失败记录于所链接 PRD。 + +## 标准流式与 TTFT（2026-11-02） + +[APMPlus TTFT 设计](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md) 扩展 CON-2/4/6。上面的已有验证仅覆盖前序变更。 + +- CON-7：每个已埋点 SDK `model_request` 子 Span 标记 `gen_ai.span.kind=llm`，并由实际 SDK 请求设置布尔值 `gen_ai.request.stream`。其 `gen_ai.chat_completions.streaming_time_to_first_token` 为浮点秒数，由本地保存的同一模型开始、首输出时间戳计算。这些标准字段属于单次 SDK 子 Span，不属于聚合的所属 Span。保持现有自定义和旧属性兼容。不支持埋点时 SDK 模式未知，不从 Runner 配置推导。 +- CON-8：首次有效流式输出时，在现有同名、单位为 `s` 的 Histogram 记录同一个 TTFT 一次，不依赖 usage 或 Trace 采样。各 SDK 重试/降级独立。非流式/无输出/不支持埋点的请求不产生样本。负时钟间隔产生有限诊断，不生成耗时；实测零值有效。已记录观测在异常/取消/关闭后保留。指标记录异常产生不含内容和异常详情的诊断，不替代模型结果/异常。 +- CON-9：TTFT 指标使用已知稳定的点分维度：`gen_ai.request.model` 为实际请求模型，`gen_ai.operation.name=chat` 为既有对话操作。未知供应商/响应模型省略。内容和逐请求标识不作为维度。现有全局 MeterProvider 负责导出，不安装新 provider、凭证或配置。通过受控时钟、SDK 适配器、内存 Span 导出和真实指标 reader 验证 CON-7..9。 + +CON-7..9 本地验证：20 项定向 TTFT 测试及 156 项受影响测试通过；生产变更行覆盖率为 100%（21/21），变更分支覆盖 4/4。仓库回归结果及其基线限制见所链接 APMPlus TTFT 设计。不声明新增真实云端验证。 diff --git a/tests/models/test_model_timing_adapters.py b/tests/models/test_model_timing_adapters.py index 7790035af..cc70f0adf 100644 --- a/tests/models/test_model_timing_adapters.py +++ b/tests/models/test_model_timing_adapters.py @@ -99,6 +99,21 @@ async def complete(self, model, messages, tools, **kwargs): r async for r in model.generate_content_async(request, stream=stream) ] assert responses + attempt = next( + s for s in exporter.get_finished_spans() if s.name == "model_request" + ) + assert attempt.attributes["gen_ai.request.stream"] is stream + ttft = "gen_ai.chat_completions.streaming_time_to_first_token" + assert (ttft in attempt.attributes) is stream + if stream: + assert ( + attempt.attributes[ttft] + == ( + attempt.attributes["veadk.model.first_token_time_unix_ns"] + - attempt.attributes["veadk.model.start_time_unix_ns"] + ) + / 1e9 + ) assert owner.attributes["veadk.model.streaming"] is stream assert owner.attributes["veadk.model.first_token_status"] == ( "observed" if stream else "non_streaming" @@ -258,6 +273,10 @@ async def responses(*args, **kwargs): if mode in {"empty", "error"} else "observed" ) + assert attempt.attributes["gen_ai.request.stream"] is (mode != "non_streaming") + assert ( + "gen_ai.chat_completions.streaming_time_to_first_token" in attempt.attributes + ) is (status == "observed") assert owner.attributes["veadk.model.first_token_status"] == status if status == "observed": assert owner.attributes["veadk.model.first_token_type"] == ( diff --git a/tests/test_model_ttft.py b/tests/test_model_ttft.py new file mode 100644 index 000000000..811460387 --- /dev/null +++ b/tests/test_model_ttft.py @@ -0,0 +1,285 @@ +# Copyright (c) 2025 Beijing Volcano Engine Technology Co., Ltd. and/or its affiliates. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Standard per-SDK-request TTFT span and metric contracts.""" + +from __future__ import annotations + +import asyncio +from collections.abc import Iterator +from unittest.mock import Mock + +import pytest +from opentelemetry.sdk.metrics import MeterProvider +from opentelemetry.sdk.metrics.export import Histogram, InMemoryMetricReader +from opentelemetry.sdk.trace import TracerProvider +from opentelemetry.sdk.trace.export import SimpleSpanProcessor +from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter +from opentelemetry.trace import NoOpTracer + +from veadk.tracing.telemetry import portal_metrics, timing + +TTFT = "gen_ai.chat_completions.streaming_time_to_first_token" + + +@pytest.fixture +def telemetry(monkeypatch: pytest.MonkeyPatch) -> Iterator[tuple]: + reader = InMemoryMetricReader() + metrics = MeterProvider(metric_readers=[reader]) + monkeypatch.setattr(portal_metrics.metrics_api, "get_meter", metrics.get_meter) + recorder = portal_metrics.PortalMetricRecorder() + monkeypatch.setattr(portal_metrics, "portal_metric_recorder", recorder) + traces = TracerProvider() + exporter = InMemorySpanExporter() + traces.add_span_processor(SimpleSpanProcessor(exporter)) + tracer = traces.get_tracer("ttft-test") + monkeypatch.setattr(timing.trace, "get_tracer", lambda *args: tracer) + yield tracer, exporter, reader, recorder + traces.shutdown() + metrics.shutdown() + + +def ttft_points(reader: InMemoryMetricReader) -> list: + data = reader.get_metrics_data() + if data is None: + return [] + points = [] + for resource in data.resource_metrics: + for scope in resource.scope_metrics: + for metric in scope.metrics: + if metric.name == TTFT: + assert metric.unit == "s" + assert isinstance(metric.data, Histogram) + points.extend(metric.data.data_points) + return points + + +@pytest.mark.parametrize("kind", ["text", "reasoning", "tool_call"]) +def test_ttft_seconds_are_recorded_once_without_usage( + monkeypatch: pytest.MonkeyPatch, telemetry: tuple, kind: str +) -> None: + tracer, exporter, reader, _ = telemetry + clock = iter([10_000_000_000, 10_250_000_000]) + monkeypatch.setattr(timing.time, "time_ns", lambda: next(clock)) + with timing.bind_request_start(timing.RequestStart(1, "http")): + with tracer.start_as_current_span("call_llm") as owner: + with timing.ModelTiming(streaming=True, model="openai/test") as call: + call.observe(None) + call.observe(kind) + call.observe("text") + assert TTFT not in owner.attributes + attempt = exporter.get_finished_spans()[0] + assert attempt.attributes["gen_ai.span.kind"] == "llm" + assert attempt.attributes["gen_ai.request.stream"] is True + assert type(attempt.attributes[TTFT]) is float + assert attempt.attributes[TTFT] == 0.25 + assert attempt.attributes["veadk.model.first_token_time_unix_ns"] == 10_250_000_000 + points = ttft_points(reader) + assert len(points) == 1 + assert (points[0].count, points[0].sum) == (1, 0.25) + assert dict(points[0].attributes) == { + "gen_ai.request.model": "openai/test", + "gen_ai.operation.name": "chat", + } + + +@pytest.mark.parametrize("mode", ["non_streaming", "empty", "unsupported"]) +def test_missing_observation_has_no_ttft(telemetry: tuple, mode: str) -> None: + tracer, exporter, reader, _ = telemetry + with tracer.start_as_current_span("call_llm") as owner: + if mode == "unsupported": + timing.mark_uninstrumented_model(owner, streaming=True) + assert "gen_ai.request.stream" not in owner.attributes + else: + with timing.ModelTiming(streaming=mode == "empty", model="test") as call: + call.observe("text" if mode == "non_streaming" else None) + for span in exporter.get_finished_spans(): + assert TTFT not in span.attributes + if span.name == "model_request": + assert span.attributes["gen_ai.request.stream"] is (mode == "empty") + assert ttft_points(reader) == [] + + +@pytest.mark.parametrize("offset", [-1, 0]) +def test_clock_boundary( + monkeypatch: pytest.MonkeyPatch, telemetry: tuple, offset: int +) -> None: + _, exporter, reader, _ = telemetry + diagnostic = Mock() + monkeypatch.setattr(timing.logger, "warning", diagnostic) + clock = iter([1_000_000_000, 1_000_000_000 + offset]) + monkeypatch.setattr(timing.time, "time_ns", lambda: next(clock)) + with timing.ModelTiming(streaming=True, model="test") as call: + call.observe("text") + call.observe("text") + attempt = exporter.get_finished_spans()[0] + assert attempt.attributes["veadk.model.first_token_status"] == "observed" + assert diagnostic.call_count == int(offset < 0) + if offset < 0: + assert TTFT not in attempt.attributes + assert ttft_points(reader) == [] + else: + assert attempt.attributes[TTFT] == 0.0 + point = ttft_points(reader)[0] + assert (point.count, point.sum) == (1, 0.0) + + +@pytest.mark.parametrize("error", [RuntimeError, asyncio.CancelledError, GeneratorExit]) +@pytest.mark.parametrize("observed", [False, True]) +def test_interruption_preserves_only_observed_ttft( + telemetry: tuple, error: type[BaseException], observed: bool +) -> None: + _, exporter, reader, _ = telemetry + with pytest.raises(error): + with timing.ModelTiming(streaming=True, model="test") as call: + if observed: + call.observe("text") + raise error() + attempt = exporter.get_finished_spans()[0] + assert attempt.end_time is not None + assert (TTFT in attempt.attributes) is observed + points = ttft_points(reader) + assert len(points) == int(observed) + if observed: + assert points[0].count == 1 + + +def test_metrics_do_not_depend_on_recording_spans( + monkeypatch: pytest.MonkeyPatch, telemetry: tuple +) -> None: + _, exporter, reader, _ = telemetry + monkeypatch.setattr(timing.trace, "get_tracer", lambda *args: NoOpTracer()) + with timing.ModelTiming(streaming=True, model="test") as call: + call.observe("text") + assert exporter.get_finished_spans() == () + assert ttft_points(reader)[0].count == 1 + + +def test_metric_failure_does_not_replace_model_error_or_expose_details( + monkeypatch: pytest.MonkeyPatch, telemetry: tuple +) -> None: + _, exporter, _, recorder = telemetry + record = Mock(side_effect=ValueError("private metric failure details")) + monkeypatch.setattr(recorder.streaming_time_to_first_token, "record", record) + diagnostic = Mock() + monkeypatch.setattr(portal_metrics.logger, "warning", diagnostic) + with pytest.raises(RuntimeError, match="model failed"): + with timing.ModelTiming(streaming=True, model="test") as call: + call.observe("text") + call.observe("text") + raise RuntimeError("model failed") + assert record.call_count == 1 + assert diagnostic.call_count == 1 + assert "private metric failure details" not in str(diagnostic.call_args) + assert TTFT in exporter.get_finished_spans()[0].attributes + + +def test_retries_never_reuse_or_duplicate_ttft( + monkeypatch: pytest.MonkeyPatch, telemetry: tuple +) -> None: + tracer, exporter, reader, _ = telemetry + clock = iter( + [1_000_000_000, 1_100_000_000, 2_000_000_000, 3_000_000_000, 3_500_000_000] + ) + monkeypatch.setattr(timing.time, "time_ns", lambda: next(clock)) + with tracer.start_as_current_span("call_llm"): + for model, observed in [ + ("primary", True), + ("primary", False), + ("fallback", True), + ]: + with timing.ModelTiming(streaming=True, model=model) as call: + if observed: + call.observe("text") + attempts = [ + span for span in exporter.get_finished_spans() if span.name == "model_request" + ] + assert attempts[0].attributes[TTFT] == 0.1 + assert TTFT not in attempts[1].attributes + assert attempts[2].attributes[TTFT] == 0.5 + assert sorted( + (p.attributes["gen_ai.request.model"], p.count, p.sum) + for p in ttft_points(reader) + ) == [("fallback", 1, 0.5), ("primary", 1, 0.1)] + + +@pytest.mark.asyncio +async def test_concurrent_requests_keep_metric_models_isolated( + telemetry: tuple, +) -> None: + _, exporter, reader, _ = telemetry + + async def run(model: str) -> None: + with timing.ModelTiming(streaming=True, model=model) as call: + await asyncio.sleep(0) + call.observe("text") + await asyncio.sleep(0) + call.observe("text") + + await asyncio.gather(run("one"), run("two")) + points = ttft_points(reader) + assert {p.attributes["gen_ai.request.model"] for p in points} == {"one", "two"} + assert all(p.count == 1 for p in points) + for span in exporter.get_finished_spans(): + point = next( + p + for p in points + if p.attributes["gen_ai.request.model"] + == span.attributes["gen_ai.request.model"] + ) + assert point.sum == span.attributes[TTFT] + + +def test_final_response_callbacks_do_not_duplicate_ttft(telemetry: tuple) -> None: + from types import SimpleNamespace + + from google.adk.models.llm_request import LlmRequest + from google.adk.models.llm_response import LlmResponse + from google.genai import types + + _, _, reader, recorder = telemetry + context = SimpleNamespace( + run_config=None, agent=SimpleNamespace(model_api_base="https://example.invalid") + ) + with timing.ModelTiming(streaming=True, model="test") as call: + call.observe("text") + for usage in ( + None, + types.GenerateContentResponseUsageMetadata(prompt_token_count=1), + ): + recorder.record_call_llm( + context, + "event", + LlmRequest(model="test"), + LlmResponse(usage_metadata=usage), + ) + assert ttft_points(reader)[0].count == 1 + + +def test_unconfigured_meter_provider_needs_no_exporter( + monkeypatch: pytest.MonkeyPatch, telemetry: tuple +) -> None: + from opentelemetry.metrics import NoOpMeterProvider + + _, exporter, reader, _ = telemetry + monkeypatch.setattr( + portal_metrics.metrics_api, "get_meter", NoOpMeterProvider().get_meter + ) + monkeypatch.setattr( + portal_metrics, "portal_metric_recorder", portal_metrics.PortalMetricRecorder() + ) + with timing.ModelTiming(streaming=True, model="test") as call: + call.observe("text") + assert TTFT in exporter.get_finished_spans()[0].attributes + assert ttft_points(reader) == [] diff --git a/veadk/tracing/telemetry/portal_metrics.py b/veadk/tracing/telemetry/portal_metrics.py index e7ee18c21..98e228098 100644 --- a/veadk/tracing/telemetry/portal_metrics.py +++ b/veadk/tracing/telemetry/portal_metrics.py @@ -262,6 +262,20 @@ def force_flush(self) -> bool: force_flush = getattr(self.provider, "force_flush", None) return bool(force_flush()) if force_flush else True + def record_model_ttft(self, duration: float, *, model: str) -> None: + """Record seconds at the first SDK output, without requiring usage.""" + try: + self.streaming_time_to_first_token.record( + duration, + attributes={ + "gen_ai.request.model": model, + "gen_ai.operation.name": "chat", + }, + ) + except Exception: + # Telemetry must not replace model output or expose backend details. + logger.warning("Failed to record model TTFT metric") + def record_call_llm( self, invocation_context: InvocationContext, @@ -344,13 +358,6 @@ def record_call_llm( } self.chat_exception_counter.add(1, exception_attributes) - # TODO: Get streaming time to first token - # time_to_frist_token = 0.1 - # if self.streaming_time_to_first_token: - # self.streaming_time_to_first_token.record( - # time_to_frist_token, attributes=attributes - # ) - # TODO: Get streaming time to generate # time_to_generate = 1.0 # if self.streaming_time_to_generate: diff --git a/veadk/tracing/telemetry/timing.py b/veadk/tracing/telemetry/timing.py index a69b0f5c8..82e0d2113 100644 --- a/veadk/tracing/telemetry/timing.py +++ b/veadk/tracing/telemetry/timing.py @@ -28,6 +28,11 @@ from opentelemetry import trace from opentelemetry.trace import Span +from veadk.tracing.telemetry import portal_metrics +from veadk.utils.logger import get_logger + +logger = get_logger(__name__) + @dataclass(frozen=True) class RequestStart: @@ -115,17 +120,24 @@ def annotate_request_start(span: Span) -> None: class ModelTiming: """One SDK request; this context manager never attaches OTel context.""" - def __init__(self, *, streaming: bool, model: str): + def __init__(self, *, streaming: bool, model: str) -> None: self.streaming = streaming + self.model = str(model) self.first_token_time: int | None = None self.owner = trace.get_current_span() self.span = trace.get_tracer(__name__).start_span( - "model_request", attributes={"gen_ai.request.model": str(model)} + "model_request", + attributes={ + "gen_ai.request.model": self.model, + "gen_ai.span.kind": "llm", + "gen_ai.request.stream": streaming, + }, ) self._spans = (self.span, self.owner) for span in self._spans: annotate_request_start(span) - self._set("veadk.model.start_time_unix_ns", time.time_ns()) + self.start_time = time.time_ns() + self._set("veadk.model.start_time_unix_ns", self.start_time) self._set("veadk.model.streaming", streaming) self._set("veadk.model.request_scope", "sdk_request") self._set( @@ -155,6 +167,21 @@ def observe(self, output_type: str | None) -> None: {"veadk.model.first_token_type": output_type}, timestamp=self.first_token_time, ) + self._record_first_token_duration(self.first_token_time) + + def _record_first_token_duration(self, first_token_time: int) -> None: + """Record one SDK request's observed duration, independent of tracing.""" + duration = (first_token_time - self.start_time) / 1e9 + if duration < 0: + logger.warning("Skipping TTFT because the wall clock moved backwards") + return + if self.span.is_recording(): + self.span.set_attribute( + portal_metrics.Meters.LLM_STREAMING_TIME_TO_FIRST_TOKEN, duration + ) + portal_metrics.portal_metric_recorder.record_model_ttft( + duration, model=self.model + ) def __exit__(self, exc_type, exc_value, traceback) -> None: outcome = "completed" From c4da5b6b7a9500ead6e798824fed2f589ba9a194 Mon Sep 17 00:00:00 2001 From: "wujiaming.ai" Date: Mon, 2 Nov 2026 12:09:07 +0800 Subject: [PATCH 2/3] fix(tracing): replace custom timing fields with standard telemetry Represent HTTP, Runner and SDK boundaries with native span timestamps. Remove custom timing attributes and first-token events without aliases. Use standard error status and bounded error types, and retain once-per- request TTFT attributes and histogram recording. Update bilingual documentation and regression tests. After synchronization, 294 affected tests and pre-commit pass. Full regression has 8053 passing cases and the previously reproduced unrelated Markdown MIME failure. Change-Id: I3b4f2eacb84bb1c378915cb244e68497190738cd --- docs/content/docs/framework/tracing.en.mdx | 27 +- docs/content/docs/framework/tracing.mdx | 27 +- .../apmplus-ttft/2026-11-02-apmplus-ttft.md | 52 +++ .../2026-11-02-apmplus-ttft.zh.md | 52 +++ specs/model-timing/README.md | 39 +-- specs/model-timing/README.zh.md | 39 +-- tests/models/test_model_timing_adapters.py | 79 ++--- tests/test_model_timing.py | 320 ++++++++++++------ tests/test_model_ttft.py | 60 +++- .../telemetry/exporters/inmemory_exporter.py | 2 - veadk/tracing/telemetry/telemetry.py | 10 - veadk/tracing/telemetry/timing.py | 187 +++++----- 12 files changed, 548 insertions(+), 346 deletions(-) diff --git a/docs/content/docs/framework/tracing.en.mdx b/docs/content/docs/framework/tracing.en.mdx index ffe573483..67e9f442b 100644 --- a/docs/content/docs/framework/tracing.en.mdx +++ b/docs/content/docs/framework/tracing.en.mdx @@ -189,24 +189,23 @@ In a multi-agent scenario, spans are linked through `parent_span_id`, showing th -## Request, model, and first-token timestamps +## Request spans and streaming TTFT -VeADK's default LiteLLM and Ark Responses adapters add the following extension attributes to model spans when OpenTelemetry tracing is enabled. Timestamp attributes use UTC Unix nanoseconds. +VeADK uses native OpenTelemetry span start/end times to describe execution boundaries. VeADK AgentKit/Harness HTTP applications create an `http_request` server span at ASGI ingress, before body parsing, and end it when the application finishes. Direct VeADK Runner execution creates a `runner_request` span; a Runner invoked inside the HTTP request reuses that request scope. These boundaries exclude client/network/gateway delays before the application receives the request. -| Attribute | Meaning | +Each LiteLLM Chat or Ark Responses SDK request creates a `model_request` client span under the owning model span. Its native start time is the same local SDK-request timestamp used to calculate TTFT; it is not provider inference start. VeADK-issued retries/fallbacks create separate spans. Hidden provider/LiteLLM retries remain within the observed SDK call. + +| Attribute | Type / meaning | | --- | --- | -| `veadk.request.start_time_unix_ns` | HTTP ASGI entry in VeADK AgentKit/Harness apps, or direct VeADK Runner execution entry. | -| `veadk.request.start_source` | `http` or `runner`; an inherited HTTP timestamp takes precedence. | -| `veadk.model.start_time_unix_ns` | Start of one adapter SDK request, not provider inference start. | -| `veadk.model.streaming` | Actual model SDK request mode, independent of HTTP SSE transport. | -| `veadk.model.first_token_time_unix_ns` | Receipt of the first nonempty generated content delta. | -| `veadk.model.first_token_type` | `text`, `reasoning`, or `tool_call`. | -| `veadk.model.first_token_status` | `observed`, `non_streaming`, `no_output`, or `unsupported`. | +| `gen_ai.span.kind` | `llm` on an SDK request span. | +| `gen_ai.request.model` | Actual requested model. | +| `gen_ai.request.stream` | Boolean actual SDK streaming mode, independent of HTTP SSE or Runner configuration. | +| `gen_ai.chat_completions.streaming_time_to_first_token` | Floating-point seconds from SDK request start to its first generated delta. | -First-token capture excludes role/id/signature metadata, empty deltas, usage, heartbeats, and completion-only aggregates. It does not require token usage or content tracing. One chunk may contain several tokens, so this is an SDK-observed first-output timestamp. Non-streaming calls have no first-token timestamp; completion time is never substituted. +The first nonempty text, reasoning, or tool-call delta records TTFT once. Metadata, empty deltas, usage, heartbeats, and completion-only aggregates do not count. Non-streaming, no-output, or uninstrumented paths omit TTFT; unknown SDK mode is not inferred from Runner configuration. One chunk can contain multiple tokens, so this is an SDK-observed duration, not a provider-side per-token timestamp. -Each SDK request creates a `model_request` child span; the owning model span also receives the latest attempt's custom timestamp/status fields. VeADK-issued retries and fallbacks create separate attempts. Internal LiteLLM/provider retries remain within the observed SDK request (`veadk.model.request_scope=sdk_request`). Unsupported external/custom engines are explicitly marked; invocation span start is not used as model start. Applications outside the VeADK HTTP factories must install the request timing middleware or use VeADK Runner to establish a request timestamp. Client-render timing and TPOT histogram reporting are separate capabilities. +The same value is recorded once in the `gen_ai.chat_completions.streaming_time_to_first_token` Histogram, unit `s`, using the existing global MeterProvider. Dimensions are `gen_ai.request.model` and `gen_ai.operation.name=chat`. Metrics do not depend on token usage or trace sampling; export requires a configured metrics pipeline. Negative wall-clock intervals are omitted with a diagnostic; genuine measured zero is valid. -Each instrumented `model_request` child is labeled `gen_ai.span.kind=llm` and carries Boolean `gen_ai.request.stream` from the actual SDK request. When the first generated delta arrives, it also carries floating-point `gen_ai.chat_completions.streaming_time_to_first_token` in seconds: `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9`. These standard fields describe the individual SDK request, not the outer `call_llm` aggregate. Existing custom timestamps and legacy attributes remain available. +Failed model requests set native Span Status to `ERROR` and `error.type` to `llm_error`, `timeout`, or `cancelled`. Request spans use `request_error`, `timeout`, or `cancelled`; HTTP 5xx responses use `http_error`. Explicit generator closure is not an error. Already observed TTFT survives interruption, and exception text is not added by this instrumentation. -The same observation is recorded once in the `gen_ai.chat_completions.streaming_time_to_first_token` Histogram, unit `s`, through the existing global MeterProvider. Metrics do not require token usage or a sampled trace; export still requires a configured metrics pipeline. Dimensions are `gen_ai.request.model` (the actual requested model) and `gen_ai.operation.name=chat`. Non-streaming, no-output, and unsupported requests produce no TTFT sample or attribute. Negative wall-clock intervals are omitted with a diagnostic; genuine zero elapsed time is valid. Retries/fallbacks have separate observations, and values observed before cancellation or failure remain recorded. +The instrumentation does not export custom `veadk.request.*` or `veadk.model.*` attributes or a custom first-token event. Start and first-output values remain internal calculation state. This replaces the previous custom timing fields without compatibility aliases. Client-render timing and TPOT histogram reporting remain outside this feature. diff --git a/docs/content/docs/framework/tracing.mdx b/docs/content/docs/framework/tracing.mdx index e16edcaa0..f95e586c1 100644 --- a/docs/content/docs/framework/tracing.mdx +++ b/docs/content/docs/framework/tracing.mdx @@ -187,24 +187,23 @@ Tracing 数据由一系列 **Span** 组成，每个 Span 记录一次操作（ -## 请求、模型与首 Token 时间戳 +## 请求 Span 与流式 TTFT -启用 OpenTelemetry Tracing 后，VeADK 默认 LiteLLM 和 Ark Responses 适配器会在模型 Span 上添加以下扩展属性。时间戳统一采用 UTC Unix 纳秒。 +VeADK 使用 OpenTelemetry Span 原生起止时间表达执行边界。VeADK AgentKit/Harness HTTP 应用在 ASGI 入口、请求体解析前创建 `http_request` server Span，在应用执行结束时关闭。直接执行 VeADK Runner 时创建 `runner_request` Span；在 HTTP 请求中调用 Runner 时复用该请求范围。上述边界不包含应用接收请求之前的客户端、网络和网关耗时。 -| 属性 | 含义 | +每次 LiteLLM Chat 或 Ark Responses SDK 请求，在所属模型 Span 下创建 `model_request` client Span。其原生开始时间与 TTFT 计算使用的本地 SDK 请求起点相同，不代表服务端开始推理。VeADK 发起的重试/降级分别创建 Span；供应商/LiteLLM 内部不可观测的重试仍属于同一次 SDK 调用。 + +| 属性 | 类型 / 含义 | | --- | --- | -| `veadk.request.start_time_unix_ns` | VeADK AgentKit/Harness 应用的 HTTP ASGI 入口，或直接调用 VeADK Runner 的执行入口。 | -| `veadk.request.start_source` | `http` 或 `runner`；继承的 HTTP 时间戳优先。 | -| `veadk.model.start_time_unix_ns` | 一次适配器 SDK 请求的开始，不是服务端开始推理。 | -| `veadk.model.streaming` | 实际模型 SDK 请求模式，与 HTTP SSE 传输独立。 | -| `veadk.model.first_token_time_unix_ns` | 收到首个非空生成内容增量的时间。 | -| `veadk.model.first_token_type` | `text`、`reasoning` 或 `tool_call`。 | -| `veadk.model.first_token_status` | `observed`、`non_streaming`、`no_output` 或 `unsupported`。 | +| `gen_ai.span.kind` | SDK 请求 Span 上为 `llm`。 | +| `gen_ai.request.model` | 实际请求的模型。 | +| `gen_ai.request.stream` | 布尔值，表示实际 SDK 流式模式，不依赖 HTTP SSE 或 Runner 配置。 | +| `gen_ai.chat_completions.streaming_time_to_first_token` | 从 SDK 请求开始到首个生成增量到达的浮点秒数。 | -首 Token 采集排除角色/id/签名元数据、空增量、usage、心跳和仅完成时返回的聚合内容。不依赖 token usage 或内容采集。一个 chunk 可含多个 token，因此这里表示 SDK 侧观测到首输出的时间。非流式调用没有首 Token 时间戳，不能用响应完成时间替代。 +首个非空文本、推理或工具调用增量触发一次 TTFT 记录。元数据、空增量、usage、心跳和仅完成时返回的聚合内容不计入。非流式、无输出或未埋点路径省略 TTFT；SDK 模式未知时不从 Runner 配置推导。一个 chunk 可含多个 token，因此这是 SDK 侧观测耗时，不是供应商侧逐 token 时间戳。 -每次 SDK 请求建立 `model_request` 子 Span，所属模型 Span 同时记录最近一次尝试的自定义时间戳/状态字段。VeADK 发起的重试和 fallback 分别记录尝试；LiteLLM/Provider 内部重试计入所观测的 SDK 请求（`veadk.model.request_scope=sdk_request`）。不支持的外部/自定义引擎明确标记，不用 invocation Span 起点替代模型开始。未使用 VeADK HTTP 工厂的应用需要安装请求计时中间件或使用 VeADK Runner，才能建立请求时间戳。客户端渲染计时和 TPOT 直方图上报属于独立能力。 +同一个值通过现有全局 MeterProvider，在 `gen_ai.chat_completions.streaming_time_to_first_token` Histogram 记录一次，单位为 `s`。维度为 `gen_ai.request.model` 和 `gen_ai.operation.name=chat`。指标不依赖 token usage 或 Trace 采样；导出需要配置指标链路。负时钟间隔省略并产生诊断；真正测得的零值有效。 -每个已埋点 `model_request` 子 Span 标记 `gen_ai.span.kind=llm`，并由实际 SDK 请求设置布尔属性 `gen_ai.request.stream`。首个生成 delta 到达时，还会设置浮点属性 `gen_ai.chat_completions.streaming_time_to_first_token`，单位为秒，计算方式为 `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9`。这些标准字段描述单次 SDK 请求，不描述外层 `call_llm` 聚合。现有自定义时间戳和旧属性继续保留。 +失败模型请求设置原生 Span Status 为 `ERROR`，`error.type` 为 `llm_error`、`timeout` 或 `cancelled`。请求 Span 使用 `request_error`、`timeout` 或 `cancelled`；HTTP 5xx 响应使用 `http_error`。主动关闭生成器不算错误。已观测的 TTFT 在中断后保留，本埋点不添加异常正文。 -同一观测值通过现有全局 MeterProvider，在 `gen_ai.chat_completions.streaming_time_to_first_token` Histogram 中记录一次，单位为 `s`。指标不依赖 token usage 或 Trace 采样，但导出仍需配置指标链路。维度为 `gen_ai.request.model`（实际请求模型）和 `gen_ai.operation.name=chat`。非流式、无输出或不支持埋点的请求不产生 TTFT 样本或属性。负时钟间隔省略并产生诊断；真正测得的零耗时有效。重试/降级分别观测，取消或失败前已观测到的值仍保留。 +本埋点不再导出自定义 `veadk.request.*`、`veadk.model.*` 属性或自定义首 Token 事件。开始时间和首输出值仅作为内部计算状态。此变更替代此前自定义计时字段，不保留兼容别名。客户端渲染计时和 TPOT Histogram 上报不在本功能范围内。 diff --git a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md index e50d9db73..6cda84613 100644 --- a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md +++ b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md @@ -7,6 +7,8 @@ Component: [model-timing](../../../specs/model-timing/README.md). Predecessor: [first-token-timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.md). Inspected revision: `d9ef697b82fde94373737aae518148df348e60b0` on `feat/first-token-timestamps` (PR #1190). +Current contract: the standards-only revision at the end of this document supersedes the earlier custom-field preservation decision. Earlier sections retain historical evidence. + ## Background and evidence The [PR review comment](https://github.com/volcengine/veadk-python/pull/1190#issuecomment-6514480806) requires the standard streaming flag, a seconds-valued TTFT span attribute, and actual TTFT Histogram recording. The supplied APMPlus Trace specification (revision 261) and Metrics specification (revision 17), read on 2026-11-02, agree with those requirements. @@ -124,3 +126,53 @@ The user explicitly authorized commit and push. PR #1190 had already been squash After synchronization, `uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q` passed all **156 tests**. `uv run --no-sync --extra dev pre-commit run --all-files` passed. `uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q` finished with **8044 passed, 1 failed, 55 skipped, 4 xfailed**, plus **6 passing subtests**, in 407.20s. The sole failure remains the previously reproduced baseline Markdown MIME mismatch; its production/test files are unchanged between the original PR head and the synchronized base. The repository-wide gate remains `fail`; no assertion was weakened. This authorization covers pushing `fix/apmplus-ttft`, not opening another PR. + +## Approved standards-only revision (2026-11-02) + +The user explicitly removed consumer compatibility as a requirement and authorized immediate implementation. This supersedes FR-1/2/4/5/6 preservation of custom telemetry: remove all `veadk.request.*` / `veadk.model.*` timing attributes and the custom first-token event. Native HTTP/Runner spans own request start/end; SDK spans use the exact SDK start as native `start_time`. Only the standard stream and TTFT attributes/Histogram remain. Failed requests use Status `ERROR` with bounded `error.type`; timeout and cancellation are identified, while explicit generator closure is not an error. Do not capture exception text. + +Update request context propagation, final telemetry/exporter hooks, timing/adapter tests, and both documentation languages. Preserve generator yield isolation, stream cleanup, independent retries, no-usage metrics, and no-output omission. Verify negative assertions for custom attributes/events, exact native start, request/model parentage, status/error privacy, and existing response behavior. Native request spans are the replacement for request-start attributes; this is not removal of request timing. The user approved this contract change; no old aliases or compatibility bridge are required. Historical test results above describe the preceding revision only. + +### Standards-only implementation and evidence (2026-11-02) + +Comparison base: `95fd4c63`; the working diff replaces custom telemetry without compatibility aliases, as explicitly requested. Production changes are limited to `timing.py`, removal of final-response annotation from `telemetry.py`, and removal of exporter annotation from `inmemory_exporter.py`. Native request spans retain request-boundary timing and preserve context across producer advancement/closure without leaking it through yields. Existing app factories and Runner use their existing installation points. No credentials, dependency metadata, deployment, commit, or push changes are part of this revision. + +| Gate | Status | Evidence or limitation | +| --- | --- | --- | +| Change Basis | PASS | Complete working diff against `95fd4c63`; no unrelated changes. | +| Contract | PASS | User-approved removal; updated CON-1..9 use native intervals and standard attributes/status. | +| Impact | PASS | S-1..4 include request/model spans, callbacks/exporters, lifecycle, and docs. | +| Portfolio | PASS | Native span and Histogram assertions, provider-boundary tests, HTTP/Runner tests, failure injection, regression. | +| Baseline | PASS | Four new regression cases failed before implementation, then passed. | +| Execution | BLOCKED | Scoped checks pass; default regression retains the previously reproduced unrelated MIME failure. | +| Evaluation | PASS | 56/56 changed executable production lines; no missing changed decision arcs. | +| Handoff | PASS | Local implementation and limitations documented; no compatibility alias or unverified cloud claim. | + +#### Change Impact + +| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | +| --- | --- | --- | --- | --- | --- | +| Standard-only | CON-1/2/6/7 | Request/model spans and exports | `timing.py`, annotation removals | Custom fields persist; native interval or parentage is wrong | S-1 Medium | +| Standard-only | CON-3/4/8/9 | TTFT and Histogram | Existing recorder plus timing/adapter tests | Missing/duplicate samples or changed units | S-2 Medium | +| Standard-only | CON-5 | Request context, retries, failure/close | Middleware, Runner wrapper, real SDK adapters | Context leak, wrong status, lost original error or cleanup | S-3 High | +| Standard-only | CON-1..9 | Bilingual specs and user docs | Updated tracing MDX and component pair | Old custom-field contract is presented as current | S-4 Medium | + +#### Test Portfolio + +| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | +| --- | --- | --- | --- | --- | --- | --- | +| S-1 | OTel exporter and ASGI/Runner | Contract/integration | Exact model start, request before body read, parentage, unsupported mode | Native times/parents; zero custom attributes/events | 84 focused and 294 affected tests | VERIFIED | +| S-2 | Real OTel reader and adapters | Controlled clock/state transitions | All output kinds, no output/usage, retries, no trace sampling, metric failure | Exact seconds/count/sum and omissions | Focused/affected tests retain prior Histogram assertions | VERIFIED | +| S-3 | Async producer and request spans | Failure injection/concurrency | Timeout, cancellation, explicit close, close error, HTTP 5xx, inherited scope | Original errors/outputs; correct ERROR/error.type; no exception text; context restored | Focused/affected tests and default regression | VERIFIED | +| S-4 | Bilingual documentation | Identifier/link review and site build | Current standard-only contract and historical predecessor labels | Equivalent identifiers and successful type/build checks | Documentation/static checks | VERIFIED | + +Executed checks: + +- `uv run --no-sync --extra dev pytest tests/test_model_ttft.py -q -k 'only_standard or model_failure'`: before implementation **4 failed, 20 deselected**; after implementation **4 passed, 20 deselected**. +- `uv run --no-sync --extra dev pytest tests/test_model_timing.py tests/test_model_ttft.py tests/models/test_model_timing_adapters.py -q`: **84 passed**, zero failures/skips, including the strengthened HTTP-before-body assertion. +- `MODEL_AGENT_API_KEY=offline-test-placeholder uv run --no-sync --extra dev pytest tests/models tests/test_model_timing.py tests/test_model_ttft.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py tests/test_runner.py tests/runner/test_runner_contract.py tests/integrations/agentkit/test_app.py tests/cloud/test_harness_app_contract.py tests/cloud/test_harness_app_http.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-standard-coverage.json`: **294 passed**, zero failures/skips. The value is synthetic and provider calls are controlled. Changed executable production-line coverage: **56/56 (100%)**; no coverage exclusions added. +- `uv run --no-sync --extra dev pytest -n 2 -m 'not codex_smoke and not piagent_smoke' -q`: **8053 passed, 1 failed, 55 skipped, 4 xfailed**, plus **6 passing subtests**, 422.58s. The sole failure is the previously reproduced `test_success_uses_trusted_scope_and_hashes_utf8_bytes` baseline mismatch. Production/test files for that failure remain unchanged. No failures were hidden or assertions loosened. +- `uv run --no-sync --extra dev pre-commit run --all-files`: **pass** after formatting; includes Ruff and secret checks. `npm --prefix docs run types:check`, `npm --prefix docs run build`, paired identifiers, relative links, function-length and diff-whitespace checks: **pass**. +- Live cloud/provider validation: **not_run**, outside the authorized local scope. The original feature's cloud evidence does not validate this new span topology. Residual compatibility impact is deliberate removal of custom fields and added native request parent spans. + +Publication authorization (2026-11-02): the user explicitly requested committing and pushing the standards-only revision. Fetch confirmed unchanged remote base `65f30f28` and branch head `95fd4c63`; rebase onto `origin/main` was up to date. After synchronization, all 294 affected tests and all applicable pre-commit hooks passed. The previously recorded full-regression baseline limitation remains unchanged. diff --git a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md index 2f0e258ee..daa7f6fa4 100644 --- a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md +++ b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md @@ -7,6 +7,8 @@ 前序设计：[first-token-timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md)。 检查版本：`feat/first-token-timestamps` 的 `d9ef697b82fde94373737aae518148df348e60b0`（PR #1190）。 +当前契约：本文末尾的仅标准字段修订取代前文保留自定义字段的决定。前文保留历史证据。 + ## 背景与证据 [PR 评论](https://github.com/volcengine/veadk-python/pull/1190#issuecomment-6514480806) 要求补齐标准流式标记、以秒为单位的 TTFT Span 属性及真正的 TTFT Histogram 记录。2026-11-02 读取的指定 APMPlus Trace 规范（revision 261）和 Metrics 规范（revision 17）与这些要求一致。 @@ -124,3 +126,53 @@ R-1/2/4 跨可观测契约，定为 Medium。R-3 可能影响常用路径的模 同步后，`uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q` 的 **156 项测试全部通过**。`uv run --no-sync --extra dev pre-commit run --all-files` 通过。 `uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q` 结果为 **8044 passed、1 failed、55 skipped、4 xfailed**，另有 **6 项子测试通过**，耗时 407.20s。唯一失败仍为此前已复现的基线 Markdown MIME 不匹配；其生产/测试文件在原 PR head 与同步后基线之间没有变化。仓库级检查仍为 `fail`，没有放宽断言。本次授权包含推送 `fix/apmplus-ttft`，不包含新建另一个 PR。 + +## 已批准的仅标准字段修订（2026-11-02） + +用户明确不考虑已有消费者，并授权立即实施。本修订替代 FR-1/2/4/5/6 中保留自定义遥测的决定：移除全部 `veadk.request.*` / `veadk.model.*` 计时属性及自定义首 Token 事件。原生 HTTP/Runner Span 负责请求起止时间；SDK Span 将精确 SDK 开始时间设为原生 `start_time`。只保留标准流式与 TTFT 属性/Histogram。失败请求使用 Status `ERROR` 和有限类别的 `error.type`；区分超时、取消，主动关闭生成器不算错误。不采集异常正文。 + +同步请求上下文传递、最终遥测/导出器钩子、计时/适配器测试及双语文档。保留生成器 yield 隔离、流清理、独立重试、无 usage 指标及无输出省略行为。验证无自定义属性/事件、精确原生起点、请求/模型父子关系、错误状态/隐私及原响应行为。原生请求 Span 替代请求开始属性，不删除请求计时能力。用户已批准该契约变化，无需旧别名或兼容桥接。上方历史测试结果仅适用于前一修订。 + +### 仅标准字段实现与证据（2026-11-02） + +比较基线：`95fd4c63`；工作区差异按用户明确要求替代自定义遥测，不保留兼容别名。生产修改仅包含 `timing.py`、移除 `telemetry.py` 中最终响应注解、移除 `inmemory_exporter.py` 中导出器注解。原生请求 Span 保留请求边界计时，并在生产者推进/关闭时绑定上下文，不跨 yield 泄漏。应用工厂和 Runner 复用既有安装点。本修订不包含凭证、依赖清单、部署、提交或推送变更。 + +| Gate | 状态 | 证据或限制 | +| --- | --- | --- | +| Change Basis | PASS | 已检查相对 `95fd4c63` 的全部工作区差异；无无关修改。 | +| Contract | PASS | 用户批准删除；更新的 CON-1..9 使用原生区间及标准属性/状态。 | +| Impact | PASS | S-1..4 覆盖请求/模型 Span、回调/导出器、生命周期和文档。 | +| Portfolio | PASS | 原生 Span 与 Histogram 断言、供应商边界测试、HTTP/Runner 测试、故障注入及回归。 | +| Baseline | PASS | 四个新增回归场景在实现前失败，实现后通过。 | +| Execution | BLOCKED | 范围内检查通过；默认回归保留此前已复现的无关 MIME 失败。 | +| Evaluation | PASS | 覆盖 56/56 个变更生产可执行行；无缺失变更分支。 | +| Handoff | PASS | 本地实现与限制已记录；无兼容别名或未经验证的云端声明。 | + +#### Change Impact + +| Change ID | 变更契约 | 受影响面 | 仓库证据 | 失败模式 | 风险 | +| --- | --- | --- | --- | --- | --- | +| Standard-only | CON-1/2/6/7 | 请求/模型 Span 及导出 | `timing.py`、注解移除 | 自定义字段残留；原生区间或父子关系错误 | S-1 Medium | +| Standard-only | CON-3/4/8/9 | TTFT 和 Histogram | 既有 recorder 与计时/适配器测试 | 样本遗漏/重复或单位改变 | S-2 Medium | +| Standard-only | CON-5 | 请求上下文、重试、失败/关闭 | 中间件、Runner 包装、真实 SDK 适配器 | 上下文泄漏、状态错误、原异常或清理丢失 | S-3 High | +| Standard-only | CON-1..9 | 双语契约与用户文档 | 更新的 tracing MDX 和组件文档对 | 把旧自定义字段契约表述为现状 | S-4 Medium | + +#### Test Portfolio + +| Risk ID | 边界 | 方法 | 场景 | 判定依据 | 证据 | 状态 | +| --- | --- | --- | --- | --- | --- | --- | +| S-1 | OTel exporter 和 ASGI/Runner | 契约/集成 | 精确模型起点、读取 body 前请求范围、父子关系、未知模式 | 原生时间/父子关系；零自定义属性/事件 | 84 项定向与 294 项受影响测试 | VERIFIED | +| S-2 | 真实 OTel reader 和适配器 | 受控时钟/状态转换 | 所有输出类型、无输出/usage、重试、不采样 Trace、指标失败 | 精确秒数/count/sum 及省略规则 | 定向/受影响测试保留先前 Histogram 断言 | VERIFIED | +| S-3 | 异步生产者和请求 Span | 故障注入/并发 | 超时、取消、主动关闭、关闭异常、HTTP 5xx、继承范围 | 原始异常/输出；正确 ERROR/error.type；无异常正文；上下文恢复 | 定向/受影响测试及默认回归 | VERIFIED | +| S-4 | 双语文档 | 标识符/链接评审及站点构建 | 现行仅标准字段契约和前序历史标记 | 标识符等价，类型/构建检查成功 | 文档/静态检查 | VERIFIED | + +已执行检查： + +- `uv run --no-sync --extra dev pytest tests/test_model_ttft.py -q -k 'only_standard or model_failure'`：实现前 **4 failed、20 deselected**；实现后 **4 passed、20 deselected**。 +- `uv run --no-sync --extra dev pytest tests/test_model_timing.py tests/test_model_ttft.py tests/models/test_model_timing_adapters.py -q`：**84 passed**，零失败/跳过，包含加强的读取 HTTP body 前断言。 +- `MODEL_AGENT_API_KEY=offline-test-placeholder uv run --no-sync --extra dev pytest tests/models tests/test_model_timing.py tests/test_model_ttft.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py tests/test_runner.py tests/runner/test_runner_contract.py tests/integrations/agentkit/test_app.py tests/cloud/test_harness_app_contract.py tests/cloud/test_harness_app_http.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-standard-coverage.json`：**294 passed**，零失败/跳过。该值为合成占位值，供应商调用受控。生产变更可执行行覆盖率：**56/56（100%）**；没有添加覆盖率排除。 +- `uv run --no-sync --extra dev pytest -n 2 -m 'not codex_smoke and not piagent_smoke' -q`：**8053 passed、1 failed、55 skipped、4 xfailed**，另有 **6 项子测试通过**，耗时 422.58s。唯一失败为此前已复现的 `test_success_uses_trusted_scope_and_hashes_utf8_bytes` 基线不匹配。该失败涉及的生产/测试文件未修改。没有隐藏失败或放宽断言。 +- `uv run --no-sync --extra dev pre-commit run --all-files`：格式化后 **pass**，包含 Ruff 与密钥扫描。`npm --prefix docs run types:check`、`npm --prefix docs run build`、双语标识符、相对链接、函数长度及 diff 空白检查：**pass**。 +- 真实云/供应商验证：**not_run**，超出本次授权的本地范围。原功能的云端证据不能证明新的 Span 拓扑。剩余兼容性影响是有意删除自定义字段，以及增加原生请求父 Span。 + +发布授权（2026-11-02）：用户明确要求提交并推送仅标准字段修订。Fetch 确认远端基线 `65f30f28` 和分支 head `95fd4c63` 未变化；rebase 到 `origin/main` 已是最新。同步后 294 项受影响测试及所有适用 pre-commit 检查通过。此前记录的全量回归基线限制未变化。 diff --git a/specs/model-timing/README.md b/specs/model-timing/README.md index 4c30dbc44..51b3fa60e 100644 --- a/specs/model-timing/README.md +++ b/specs/model-timing/README.md @@ -6,35 +6,26 @@ Component ID: `model-timing`; revision: 2026-11-02; status: active. ## Responsibility and interfaces -Own SDK-observed request/model/first-output timestamps in `veadk/tracing/telemetry/timing.py`, model adapters, Runner, and VeADK HTTP application factories. Consumers are existing OpenTelemetry exporters and trace dumps. No new configuration, credentials, dependencies, or response payload fields are required. +Own native request/model spans and standard streaming TTFT in `veadk/tracing/telemetry/timing.py`, with model adapters, Runner, and VeADK HTTP factories. `portal_metrics.py` owns the existing Histogram instrument; the configured global MeterProvider owns export. No new configuration, credentials, dependencies, or agent response fields are introduced. ## Contracts -- CON-1: `veadk.request.start_time_unix_ns` is captured at HTTP ASGI entry, before request parsing, in VeADK AgentKit/Harness applications. `veadk.request.start_source` is `http`. Direct VeADK Runner calls use Runner execution entry and source `runner`. An inherited HTTP timestamp takes precedence. This excludes client/network/gateway delays before ASGI entry. -- CON-2: `veadk.model.start_time_unix_ns` is captured immediately before each adapter SDK request (`LiteLLMClient.acompletion` or Ark `aresponses`). Each request has a child `model_request` span under the owning model span; its model attribute identifies the requested model. Internal provider/LiteLLM retry/fallback activity is opaque and included in that SDK request. VeADK-issued retries/fallbacks create separate child spans. Successful/latest attempt custom timestamp/status fields also annotate the owning model span. This is not provider inference start. -- CON-3: For streaming requests, `veadk.model.first_token_time_unix_ns` is the local receipt time of the first nonempty generated content delta. `veadk.model.first_token_type` is `text`, `reasoning`, or `tool_call`. Empty deltas, role/id/signature metadata, heartbeats, usage, and completion-only aggregates do not count. A chunk can contain several tokens; no provider-side token generation timestamp is claimed. Record once, without requiring usage or storing content. -- CON-4: `veadk.model.streaming` describes the actual SDK request. `veadk.model.first_token_status` is `observed`, `non_streaming`, `no_output`, or `unsupported`. Non-streaming requests never synthesize a first-token timestamp from their complete response. Unsupported/custom/external engines explicitly expose absent model timing rather than treating an invocation span start as model start. -- CON-5: Each attempt ends on completion, error, cancellation, or generator closure. Already observed timestamps survive interruption. Model/request context does not leak between concurrent invocations or through async-generator yields. Original outputs, exceptions, cancellation, retry rules, and close behavior remain intact. -- CON-6: Wall-clock timestamps are UTC Unix nanoseconds. They may be used for trace correlation; no cross-host subtraction or monotonic-duration/TPOT guarantee is introduced. Trace attributes carry timestamps so existing JSON dumps retain them. First output also emits a timestamped `veadk.model.first_token` event. +- CON-1: VeADK AgentKit/Harness HTTP factories create a native `http_request` SERVER span at ASGI entry, before body parsing, ending when the application finishes. Direct Runner execution owns a `runner_request` span. An inherited HTTP request span is reused by Runner. Neither boundary includes pre-ingress client/network/gateway delays. +- CON-2: Each observable SDK request has a `model_request` CLIENT child under the current model/agent context. Its native start is the local SDK start used by TTFT calculation. VeADK-issued retries/fallbacks have separate spans; hidden provider/LiteLLM retries remain within the observed SDK request. This is not provider inference start. +- CON-3: First output is the first nonempty text, reasoning, or tool-call delta. Empty/role/id/signature metadata, usage, heartbeats, and completion-only aggregates do not count. A chunk may contain several tokens. First-output receipt is internal state, latched once without requiring usage or storing content. +- CON-4: `gen_ai.request.stream` is the actual SDK Boolean mode. `gen_ai.chat_completions.streaming_time_to_first_token` is floating-point seconds from SDK start to first output. Non-streaming/no-output/uninstrumented paths omit TTFT. Unknown actual SDK mode is not inferred from Runner configuration. +- CON-5: Spans end on completion, failure, cancellation, and explicit generator closure. Request context is attached only during producer advancement/closure, not across generator yields. Model failures set native Status `ERROR` with `error.type=llm_error`, `timeout`, or `cancelled`. Request failures use `request_error`, `timeout`, or `cancelled`; HTTP 5xx uses `http_error`. Explicit generator closure is not an error. Original outputs, exceptions, and cleanup are preserved. +- CON-6: Native start/end timestamps use OpenTelemetry units. TTFT converts the local Unix-nanosecond difference to seconds; no cross-host or monotonic-clock guarantee is introduced. Negative intervals are omitted with a bounded diagnostic; genuine zero elapsed time is valid. Already observed TTFT survives later interruption. +- CON-7: SDK spans carry `gen_ai.span.kind=llm` and `gen_ai.request.model`. Standard model fields belong to each SDK span, not its aggregate owner. Do not export `veadk.request.*`, `veadk.model.*`, or a custom first-token event; do not duplicate native span times in attributes. No compatibility aliases are retained, as explicitly authorized by the user. +- CON-8: Record the same observed TTFT exactly once in the existing `gen_ai.chat_completions.streaming_time_to_first_token` Histogram, unit `s`, independent of usage and trace sampling. No observations means no sample. Metric-recording failures emit a bounded diagnostic without backend details and do not replace model output/error. +- CON-9: TTFT metric dimensions are the actual `gen_ai.request.model` and existing conversational `gen_ai.operation.name=chat`. Unknown provider/response-model values are omitted. No prompts, responses, exception text, or per-request identifiers are added. Export configuration remains owned by the existing MeterProvider. -## Security and compatibility +## Compatibility and security -Only timing, bounded status/type labels, and existing model identifiers are added. No prompts, response content, or credentials are stored by timing instrumentation. HTTP middleware does not buffer bodies or alter SSE. Existing content-tracing controls remain applicable. Public APIs and serialized agent events stay compatible. Rollback removes additive instrumentation without migrating stored data. Generic ADK/custom application factories without the middleware can only provide a Runner timestamp when using VeADK Runner, or no request timestamp; no earlier start is fabricated. +This intentionally replaces custom timing fields and their mirrored aggregate fields with native span boundaries and standard telemetry. Callers must inspect request/SDK spans and standard TTFT; no legacy aliases remain. Application responses and public Agent invocation signatures do not change. The HTTP middleware does not buffer bodies. New request spans can change trace parentage. Exception text is not recorded by this instrumentation. Rollback requires reverting the coherent timing, hook, test, and documentation change. -## Verification +## Verification and change record -CON-1/5: ASGI boundary, async-generator/context/cancellation tests. CON-2/3/4/5: real adapter tests with controlled provider boundaries, plus real cloud Runtime/provider E2E. CON-6: exporter/dump contract assertions. Changed executable production lines must reach at least 95% coverage against the branch base, with no coverage exclusions added to satisfy the gate. +Tests: `tests/test_model_timing.py`, `tests/test_model_ttft.py`, `tests/models/test_model_timing_adapters.py`, and affected Runner/application/exporter tests. Cover native start/parentage, absence of custom fields/events, actual SDK mode, first-output classification, failures/privacy, retry/close/cancellation, yield/task isolation, and real in-memory Histogram data. Changed production-line coverage must reach at least 95%; no exclusions may be added to satisfy it. -Change design and evidence: [first-token-timestamps](../../prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md). - -Predecessor verification: 55 focused timing/adapter tests, 244 affected tests and 6 real cloud cases passed; changed production-line coverage is 100% (208/208). The unrelated default-regression failure is documented in the linked PRD. - -## Standard streaming and TTFT (2026-11-02) - -[APMPlus TTFT design](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md) extends CON-2/4/6. Existing verification above covers the predecessor only. - -- CON-7: Each instrumented SDK `model_request` child is labeled `gen_ai.span.kind=llm` and carries Boolean `gen_ai.request.stream` from the actual SDK request. Its `gen_ai.chat_completions.streaming_time_to_first_token` is a float in seconds, calculated from the same locally stored model-start and first-output timestamps. These standard fields belong to individual SDK children, not aggregate owner spans. Keep existing custom and legacy attributes compatible. Unsupported SDK mode is unknown, not inferred from Runner configuration. -- CON-8: On the first valid streaming output, record the identical TTFT once in the existing same-name Histogram with unit `s`. This does not depend on usage or trace sampling. Each SDK retry/fallback is independent. Non-streaming/no-output/unsupported requests produce no sample. Negative wall-clock intervals produce a bounded diagnostic and no duration; measured zero is valid. Already recorded observations survive error/cancellation/close. Metric-recording errors are diagnosed without content or exception details and do not replace model results/errors. -- CON-9: TTFT metrics use known stable dotted dimensions: `gen_ai.request.model` for the actual requested model and `gen_ai.operation.name=chat` for the existing conversational operation. Unknown provider/response-model values are omitted. No content or per-request identifiers are dimensions. The existing global MeterProvider owns export; no new provider, credentials, or configuration is installed. Verify CON-7..9 with controlled clocks, SDK adapters, in-memory span export, and a real metrics reader. - -Local CON-7..9 verification: 20 focused TTFT tests and 156 affected tests passed; changed production-line coverage is 100% (21/21), with 4/4 changed decision arcs covered. See the linked APMPlus TTFT design for the repository regression result and its baseline limitation. No new live cloud verification is claimed. +[Design and executed evidence](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md). The standards-only revision supersedes the predecessor's custom-field contracts. Historical cloud results do not validate this revision; current verification is local unless explicitly recorded otherwise. diff --git a/specs/model-timing/README.zh.md b/specs/model-timing/README.zh.md index c7bf64539..efd216b5c 100644 --- a/specs/model-timing/README.zh.md +++ b/specs/model-timing/README.zh.md @@ -6,35 +6,26 @@ ## 职责与接口 -负责 `veadk/tracing/telemetry/timing.py`、模型适配器、Runner 和 VeADK HTTP 应用工厂中的 SDK 侧请求开始、模型开始及首输出时间戳。消费者是现有 OpenTelemetry 导出器和 Trace dump。无需新增配置、凭证、依赖或响应载荷字段。 +负责 `veadk/tracing/telemetry/timing.py` 中的原生请求/模型 Span 及标准流式 TTFT，配合模型适配器、Runner 和 VeADK HTTP 工厂。`portal_metrics.py` 管理现有 Histogram instrument；已配置的全局 MeterProvider 负责导出。不引入新配置、凭证、依赖或 Agent 响应字段。 ## 契约 -- CON-1：VeADK AgentKit/Harness 应用在 HTTP ASGI 入口、请求解析前记录 `veadk.request.start_time_unix_ns`，`veadk.request.start_source` 为 `http`。直接调用 VeADK Runner 时以 Runner 执行入口为起点，来源为 `runner`。继承的 HTTP 时间戳优先。不包含 ASGI 入口之前的客户端、网络和网关耗时。 -- CON-2：每次适配器 SDK 请求（`LiteLLMClient.acompletion` 或 Ark `aresponses`）之前记录 `veadk.model.start_time_unix_ns`。每次请求在所属模型 Span 下建立 `model_request` 子 Span，其模型属性标识请求模型。Provider/LiteLLM 内部重试和 fallback 不可见，计入本次 SDK 请求；VeADK 发起的重试和 fallback 分别建立子 Span。成功或最近一次尝试的自定义时间戳/状态字段同时写入所属模型 Span。这不是模型服务端开始推理的时间。 -- CON-3：流式请求的 `veadk.model.first_token_time_unix_ns` 为首个非空生成内容增量在本地收到的时间，`veadk.model.first_token_type` 为 `text`、`reasoning` 或 `tool_call`。空增量、角色/id/签名元数据、心跳、usage 和仅完成时返回的聚合内容不计入。一个 chunk 可含多个 token，不声称取得服务端生成 token 的时间。仅记录一次，不依赖 usage，也不存储内容。 -- CON-4：`veadk.model.streaming` 表示实际 SDK 请求模式。`veadk.model.first_token_status` 为 `observed`、`non_streaming`、`no_output` 或 `unsupported`。非流式请求不使用完整响应时间伪造首 Token 时间。不支持的自定义/外部执行引擎明确标记模型计时缺失，不把 invocation Span 起点当成模型开始。 -- CON-5：每次尝试在完成、异常、取消或生成器关闭时结束。已观测到的时间戳在中断后保留。模型/请求上下文不会在并发调用之间或通过异步生成器 yield 泄漏。原有输出、异常、取消、重试规则和关闭行为保持一致。 -- CON-6：时钟时间戳统一为 UTC Unix 纳秒，用于 Trace 关联；不引入跨主机相减、单调时钟耗时或 TPOT 保证。时间戳写入 Trace 属性，现有 JSON dump 可以保留；首输出另产生带时间戳的 `veadk.model.first_token` 事件。 +- CON-1：VeADK AgentKit/Harness HTTP 工厂在 ASGI 入口、请求体解析前创建原生 `http_request` SERVER Span，应用执行结束时关闭。直接执行 Runner 时拥有 `runner_request` Span。Runner 复用继承的 HTTP 请求 Span。两种边界均不含入口之前的客户端、网络和网关耗时。 +- CON-2：每次可观测 SDK 请求，在当前模型/Agent 上下文下拥有 `model_request` CLIENT 子 Span。原生开始时间就是 TTFT 计算使用的本地 SDK 起点。VeADK 发起的重试/降级分别创建 Span；供应商/LiteLLM 内部不可观测重试仍计入同一次 SDK 请求。这不是服务端开始推理时间。 +- CON-3：首输出为首个非空文本、推理或工具调用 delta。空增量、角色/id/签名元数据、usage、心跳和仅完成时返回的聚合内容不计入。一个 chunk 可含多个 token。首输出接收时间仅作为内部状态锁定一次，不依赖 usage，也不保存内容。 +- CON-4：`gen_ai.request.stream` 为实际 SDK 布尔模式。`gen_ai.chat_completions.streaming_time_to_first_token` 为 SDK 起点到首输出的浮点秒数。非流式/无输出/未埋点路径省略 TTFT。实际 SDK 模式未知时不从 Runner 配置推导。 +- CON-5：Span 在完成、失败、取消和主动关闭生成器时结束。仅在推进/关闭生产者时绑定请求上下文，不跨生成器 yield 保留。模型失败设置原生 Status `ERROR`，`error.type=llm_error`、`timeout` 或 `cancelled`。请求失败使用 `request_error`、`timeout` 或 `cancelled`；HTTP 5xx 使用 `http_error`。主动关闭生成器不算错误。保留原始输出、异常及清理行为。 +- CON-6：原生起止时间戳采用 OpenTelemetry 单位。TTFT 将本地 Unix 纳秒差值换算为秒，不引入跨主机或单调时钟保证。负间隔省略并产生有限诊断；真正零耗时有效。后续中断不影响已经观测的 TTFT。 +- CON-7：SDK Span 携带 `gen_ai.span.kind=llm` 和 `gen_ai.request.model`。标准模型字段属于每次 SDK Span，不属于聚合的所属 Span。不导出 `veadk.request.*`、`veadk.model.*` 或自定义首 Token 事件，不在属性中重复原生 Span 时间。根据用户明确授权，不保留兼容别名。 +- CON-8：同一 TTFT 观测在现有 `gen_ai.chat_completions.streaming_time_to_first_token` Histogram 中恰好记录一次，单位为 `s`，独立于 usage 和 Trace 采样。没有观测就没有样本。指标记录失败时产生不含后端详情的有限诊断，不替换模型输出/异常。 +- CON-9：TTFT 指标维度为实际 `gen_ai.request.model` 和既有对话操作 `gen_ai.operation.name=chat`。未知供应商/响应模型省略。不添加提示词、响应、异常正文或逐请求标识。导出配置仍由现有 MeterProvider 管理。 -## 安全与兼容性 +## 兼容与安全 -只添加时间、有限状态/类型标签和现有模型标识。计时采集不存储提示词、输出内容和凭证。HTTP 中间件不缓存请求体，也不改变 SSE。现有内容采集控制仍适用。公开接口及 Agent 事件序列化保持兼容。回滚只需移除新增采集，无需迁移历史数据。未安装中间件的通用 ADK/自定义应用，仅在使用 VeADK Runner 时提供 Runner 时间，否则不提供请求时间；不伪造更早的起点。 +本变更有意用原生 Span 边界和标准遥测替代自定义计时字段及其聚合镜像字段。调用方应查看请求/SDK Span 和标准 TTFT；不保留旧别名。应用响应与公开 Agent 调用签名不变。HTTP 中间件不缓存请求体。新增请求 Span 可能改变 Trace 父子关系。本埋点不记录异常正文。回滚需要整体还原计时、钩子、测试和文档改动。 -## 验证 +## 验证与变更记录 -CON-1/5：ASGI 入口、异步生成器/上下文/取消测试。CON-2/3/4/5：控制外部 Provider 边界的真实适配器测试，以及真实云端 Runtime/Provider E2E。CON-6：导出与 dump 契约断言。相对分支基线，生产代码变更可执行行覆盖率必须至少 95%，不得为了满足门槛新增覆盖率排除。 +测试：`tests/test_model_timing.py`、`tests/test_model_ttft.py`、`tests/models/test_model_timing_adapters.py` 以及受影响的 Runner/应用/导出器测试。覆盖原生起点/父子关系、无自定义字段/事件、实际 SDK 模式、首输出分类、失败/隐私、重试/关闭/取消、yield/任务隔离及真实内存 Histogram 数据。生产变更行覆盖率至少 95%，不得为达标新增排除。 -变更设计与证据：[first-token-timestamps](../../prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md)。 - -前序变更验证：55 项计时/适配器测试、244 项受影响测试及 6 项真实云端用例通过；生产变更行覆盖率为 100%（208/208）。无关的默认回归失败记录于所链接 PRD。 - -## 标准流式与 TTFT（2026-11-02） - -[APMPlus TTFT 设计](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md) 扩展 CON-2/4/6。上面的已有验证仅覆盖前序变更。 - -- CON-7：每个已埋点 SDK `model_request` 子 Span 标记 `gen_ai.span.kind=llm`，并由实际 SDK 请求设置布尔值 `gen_ai.request.stream`。其 `gen_ai.chat_completions.streaming_time_to_first_token` 为浮点秒数，由本地保存的同一模型开始、首输出时间戳计算。这些标准字段属于单次 SDK 子 Span，不属于聚合的所属 Span。保持现有自定义和旧属性兼容。不支持埋点时 SDK 模式未知，不从 Runner 配置推导。 -- CON-8：首次有效流式输出时，在现有同名、单位为 `s` 的 Histogram 记录同一个 TTFT 一次，不依赖 usage 或 Trace 采样。各 SDK 重试/降级独立。非流式/无输出/不支持埋点的请求不产生样本。负时钟间隔产生有限诊断，不生成耗时；实测零值有效。已记录观测在异常/取消/关闭后保留。指标记录异常产生不含内容和异常详情的诊断，不替代模型结果/异常。 -- CON-9：TTFT 指标使用已知稳定的点分维度：`gen_ai.request.model` 为实际请求模型，`gen_ai.operation.name=chat` 为既有对话操作。未知供应商/响应模型省略。内容和逐请求标识不作为维度。现有全局 MeterProvider 负责导出，不安装新 provider、凭证或配置。通过受控时钟、SDK 适配器、内存 Span 导出和真实指标 reader 验证 CON-7..9。 - -CON-7..9 本地验证：20 项定向 TTFT 测试及 156 项受影响测试通过；生产变更行覆盖率为 100%（21/21），变更分支覆盖 4/4。仓库回归结果及其基线限制见所链接 APMPlus TTFT 设计。不声明新增真实云端验证。 +[设计与执行证据](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md)。仅标准字段修订取代前序自定义字段契约。历史云端结果不证明本修订；除非明确另行记录，本次验证均为本地验证。 diff --git a/tests/models/test_model_timing_adapters.py b/tests/models/test_model_timing_adapters.py index cc70f0adf..cdff3ec65 100644 --- a/tests/models/test_model_timing_adapters.py +++ b/tests/models/test_model_timing_adapters.py @@ -24,6 +24,7 @@ from litellm import ModelResponse from litellm.types.utils import ModelResponseStream from opentelemetry.sdk.trace import TracerProvider +from opentelemetry.trace import StatusCode from opentelemetry.sdk.trace.export import SimpleSpanProcessor from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter from volcenginesdkarkruntime.types.responses import ( @@ -106,25 +107,10 @@ async def complete(self, model, messages, tools, **kwargs): ttft = "gen_ai.chat_completions.streaming_time_to_first_token" assert (ttft in attempt.attributes) is stream if stream: - assert ( - attempt.attributes[ttft] - == ( - attempt.attributes["veadk.model.first_token_time_unix_ns"] - - attempt.attributes["veadk.model.start_time_unix_ns"] - ) - / 1e9 - ) - assert owner.attributes["veadk.model.streaming"] is stream - assert owner.attributes["veadk.model.first_token_status"] == ( - "observed" if stream else "non_streaming" - ) - if stream: - assert ( - owner.attributes["veadk.model.first_token_time_unix_ns"] - >= owner.attributes["veadk.model.start_time_unix_ns"] - ) - else: - assert "veadk.model.first_token_time_unix_ns" not in owner.attributes + assert attempt.attributes[ttft] >= 0 + assert attempt.start_time + attempt.attributes[ttft] * 1e9 <= attempt.end_time + assert not owner.attributes + assert not owner.events assert ( len([s for s in exporter.get_finished_spans() if s.name == "model_request"]) == 1 @@ -173,11 +159,11 @@ async def complete(*args, **kwargs): _ = [r async for r in response] attempt = exporter.get_finished_spans()[0] assert closed == [True] - assert attempt.attributes["veadk.model.outcome"] == { - "error": "error", - "cancel": "cancelled", - "close": "cancelled", - }.get(mode, "completed") + error_type = {"error": "llm_error", "cancel": "cancelled"}.get(mode) + assert attempt.attributes.get("error.type") == error_type + assert attempt.status.status_code is ( + StatusCode.ERROR if error_type else StatusCode.UNSET + ) @pytest.mark.asyncio @@ -190,7 +176,7 @@ async def complete(*args, **kwargs): monkeypatch.setattr(LiteLLMClient, "acompletion", complete) with pytest.raises(RuntimeError, match="request failed"): await TimedLiteLLMClient().acompletion("test", [], [], stream=True) - assert exporter.get_finished_spans()[0].attributes["veadk.model.outcome"] == "error" + assert exporter.get_finished_spans()[0].status.status_code is StatusCode.ERROR @pytest.mark.asyncio @@ -277,13 +263,11 @@ async def responses(*args, **kwargs): assert ( "gen_ai.chat_completions.streaming_time_to_first_token" in attempt.attributes ) is (status == "observed") - assert owner.attributes["veadk.model.first_token_status"] == status - if status == "observed": - assert owner.attributes["veadk.model.first_token_type"] == ( - "tool_call" if mode == "tool_call" else "text" - ) - else: - assert "veadk.model.first_token_time_unix_ns" not in owner.attributes + assert not owner.attributes + assert not owner.events + assert attempt.status.status_code is ( + StatusCode.ERROR if mode == "error" else StatusCode.UNSET + ) assert attempt.end_time is not None if mode != "non_streaming": assert closed == [True] @@ -313,8 +297,11 @@ async def complete(*args, **kwargs): await response.aclose() assert closed == [True] attempt = exporter.get_finished_spans()[0] - assert attempt.attributes["veadk.model.outcome"] == "cancelled" - assert attempt.attributes["veadk.model.first_token_status"] == "no_output" + assert attempt.status.status_code is StatusCode.UNSET + assert ( + "gen_ai.chat_completions.streaming_time_to_first_token" + not in attempt.attributes + ) with pytest.raises(StopAsyncIteration): await anext(response) @@ -340,7 +327,7 @@ async def complete(*args, **kwargs): response = await TimedLiteLLMClient().acompletion("test", [], [], stream=True) with pytest.raises(RuntimeError, match="close failed"): await anext(response) - assert exporter.get_finished_spans()[0].attributes["veadk.model.outcome"] == "error" + assert exporter.get_finished_spans()[0].status.status_code is StatusCode.ERROR @pytest.mark.asyncio @@ -372,7 +359,7 @@ async def complete(self, model, messages, tools, **kwargs): model=model.model, contents=[types.Content(role="user", parts=[types.Part(text="hello")])], ) - with timing.bind_request_start(timing.RequestStart(1, "runner")): + with tracer.start_as_current_span("runner_request"): with tracer.start_as_current_span("call_llm") as owner: responses = [ r async for r in model.generate_content_async(request, stream=True) @@ -380,14 +367,14 @@ async def complete(self, model, messages, tools, **kwargs): assert responses and requests == ["openai/test", "openai/test"] attempts = [s for s in exporter.get_finished_spans() if s.name == "model_request"] assert len(attempts) == 2 - assert attempts[0].attributes["veadk.model.outcome"] == "error" - assert attempts[0].attributes["veadk.model.first_token_status"] == "no_output" - assert "veadk.model.first_token_time_unix_ns" not in attempts[0].attributes - assert attempts[1].attributes["veadk.model.outcome"] == "completed" - assert attempts[1].attributes["veadk.model.first_token_status"] == "observed" - assert ( - owner.attributes["veadk.model.first_token_time_unix_ns"] - == attempts[1].attributes["veadk.model.first_token_time_unix_ns"] - ) + assert attempts[0].status.status_code is StatusCode.ERROR + assert attempts[0].attributes["error.type"] == "llm_error" + ttft = "gen_ai.chat_completions.streaming_time_to_first_token" + assert ttft not in attempts[0].attributes + assert attempts[1].status.status_code is StatusCode.UNSET + assert ttft in attempts[1].attributes + assert not owner.attributes assert all(s.parent.span_id == owner.context.span_id for s in attempts) - assert all(s.attributes["veadk.request.start_time_unix_ns"] == 1 for s in attempts) + assert all( + not any(key.startswith("veadk.") for key in s.attributes) for s in attempts + ) diff --git a/tests/test_model_timing.py b/tests/test_model_timing.py index 5323d930d..3039151de 100644 --- a/tests/test_model_timing.py +++ b/tests/test_model_timing.py @@ -21,6 +21,7 @@ from fastapi import FastAPI from httpx import ASGITransport, AsyncClient from opentelemetry import trace +from opentelemetry.trace import SpanKind, StatusCode from opentelemetry.sdk.trace import TracerProvider from opentelemetry.sdk.trace.export import SimpleSpanProcessor from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter @@ -40,55 +41,60 @@ def spans(monkeypatch): @pytest.mark.parametrize("kind", ["text", "reasoning", "tool_call"]) -def test_first_output_is_latched_without_usage(monkeypatch, spans, kind): +def test_first_output_is_latched_without_usage( + monkeypatch: pytest.MonkeyPatch, spans: tuple, kind: str +) -> None: tracer, exporter = spans clock = iter([100, 200, 300]) monkeypatch.setattr(timing.time, "time_ns", lambda: next(clock)) - with timing.bind_request_start(timing.RequestStart(50, "http")): - with tracer.start_as_current_span("call_llm") as owner: - with timing.ModelTiming(streaming=True, model="openai/test") as call: - call.observe(None) - call.observe(kind) - call.observe("text") - assert owner.attributes["veadk.request.start_time_unix_ns"] == 50 - assert owner.attributes["veadk.model.start_time_unix_ns"] == 100 - assert owner.attributes["veadk.model.first_token_time_unix_ns"] == 200 - assert owner.attributes["veadk.model.first_token_type"] == kind - assert owner.attributes["veadk.model.first_token_status"] == "observed" - assert len(owner.events) == 1 - assert owner.events[0].timestamp == 200 - attempt = next( - s for s in exporter.get_finished_spans() if s.name == "model_request" - ) + with tracer.start_as_current_span("call_llm") as owner: + with timing.ModelTiming(streaming=True, model="openai/test") as call: + call.observe(None) + call.observe(kind) + call.observe("text") + assert not owner.attributes + assert not owner.events + attempt = exporter.get_finished_spans()[0] assert attempt.parent.span_id == owner.context.span_id - assert attempt.attributes["veadk.model.request_scope"] == "sdk_request" - assert attempt.attributes["veadk.model.outcome"] == "completed" - assert "content" not in str(dict(attempt.attributes)) + assert attempt.start_time == 100 + assert attempt.kind is SpanKind.CLIENT + assert ( + attempt.attributes["gen_ai.chat_completions.streaming_time_to_first_token"] + == 1e-7 + ) + assert attempt.status.status_code is StatusCode.UNSET + assert not any(key.startswith("veadk.") for key in attempt.attributes) + assert not attempt.events -@pytest.mark.parametrize( - "streaming,status", [(False, "non_streaming"), (True, "no_output")] -) -def test_no_first_token_is_fabricated(spans, streaming, status): +@pytest.mark.parametrize("streaming", [False, True]) +def test_no_first_token_is_fabricated(spans: tuple, streaming: bool) -> None: tracer, exporter = spans with tracer.start_as_current_span("call_llm") as owner: with timing.ModelTiming(streaming=streaming, model="test") as call: if not streaming: call.observe("text") - assert owner.attributes["veadk.model.first_token_status"] == status - assert "veadk.model.first_token_time_unix_ns" not in owner.attributes + assert not owner.attributes + attempt = exporter.get_finished_spans()[0] + assert attempt.attributes["gen_ai.request.stream"] is streaming + assert ( + "gen_ai.chat_completions.streaming_time_to_first_token" + not in attempt.attributes + ) assert len(exporter.get_finished_spans()) == 2 @pytest.mark.parametrize( - "error,outcome", + "error,error_type", [ - (RuntimeError("failed"), "error"), + (RuntimeError("failed"), "llm_error"), (asyncio.CancelledError(), "cancelled"), - (GeneratorExit(), "cancelled"), + (GeneratorExit(), None), ], ) -def test_interrupted_attempt_retains_output_and_ends(spans, error, outcome): +def test_interrupted_attempt_retains_output_and_ends( + spans: tuple, error: BaseException, error_type: str | None +) -> None: tracer, exporter = spans with tracer.start_as_current_span("call_llm"): with pytest.raises(type(error)): @@ -97,11 +103,14 @@ def test_interrupted_attempt_retains_output_and_ends(spans, error, outcome): raise error attempt = exporter.get_finished_spans()[0] assert attempt.end_time is not None - assert attempt.attributes["veadk.model.first_token_status"] == "observed" - assert attempt.attributes["veadk.model.outcome"] == outcome + assert "gen_ai.chat_completions.streaming_time_to_first_token" in attempt.attributes + assert attempt.attributes.get("error.type") == error_type + assert attempt.status.status_code is ( + StatusCode.ERROR if error_type else StatusCode.UNSET + ) -def test_retry_attempts_have_independent_timestamps(spans): +def test_retry_attempts_have_independent_timestamps(spans: tuple) -> None: tracer, exporter = spans with tracer.start_as_current_span("call_llm") as owner: with pytest.raises(RuntimeError): @@ -111,29 +120,23 @@ def test_retry_attempts_have_independent_timestamps(spans): call.observe("text") attempts = [s for s in exporter.get_finished_spans() if s.name == "model_request"] assert len(attempts) == 2 - assert attempts[0].attributes["veadk.model.first_token_status"] == "no_output" - assert "veadk.model.first_token_time_unix_ns" not in attempts[0].attributes - assert attempts[1].attributes["veadk.model.first_token_status"] == "observed" - assert ( - owner.attributes["veadk.model.start_time_unix_ns"] - == attempts[1].attributes["veadk.model.start_time_unix_ns"] - ) + ttft = "gen_ai.chat_completions.streaming_time_to_first_token" + assert ttft not in attempts[0].attributes + assert attempts[0].status.status_code is StatusCode.ERROR + assert ttft in attempts[1].attributes + assert attempts[1].status.status_code is StatusCode.UNSET + assert attempts[0].start_time <= attempts[1].start_time + assert not owner.attributes -@pytest.mark.parametrize( - "streaming,status", [(True, "unsupported"), (False, "non_streaming")] -) -def test_unsupported_models_do_not_use_invocation_start(spans, streaming, status): +@pytest.mark.parametrize("streaming", [True, False]) +def test_model_timing_does_not_mutate_owner(spans: tuple, streaming: bool) -> None: tracer, _ = spans with tracer.start_as_current_span("call_llm") as owner: - timing.mark_uninstrumented_model(owner, streaming=streaming) - assert owner.attributes["veadk.model.first_token_status"] == status - assert "veadk.model.start_time_unix_ns" not in owner.attributes - assert owner.attributes["veadk.model.streaming"] is streaming - with timing.ModelTiming(streaming=True, model="test") as call: + with timing.ModelTiming(streaming=streaming, model="test") as call: call.observe("text") - timing.mark_uninstrumented_model(owner, streaming=False) - assert owner.attributes["veadk.model.first_token_status"] == "observed" + assert not owner.attributes + assert not owner.events @pytest.mark.parametrize( @@ -157,11 +160,11 @@ def test_unsupported_models_do_not_use_invocation_start(spans, streaming, status ({"function_call": {"arguments": "{"}}, "tool_call"), ], ) -def test_litellm_delta_classification(delta, expected): +def test_litellm_delta_classification(delta: dict, expected: str | None) -> None: assert timing.litellm_output_type(NS(choices=[NS(delta=delta)])) == expected -def test_litellm_metadata_and_object_shapes(): +def test_litellm_metadata_and_object_shapes() -> None: assert timing.litellm_output_type(NS(choices=[])) is None assert timing.litellm_output_type(NS(choices=[NS(delta=None)])) is None assert ( @@ -187,34 +190,43 @@ def test_litellm_metadata_and_object_shapes(): ("response.output_item.added", "", None), ], ) -def test_ark_delta_classification(event_type, delta, expected): +def test_ark_delta_classification( + event_type: str, delta: dict, expected: str | None +) -> None: assert timing.ark_output_type(NS(type=event_type, delta=delta)) == expected @pytest.mark.asyncio -async def test_request_context_is_isolated_across_yields_and_tasks(): +async def test_request_context_is_isolated_across_yields_and_tasks( + spans: tuple, +) -> None: + tracer, _ = spans + async def events(expected): - assert timing.current_request_start() == expected - yield expected.time_ns + assert timing.current_request_span() is expected + assert trace.get_current_span() is expected + yield expected.name await asyncio.sleep(0) - assert timing.current_request_start() == expected - yield expected.source + assert timing.current_request_span() is expected + yield expected.name - first = timing.RequestStart(1, "runner") - second = timing.RequestStart(2, "http") + first, second = tracer.start_span("one"), tracer.start_span("two") a = timing.with_request_timing(events(first), first) b = timing.with_request_timing(events(second), second) - assert await asyncio.gather(anext(a), anext(b)) == [1, 2] - assert timing.current_request_start() is None - assert await asyncio.gather(anext(a), anext(b)) == ["runner", "http"] - assert timing.current_request_start() is None + assert await asyncio.gather(anext(a), anext(b)) == ["one", "two"] + assert timing.current_request_span() is None + assert await asyncio.gather(anext(a), anext(b)) == ["one", "two"] + assert timing.current_request_span() is None await a.aclose() await b.aclose() + first.end() + second.end() @pytest.mark.asyncio -async def test_request_context_restored_on_error_and_close(): - inner = timing.RequestStart(2, "runner") +async def test_request_context_restored_on_error_and_close(spans: tuple) -> None: + tracer, _ = spans + inner, outer = tracer.start_span("inner"), tracer.start_span("outer") closed = [] async def events(): @@ -222,56 +234,66 @@ async def events(): yield 1 raise ValueError("original") finally: - closed.append(timing.current_request_start()) + closed.append(timing.current_request_span()) - with timing.bind_request_start(timing.RequestStart(1, "http")) as outer: + with timing.bind_request_span(outer): wrapped = timing.with_request_timing(events(), inner) assert await anext(wrapped) == 1 - assert timing.current_request_start() == outer + assert timing.current_request_span() is outer with pytest.raises(ValueError, match="original"): await anext(wrapped) - assert timing.current_request_start() == outer + assert trace.get_current_span() is outer assert closed == [inner] wrapped = timing.with_request_timing(events(), inner) await anext(wrapped) await wrapped.aclose() assert closed == [inner, inner] - assert timing.current_request_start() is None + assert timing.current_request_span() is None + inner.end() + outer.end() @pytest.mark.asyncio -async def test_timed_runner_uses_inherited_or_local_start(monkeypatch): - monkeypatch.setattr(timing.time, "time_ns", lambda: 100) +async def test_timed_runner_uses_inherited_or_local_span(spans: tuple) -> None: + tracer, exporter = spans @timing.timed_runner async def run(value): - yield (value, timing.current_request_start()) - - assert [e async for e in run("hello")] == [ - ("hello", timing.RequestStart(100, "runner")) - ] - with timing.bind_request_start(timing.RequestStart(50, "http")): - generator = run("http") - assert await anext(generator) == ("http", timing.RequestStart(50, "http")) - await generator.aclose() - assert timing.current_request_start() is None + with timing.ModelTiming(streaming=False, model="test"): + yield (value, timing.current_request_span()) + + result = [e async for e in run("hello")] + assert result[0][0] == "hello" + request = result[0][1] + assert request.name == "runner_request" + assert request.end_time is not None + assert exporter.get_finished_spans()[0].parent.span_id == request.context.span_id + with tracer.start_as_current_span("http_request") as inherited: + with timing.bind_request_span(inherited): + generator = run("http") + assert await anext(generator) == ("http", inherited) + await generator.aclose() + assert inherited.is_recording() + assert timing.current_request_span() is None + assert ( + len([s for s in exporter.get_finished_spans() if s.name == "runner_request"]) + == 1 + ) @pytest.mark.asyncio async def test_http_boundary_is_before_body_parsing_and_install_is_idempotent( - monkeypatch, -): - monkeypatch.setattr(timing.time, "time_ns", lambda: 100) + spans: tuple, +) -> None: + _, exporter = spans app = FastAPI() @app.post("/run") async def run(payload: dict): - start = timing.current_request_start() - return { - "start": start.time_ns, - "source": start.source, - "value": payload["value"], - } + span = timing.current_request_span() + assert span.name == "http_request" and span.is_recording() + with timing.ModelTiming(streaming=False, model="test"): + return {"value": payload["value"]} timing.install_request_timing(app) timing.install_request_timing(app) @@ -279,17 +301,32 @@ async def run(payload: dict): async with AsyncClient( transport=ASGITransport(app=app), base_url="http://test" ) as client: - response = await client.post("/run", json={"value": "hello"}) - assert response.json() == {"start": 100, "source": "http", "value": "hello"} - assert timing.current_request_start() is None + + async def body(): + request = timing.current_request_span() + assert request is not None and request.name == "http_request" + assert request.is_recording() + yield b'{"value": "hello"}' + + response = await client.post( + "/run", content=body(), headers={"content-type": "application/json"} + ) + assert response.json() == {"value": "hello"} + model, request = exporter.get_finished_spans() + assert request.kind is SpanKind.SERVER + assert request.start_time <= model.start_time <= model.end_time <= request.end_time + assert model.parent.span_id == request.context.span_id + assert not request.attributes + assert timing.current_request_span() is None @pytest.mark.asyncio -async def test_non_http_scopes_and_failures_preserve_context(): +async def test_non_http_scopes_and_failures_preserve_context(spans: tuple) -> None: + _, exporter = spans received = [] async def app(scope, receive, send): - received.append(timing.current_request_start()) + received.append(timing.current_request_span()) if scope["type"] == "http": raise RuntimeError("original") @@ -298,12 +335,91 @@ async def app(scope, receive, send): assert received == [None] with pytest.raises(RuntimeError, match="original"): await middleware({"type": "http"}, None, None) - assert received[1].source == "http" - assert timing.current_request_start() is None + assert received[1].name == "http_request" + assert timing.current_request_span() is None + span = exporter.get_finished_spans()[0] + assert span.status.status_code is StatusCode.ERROR + assert span.attributes["error.type"] == "request_error" + assert not span.events -def test_without_recording_tracer(): +@pytest.mark.asyncio +async def test_http_server_error_response_is_recorded(spans: tuple) -> None: + _, exporter = spans + sent = [] + + async def app(scope, receive, send): + await send({"type": "http.response.start", "status": 503, "headers": []}) + await send({"type": "http.response.body", "body": b"unavailable"}) + + async def send(message): + sent.append(message) + + await timing.RequestTimingMiddleware(app)({"type": "http"}, None, send) + span = exporter.get_finished_spans()[0] + assert span.status.status_code is StatusCode.ERROR + assert span.attributes["error.type"] == "http_error" + assert sent[1]["body"] == b"unavailable" + + +def test_without_recording_tracer() -> None: with trace.use_span(trace.INVALID_SPAN): with timing.ModelTiming(streaming=True, model="test") as call: call.observe("text") - timing.mark_uninstrumented_model(trace.INVALID_SPAN, streaming=True) + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "error,error_type", + [ + (RuntimeError, "request_error"), + (TimeoutError, "timeout"), + (asyncio.CancelledError, "cancelled"), + ], +) +async def test_runner_failure_sets_status_and_releases_context( + spans: tuple, error: type[BaseException], error_type: str +) -> None: + _, exporter = spans + closed = [] + + @timing.timed_runner + async def run(): + try: + yield 1 + raise error("private") + finally: + closed.append(timing.current_request_span()) + + events = run() + assert await anext(events) == 1 + assert timing.current_request_span() is None + with pytest.raises(error): + await anext(events) + request = exporter.get_finished_spans()[0] + assert request.status.status_code is StatusCode.ERROR + assert request.attributes["error.type"] == error_type + assert not request.events + assert closed[0].get_span_context().span_id == request.context.span_id + assert timing.current_request_span() is None + + +@pytest.mark.asyncio +async def test_runner_close_failure_ends_span(spans: tuple) -> None: + _, exporter = spans + + @timing.timed_runner + async def run(): + try: + yield 1 + finally: + raise RuntimeError("close failed") + + events = run() + assert await anext(events) == 1 + with pytest.raises(RuntimeError, match="close failed"): + await events.aclose() + request = exporter.get_finished_spans()[0] + assert request.status.status_code is StatusCode.ERROR + assert request.attributes["error.type"] == "request_error" + assert timing.current_request_span() is None diff --git a/tests/test_model_ttft.py b/tests/test_model_ttft.py index 811460387..daedc1fdf 100644 --- a/tests/test_model_ttft.py +++ b/tests/test_model_ttft.py @@ -72,19 +72,18 @@ def test_ttft_seconds_are_recorded_once_without_usage( tracer, exporter, reader, _ = telemetry clock = iter([10_000_000_000, 10_250_000_000]) monkeypatch.setattr(timing.time, "time_ns", lambda: next(clock)) - with timing.bind_request_start(timing.RequestStart(1, "http")): - with tracer.start_as_current_span("call_llm") as owner: - with timing.ModelTiming(streaming=True, model="openai/test") as call: - call.observe(None) - call.observe(kind) - call.observe("text") - assert TTFT not in owner.attributes + with tracer.start_as_current_span("call_llm") as owner: + with timing.ModelTiming(streaming=True, model="openai/test") as call: + call.observe(None) + call.observe(kind) + call.observe("text") + assert TTFT not in owner.attributes attempt = exporter.get_finished_spans()[0] assert attempt.attributes["gen_ai.span.kind"] == "llm" assert attempt.attributes["gen_ai.request.stream"] is True assert type(attempt.attributes[TTFT]) is float assert attempt.attributes[TTFT] == 0.25 - assert attempt.attributes["veadk.model.first_token_time_unix_ns"] == 10_250_000_000 + assert attempt.start_time == 10_000_000_000 points = ttft_points(reader) assert len(points) == 1 assert (points[0].count, points[0].sum) == (1, 0.25) @@ -99,7 +98,6 @@ def test_missing_observation_has_no_ttft(telemetry: tuple, mode: str) -> None: tracer, exporter, reader, _ = telemetry with tracer.start_as_current_span("call_llm") as owner: if mode == "unsupported": - timing.mark_uninstrumented_model(owner, streaming=True) assert "gen_ai.request.stream" not in owner.attributes else: with timing.ModelTiming(streaming=mode == "empty", model="test") as call: @@ -124,7 +122,7 @@ def test_clock_boundary( call.observe("text") call.observe("text") attempt = exporter.get_finished_spans()[0] - assert attempt.attributes["veadk.model.first_token_status"] == "observed" + assert call.first_token_time == 1_000_000_000 + offset assert diagnostic.call_count == int(offset < 0) if offset < 0: assert TTFT not in attempt.attributes @@ -283,3 +281,45 @@ def test_unconfigured_meter_provider_needs_no_exporter( call.observe("text") assert TTFT in exporter.get_finished_spans()[0].attributes assert ttft_points(reader) == [] + + +def test_only_standard_fields_and_native_model_start( + monkeypatch: pytest.MonkeyPatch, telemetry: tuple +) -> None: + tracer, exporter, _, _ = telemetry + clock = iter([10_000_000_000, 10_250_000_000]) + monkeypatch.setattr(timing.time, "time_ns", lambda: next(clock)) + with tracer.start_as_current_span("call_llm"): + with timing.ModelTiming(streaming=True, model="test") as call: + call.observe("text") + model, owner = exporter.get_finished_spans() + assert model.start_time == 10_000_000_000 + assert model.attributes[TTFT] == 0.25 + for span in (model, owner): + assert not any(key.startswith("veadk.") for key in span.attributes) + assert not any(event.name.startswith("veadk.") for event in span.events) + + +@pytest.mark.parametrize( + "error,error_type", + [ + (RuntimeError, "llm_error"), + (TimeoutError, "timeout"), + (asyncio.CancelledError, "cancelled"), + ], +) +def test_model_failure_uses_standard_error_status( + telemetry: tuple, error: type[BaseException], error_type: str +) -> None: + from opentelemetry.trace import StatusCode + + _, exporter, _, _ = telemetry + with pytest.raises(error): + with timing.ModelTiming(streaming=True, model="test"): + raise error("private details") + span = exporter.get_finished_spans()[0] + assert span.status.status_code is StatusCode.ERROR + assert span.attributes["error.type"] == error_type + assert "private details" not in str(span.attributes) + assert span.status.description is None + assert not span.events diff --git a/veadk/tracing/telemetry/exporters/inmemory_exporter.py b/veadk/tracing/telemetry/exporters/inmemory_exporter.py index c787cfd83..b15a87751 100644 --- a/veadk/tracing/telemetry/exporters/inmemory_exporter.py +++ b/veadk/tracing/telemetry/exporters/inmemory_exporter.py @@ -29,7 +29,6 @@ from veadk.tracing.telemetry.exporters.base_exporter import BaseExporter from veadk.utils.logger import get_logger -from veadk.tracing.telemetry.timing import annotate_request_start logger = get_logger(__name__) _registration_lock = Lock() @@ -197,7 +196,6 @@ def on_start(self, span, parent_context) -> None: span: The span being started parent_context: Parent OpenTelemetry context """ - annotate_request_start(span) if span.name.startswith("invocation"): span.set_attribute("gen_ai.operation.name", "chain") span.set_attribute("gen_ai.span.kind", "workflow") diff --git a/veadk/tracing/telemetry/telemetry.py b/veadk/tracing/telemetry/telemetry.py index eabdb66bb..9f2992f2b 100644 --- a/veadk/tracing/telemetry/telemetry.py +++ b/veadk/tracing/telemetry/telemetry.py @@ -18,7 +18,6 @@ from google.adk.events import Event from google.adk.models.llm_request import LlmRequest from google.adk.models.llm_response import LlmResponse -from google.adk.agents.run_config import StreamingMode from google.adk.tools import BaseTool from opentelemetry import trace from opentelemetry.context import get_value @@ -32,7 +31,6 @@ ) from veadk.tracing.telemetry.content_tracing import should_trace_content from veadk.tracing.telemetry import portal_metrics -from veadk.tracing.telemetry.timing import mark_uninstrumented_model from veadk.utils.logger import get_logger from veadk.utils.misc import safe_json_serialize @@ -394,14 +392,6 @@ def trace_call_llm( if span is None: span = trace.get_current_span() # type: ignore - mark_uninstrumented_model( - span, - streaming=bool( - invocation_context.run_config - and invocation_context.run_config.streaming_mode != StreamingMode.NONE - ), - ) - from veadk.agent import Agent set_common_attributes_on_model_span( diff --git a/veadk/tracing/telemetry/timing.py b/veadk/tracing/telemetry/timing.py index 82e0d2113..c71bb2d08 100644 --- a/veadk/tracing/telemetry/timing.py +++ b/veadk/tracing/telemetry/timing.py @@ -12,143 +12,157 @@ # See the License for the specific language governing permissions and # limitations under the License. -"""SDK-observed model timestamps and isolated request start propagation.""" +"""Native request spans and standard per-SDK-request streaming telemetry.""" from __future__ import annotations import asyncio import functools import time -from collections.abc import AsyncGenerator, Callable, Mapping +from collections.abc import AsyncGenerator, Callable, Iterator, Mapping from contextlib import contextmanager from contextvars import ContextVar -from dataclasses import dataclass +from types import TracebackType from typing import Any from opentelemetry import trace -from opentelemetry.trace import Span +from opentelemetry.trace import Span, SpanKind, StatusCode +from starlette.types import ASGIApp, Message, Receive, Scope, Send from veadk.tracing.telemetry import portal_metrics from veadk.utils.logger import get_logger logger = get_logger(__name__) +_REQUEST_SPAN: ContextVar[Span | None] = ContextVar("veadk_request_span", default=None) -@dataclass(frozen=True) -class RequestStart: - time_ns: int - source: str - - -_REQUEST_START: ContextVar[RequestStart | None] = ContextVar( - "veadk_request_start", default=None -) - - -def current_request_start() -> RequestStart | None: - return _REQUEST_START.get() +def current_request_span() -> Span | None: + return _REQUEST_SPAN.get() @contextmanager -def bind_request_start(start: RequestStart): - token = _REQUEST_START.set(start) +def bind_request_span(span: Span) -> Iterator[Span]: + token = _REQUEST_SPAN.set(span) try: - yield start + with trace.use_span( + span, record_exception=False, set_status_on_exception=False + ): + yield span finally: - _REQUEST_START.reset(token) + _REQUEST_SPAN.reset(token) + + +def _record_error(span: Span, error: BaseException, fallback: str) -> None: + if isinstance(error, GeneratorExit): + return + error_type = ( + "timeout" + if isinstance(error, TimeoutError) + else "cancelled" + if isinstance(error, asyncio.CancelledError) + else fallback + ) + span.set_attribute("error.type", error_type) + span.set_status(StatusCode.ERROR) -async def with_request_timing( - events: AsyncGenerator, start: RequestStart -) -> AsyncGenerator: - """Bind only while advancing/closing; never retain context across yields.""" +async def with_request_timing(events: AsyncGenerator, span: Span) -> AsyncGenerator: + """Attach request context only while advancing or closing the producer.""" try: while True: - with bind_request_start(start): + with bind_request_span(span): try: event = await anext(events) except StopAsyncIteration: return yield event finally: - with bind_request_start(start): + with bind_request_span(span): await events.aclose() def timed_runner(func: Callable) -> Callable: @functools.wraps(func) - async def wrapper(*args, **kwargs): - start = current_request_start() or RequestStart(time.time_ns(), "runner") - events = with_request_timing(func(*args, **kwargs), start) + async def wrapper(*args: Any, **kwargs: Any) -> AsyncGenerator: + inherited = current_request_span() + span = ( + inherited + if inherited is not None + else trace.get_tracer(__name__).start_span("runner_request") + ) + events = with_request_timing(func(*args, **kwargs), span) try: - async for event in events: - yield event + try: + async for event in events: + yield event + finally: + await events.aclose() + except BaseException as error: + if inherited is None: + _record_error(span, error, "request_error") + raise finally: - await events.aclose() + if inherited is None: + span.end() return wrapper class RequestTimingMiddleware: - """Capture ASGI ingress without inspecting or buffering request bodies.""" + """Represent the HTTP execution boundary using a native server span.""" - def __init__(self, app): + def __init__(self, app: ASGIApp) -> None: self.app = app - async def __call__(self, scope, receive, send): + async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: if scope["type"] != "http": await self.app(scope, receive, send) return - with bind_request_start(RequestStart(time.time_ns(), "http")): - await self.app(scope, receive, send) + span = trace.get_tracer(__name__).start_span( + "http_request", kind=SpanKind.SERVER + ) + + async def traced_send(message: Message) -> None: + if message["type"] == "http.response.start" and message["status"] >= 500: + span.set_attribute("error.type", "http_error") + span.set_status(StatusCode.ERROR) + await send(message) + try: + with bind_request_span(span): + await self.app(scope, receive, traced_send) + except BaseException as error: + _record_error(span, error, "request_error") + raise + finally: + span.end() -def install_request_timing(app) -> None: + +def install_request_timing(app: Any) -> None: if getattr(app.state, "_veadk_request_timing_installed", False): return app.add_middleware(RequestTimingMiddleware) app.state._veadk_request_timing_installed = True -def annotate_request_start(span: Span) -> None: - start = current_request_start() - if start is not None and span.is_recording(): - span.set_attribute("veadk.request.start_time_unix_ns", start.time_ns) - span.set_attribute("veadk.request.start_source", start.source) - - class ModelTiming: - """One SDK request; this context manager never attaches OTel context.""" + """One SDK request, with its own native interval and first-output latch.""" def __init__(self, *, streaming: bool, model: str) -> None: self.streaming = streaming self.model = str(model) self.first_token_time: int | None = None - self.owner = trace.get_current_span() + self.start_time = time.time_ns() self.span = trace.get_tracer(__name__).start_span( "model_request", + kind=SpanKind.CLIENT, + start_time=self.start_time, attributes={ "gen_ai.request.model": self.model, "gen_ai.span.kind": "llm", "gen_ai.request.stream": streaming, }, ) - self._spans = (self.span, self.owner) - for span in self._spans: - annotate_request_start(span) - self.start_time = time.time_ns() - self._set("veadk.model.start_time_unix_ns", self.start_time) - self._set("veadk.model.streaming", streaming) - self._set("veadk.model.request_scope", "sdk_request") - self._set( - "veadk.model.first_token_status", - "no_output" if streaming else "non_streaming", - ) - - def _set(self, name: str, value: Any) -> None: - for span in self._spans: - if span.is_recording(): - span.set_attribute(name, value) def __enter__(self) -> ModelTiming: return self @@ -157,21 +171,7 @@ def observe(self, output_type: str | None) -> None: if not self.streaming or self.first_token_time is not None or not output_type: return self.first_token_time = time.time_ns() - self._set("veadk.model.first_token_time_unix_ns", self.first_token_time) - self._set("veadk.model.first_token_type", output_type) - self._set("veadk.model.first_token_status", "observed") - for span in self._spans: - if span.is_recording(): - span.add_event( - "veadk.model.first_token", - {"veadk.model.first_token_type": output_type}, - timestamp=self.first_token_time, - ) - self._record_first_token_duration(self.first_token_time) - - def _record_first_token_duration(self, first_token_time: int) -> None: - """Record one SDK request's observed duration, independent of tracing.""" - duration = (first_token_time - self.start_time) / 1e9 + duration = (self.first_token_time - self.start_time) / 1e9 if duration < 0: logger.warning("Skipping TTFT because the wall clock moved backwards") return @@ -183,30 +183,17 @@ def _record_first_token_duration(self, first_token_time: int) -> None: duration, model=self.model ) - def __exit__(self, exc_type, exc_value, traceback) -> None: - outcome = "completed" - if exc_type is not None: - outcome = ( - "cancelled" - if issubclass(exc_type, (asyncio.CancelledError, GeneratorExit)) - else "error" - ) - self._set("veadk.model.outcome", outcome) + def __exit__( + self, + exc_type: type[BaseException] | None, + exc_value: BaseException | None, + traceback: TracebackType | None, + ) -> None: + if exc_value is not None: + _record_error(self.span, exc_value, "llm_error") self.span.end() -def mark_uninstrumented_model(span: Span, *, streaming: bool) -> None: - annotate_request_start(span) - attributes = getattr(span, "attributes", None) or {} - if "veadk.model.start_time_unix_ns" in attributes or not span.is_recording(): - return - span.set_attribute("veadk.model.streaming", streaming) - span.set_attribute( - "veadk.model.first_token_status", - "unsupported" if streaming else "non_streaming", - ) - - def _field(value: Any, name: str, default=None): return ( value.get(name, default) From 045b0c7bc08ba8acdffa3a57009ef78675bd74f8 Mon Sep 17 00:00:00 2001 From: "wujiaming.ai" Date: Mon, 2 Nov 2026 14:43:28 +0800 Subject: [PATCH 3/3] chore(docs): remove root design specs and opt out of regeneration Remove prd-spec and specs; keep plans and verification summaries in conversation or PR descriptions. Require an explicit user request before creating standalone design/spec documents. Change-Id: Ibabda377bee6fc64b844dfe4164febb4fa1d6cd5 Validation: all pre-commit hooks passed; YAML secret scanner unit tests passed (4 tests). Documentation and workflow guidance only; no runtime code or public API changes. --- AGENTS.md | 18 +- .../apmplus-ttft/2026-11-02-apmplus-ttft.md | 178 ------------------ .../2026-11-02-apmplus-ttft.zh.md | 178 ------------------ .../2026-10-28-stabilize-concurrent-tests.md | 85 --------- ...026-10-28-stabilize-concurrent-tests.zh.md | 85 --------- .../2026-10-28-first-token-timestamps.md | 119 ------------ .../2026-10-28-first-token-timestamps.zh.md | 119 ------------ specs/model-timing/README.md | 31 --- specs/model-timing/README.zh.md | 31 --- 9 files changed, 10 insertions(+), 834 deletions(-) delete mode 100644 prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md delete mode 100644 prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md delete mode 100644 prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.md delete mode 100644 prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.zh.md delete mode 100644 prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md delete mode 100644 prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md delete mode 100644 specs/model-timing/README.md delete mode 100644 specs/model-timing/README.zh.md diff --git a/AGENTS.md b/AGENTS.md index d03a4684e..a9581d0ba 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -5,21 +5,23 @@ VeADK includes a Python SDK, CLI/runtime integrations, and AgentKit Studio with ## Language and document ownership - Keep this repository-wide development standard in English. Use English for new code identifiers, comments, and docstrings; user-facing text follows the owning area's localization rules. -- Keep durable change intent, scope, tasks, evidence, and acceptance in the PR/MR description, linked issue, external design document, or affected user documentation when the change needs long-lived context. Do not create repository-local design or component-spec files by default. +- Do not create standalone PRD or component-spec files, or recreate the root `prd-spec/` and `specs/` directories, as part of routine development. Create such documents only when the user explicitly requests them; generic skills or workflow templates do not make them mandatory. +- Discuss change-specific intent, scope, design decisions, and acceptance criteria in the conversation or PR description. Update existing maintained documentation when an affected interface or behavior needs clarification. +- When updating existing bilingual documentation, keep its language counterparts semantically equivalent in the same change, including identifiers, commands, examples, limits, and acceptance criteria. - Before modifying frontend code, read `frontend/SPEC.md`; also apply it to its supporting backend interfaces as specified there. It remains the Studio development standard and is not replaced or translated by this document. - Preserve existing user-documentation conventions: the documentation site uses Chinese `.mdx` and English `.en.mdx`; bilingual module/example READMEs use English `README.md` and Chinese `README.zh.md`. ## Required development workflow 1. **Inspect and agree on scope.** Read the affected implementation, tests, and contracts. When the user describes a requirement, propose an implementation plan and wait for the user to be satisfied before making edits. Distinguish verified facts from assumptions. -2. **Plan before implementation.** For features, refactors, and bugfixes, size the change against the affected contracts and risk. Record background/evidence, goals, non-goals, affected files, tasks, tests, risks, and acceptance criteria in the PR/MR description, linked issue, external design document, or user documentation when the change needs durable context. -3. **Assess contracts.** Identify changes to ownership, APIs, configuration, state/data, events, permissions, security, compatibility, runtime behavior, or observability. Record the contract impact or no-impact rationale in the PR/MR description, linked issue, external design document, or user documentation as appropriate. Do not backfill unrelated contracts. -4. **Clear scope review.** Review plan consistency, feasibility, boundaries, errors, security, compatibility, and testability. Resolve blockers and record user approval before modifying production code or tests. -5. **Implement against the approved design.** Map changes to requirements/tasks, write a failing regression or contract test first, then implement and refactor within scope. Contract or scope changes return to design review before implementation proceeds. +2. **Plan before implementation.** Explain the implementation approach, affected areas, risks, and verification plan in the conversation. Scale the detail to the change; no separate design document is required. +3. **Assess component contracts.** Check affected ownership, APIs, configuration, state/data, events, permissions, security, compatibility, runtime behavior, and observability. Update relevant existing documentation when necessary; do not generate separate component specs or no-impact reports by default. +4. **Review the approach.** Check feasibility, boundaries, errors, security, compatibility, and testability before editing. Resolve blockers and obtain user agreement for material scope changes. No standalone design review artifact or PRD/spec approval gate is required. +5. **Implement within the agreed scope.** Write a failing regression or contract test first for bugfixes, then implement and refactor within scope. Reassess the plan when contracts or scope change. 6. **Verify and review.** Run affected tests first, then required repository and component gates. Review both implementation correctness and edge cases, resource handling, security, test quality, and contract alignment. Fix blocking findings and rerun affected checks. -7. **Reconcile and deliver.** Synchronize affected user docs/examples and required generated artifacts. Record actual verification commands, results, unverified areas, and remaining risks. All agreed tasks and acceptance criteria must be satisfied before declaring completion; deferred scope requires user agreement. +7. **Reconcile and deliver.** Update affected existing user docs/examples, their applicable language counterparts, and required generated artifacts. Summarize actual verification commands, results, unverified areas, and remaining risks in the conversation or PR description. All agreed tasks and acceptance criteria must be satisfied before declaring completion; deferred scope requires user agreement. -Pure documentation, translation, or formatting changes that preserve runtime behavior and public contracts do not need a separate change design. They still require an agreed approach, applicable bilingual updates where the owning document convention requires them, and proportionate checks. This exception includes maintaining these development guidelines; it does not exempt code or behavioral changes. +Documentation, translation, formatting, and development-guideline changes require an agreed approach, applicable updates to existing language counterparts, and proportionate checks. They do not require a separate design document. ## Implementation boundaries @@ -57,7 +59,7 @@ Use the repository-local Python environment and current `pyproject.toml`, `pytes - Before committing, run `uv run --extra dev pre-commit run --all-files` and unit tests after synchronizing the branch as described below. Pre-commit includes Ruff and secret scanning; it does not replace browser, integration, or runtime verification. - Prefer targeted checks during iteration. Expand to affected integration/E2E and regression gates for shared or high-risk changes and final delivery; explain any omitted required check. - Record check outcomes as `pass`, `fail`, `blocked`, `not_run`, or `not_applicable`, with reasons for the last three. Include the tested revision/diff scope and execution date. Skipped tests do not prove the relevant behavior. -- Keep change-specific review and verification summaries in the PR/MR description, linked issue, external design document, or affected user documentation as appropriate. Separate evidence artifacts are optional when useful; OpenSpec and a multi-report hierarchy are not prerequisites. +- Keep change-specific review and verification summaries in the conversation or PR/MR description by default, with links to existing issues or external documentation when useful. Do not generate PRD/spec files, OpenSpec records, or a multi-report hierarchy unless the user requests them. ## Git and execution safety diff --git a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md deleted file mode 100644 index 6cda84613..000000000 --- a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md +++ /dev/null @@ -1,178 +0,0 @@ -# APMPlus streaming and TTFT telemetry - -[中文版](2026-11-02-apmplus-ttft.zh.md) - -Change ID: `apmplus-ttft`; created/revised: 2026-11-02; status: approved. -Component: [model-timing](../../../specs/model-timing/README.md). -Predecessor: [first-token-timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.md). -Inspected revision: `d9ef697b82fde94373737aae518148df348e60b0` on `feat/first-token-timestamps` (PR #1190). - -Current contract: the standards-only revision at the end of this document supersedes the earlier custom-field preservation decision. Earlier sections retain historical evidence. - -## Background and evidence - -The [PR review comment](https://github.com/volcengine/veadk-python/pull/1190#issuecomment-6514480806) requires the standard streaming flag, a seconds-valued TTFT span attribute, and actual TTFT Histogram recording. The supplied APMPlus Trace specification (revision 261) and Metrics specification (revision 17), read on 2026-11-02, agree with those requirements. - -`ModelTiming` currently records custom timestamps and actual SDK streaming mode. `PortalMetricRecorder` already creates the correctly named TTFT Histogram with unit `s`, but its recording remains TODO. `record_call_llm()` runs on response callbacks and places existing measurements behind a usage check; it cannot establish exactly one TTFT measurement per SDK request. The original design explicitly excluded Histograms; this successor proposes that narrowly scoped extension. - -## Goals and non-goals - -Add `gen_ai.request.stream` and `gen_ai.chat_completions.streaming_time_to_first_token` to each observable SDK request span, and record the same TTFT value once in the existing Histogram. Preserve custom timestamp fields and model behavior. - -Exclude TPOT, unrelated metric renaming, token accounting changes, client-render timing, hidden provider retries, new exporters/configuration/dependencies, frontend changes, and cloud deployment. Historical cloud evidence does not validate this new change. - -## Requirements and scenarios - -- FR-1: An instrumented `model_request` span has Boolean `gen_ai.request.stream` from the actual SDK request, independent of Runner streaming configuration. Preserve `veadk.model.streaming` and legacy attributes. -- FR-2: The first nonempty text, reasoning, or tool-call delta produces a floating-point seconds value `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9` under `gen_ai.chat_completions.streaming_time_to_first_token`. Reuse the same stored request-start timestamp used by custom attributes. Request ingress and outer span start are not calculation inputs. -- FR-3: At that first observation, record the identical value once in the existing same-name Histogram with unit `s`, even without usage or a recording trace span. Repeated chunks and final-response callbacks must not duplicate it. Every observable retry/fallback request owns its own latch and sample. -- FR-4: Non-streaming, no-output, and unsupported requests have no TTFT attribute/sample. Unknown actual SDK mode must not be invented from Runner configuration. A clock regression preserves raw timestamps but omits a negative duration with a bounded diagnostic; zero measured elapsed time is valid, not a missing-value placeholder. -- FR-5: Preserve samples observed before failure, cancellation, or close. Preserve original output, exception propagation, and resource cleanup. A metrics recording failure emits a bounded diagnostic without recording request content or replacing the model result/error. -- FR-6: New metric dimensions use dotted specification names and known stable values only. Include the actual requested model; omit unknown provider/response-model values. Never include prompt/output content, user/session/trace IDs, or response IDs. Continue using the existing global MeterProvider without installing an export pipeline. - -Given metadata followed by a generated delta, only the generated delta records TTFT. Given two requests sharing one outer model span, each SDK child has independent fields and measurements. Given tracing disabled but a configured metrics reader, an observed streaming request still records the Histogram. Given a request with no generated delta, completion cannot fabricate a sample. - -## Design, alternatives, and contract impact - -Keep one measurement owner in `ModelTiming.observe()`. Store the request-start timestamp and model locally so calculation and metric recording do not depend on readable span attributes. Add a focused typed `PortalMetricRecorder` method for recording this measurement; remove only the superseded TTFT TODO. Reuse the existing instrument, unit, and bucket boundaries. - -Use the per-SDK `model_request` child as the authoritative standard LLM span and label it `gen_ai.span.kind=llm`. This avoids presenting an aggregate/retry owner's lifetime as one SDK request. Existing custom timestamp mirroring to `call_llm` remains compatible; standard TTFT is not copied to an aggregate owner, avoiding stale observations after a later no-output attempt. Document this span boundary explicitly. Existing `gen_ai.is_streaming` is retained for compatibility. - -Alternative: record from `record_call_llm()`. Rejected because callback multiplicity, absent usage, and retries would require additional shared state and could duplicate or lose measurements. Alternative: rename/delete custom timestamps. Rejected because timestamps remain useful and removing them would break consumers without satisfying the duration requirement. - -Before implementation, update both model-timing spec languages: extend CON-2/4/6 and add a per-request Histogram contract covering FR-3/5/6. Add a predecessor note to the original design explaining this extension without rewriting historical acceptance. Update both tracing MDX pages. No persistence, permissions, HTTP/event payload, public model invocation signature, or database migration changes are needed. Rollback removes additive standard telemetry; existing custom timestamps remain usable. - -## Tasks and acceptance - -| Requirement | Task | Acceptance | Verification | Result | -| --- | --- | --- | --- | --- | -| FR-1..6 | T-1: reconcile bilingual design/spec and review | AC-1: consistent scope and approved design | Paired identifiers, links, direct design review | pass: approved on 2026-11-02 | -| FR-1/2/4 | T-2: add failing span contract tests, then implement | AC-2: actual Boolean mode; exact seconds; correct omissions | `tests/test_model_ttft.py`, `tests/test_model_timing.py`, `tests/models/test_model_timing_adapters.py` | pass: implemented and locally verified | -| FR-3/5/6 | T-3: add reader-backed metric tests, then wire recording | AC-3: real Histogram name/unit/count/sum/dimensions; no duplicate or missing samples | `tests/test_portal_metrics.py`, timing and adapter tests | pass: implemented and locally verified | -| FR-1..6 | T-4: run affected/regression/static/docs checks and review | AC-4: compatible outputs, cleanup, exports, and bilingual docs; changed production-line coverage >=95% | Commands below and coverage against inspected revision | local checks pass; default regression fail: one reproduced baseline MIME mismatch | - -Test cases include text/reasoning/tool output, metadata-only chunks, repeat chunks, no usage, actual SDK mode differing from Runner mode, non-streaming, no output, retries/fallbacks, concurrent requests, cancellation/close before and after output, disabled tracing, configured/unconfigured MeterProvider, clock regression, genuine zero elapsed time, and a failed metric recorder. Assert Histogram type, unit `s`, count, sum, dimensions, and exported span fields using controlled clocks and provider boundaries. - -Planned commands, discovered from repository guidance and manifests: - -- `uv run --extra dev pytest tests/test_model_ttft.py tests/test_model_timing.py tests/models/test_model_timing_adapters.py tests/test_portal_metrics.py -q` -- `uv run --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json` -- `uv run --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke"` -- `uv run --extra dev pre-commit run --all-files` (and explicit changed-file checks for untracked additions) -- `npm --prefix docs run types:check`; `npm --prefix docs run build`; `git diff --check` - -Use the repository-local environment; document any environment blockers rather than modifying machine-global settings. Two regression workers follow repository guidance. Actual provider/cloud calls are not part of this local change's acceptance; report local adapter/reader evidence separately from the predecessor's live tests. Commit/push remain subject to separate authorization. - -## Review, risks, and delivery record - -Direct review is used because `review-spec` is unavailable. Inspected calculation ownership, callback duplication, retry boundaries, missing observations, metric dimensions/privacy, failure isolation, compatibility, and bilingual equivalence. Design clarification: standard fields live on observable SDK-request children, not aggregate spans. Main risks are duplicate metric samples, wrong time boundaries/units, stale aggregate fields, and accidental dependency on trace sampling or usage. The acceptance cases directly exercise those risks. - -User approval: explicitly granted on 2026-11-02 to create a new branch and implement immediately. Created `fix/apmplus-ttft` and synchronized the PR base with `git pull --ff-only origin feat/first-token-timestamps`. Implementation and component-spec/MDX reconciliation are complete. The lifecycle remains approved because the repository-wide AC-4 gate has the pre-existing failure recorded below. Runtime verification is recorded below. Source reads and specification comparison passed on 2026-11-02; repository branch checkout and `git pull --ff-only` succeeded. Implementation evidence, eight verification Gates, Change Impact, and Test Portfolio tables are recorded below and in the Chinese counterpart. - -## Implementation verification (2026-11-02) - -Scope: the working diff on `fix/apmplus-ttft` against `d9ef697b82fde94373737aae518148df348e60b0`, including the new test and design files. Production changes are limited to `timing.py` and `portal_metrics.py`. No unrelated user changes were present. Standard per-request fields and Histogram recording are implemented; final repository-wide verification has one reproduced baseline failure, recorded below. - -### Gate status - -| Gate | Status | Evidence or blocking reason | -| --- | --- | --- | -| Change Basis | PASS | Inspected the complete tracked/untracked diff against the PR head; new branch synchronized from that head. | -| Contract | PASS | FR-1..6 and CON-7..9 preserve legacy fields and define standard SDK-request fields, units, omissions, and metric ownership. | -| Impact | PASS | R-1..4 below cover spans, metrics, lifecycle, and maintained documentation. No dependency metadata, UI, payload, or deployment change. | -| Portfolio | PASS | Controlled clocks, real OTel reader/exporter, real model adapters with controlled provider boundaries, fault injection, and existing regression. | -| Baseline | PASS | Before implementation: 13 failing and 5 passing new tests; missing attributes and missing measurements caused the expected failures. | -| Execution | BLOCKED | Default regression: 7950 passed, 1 reproduced baseline MIME failure. Targeted/affected, static, and documentation checks passed; the repository-wide gate is not claimed to pass. | -| Evaluation | PASS | All changed production executable lines and changed decision arcs exercised; assertions distinguish wrong units, duplicate/missing samples, and wrong span scope. | -| Handoff | PASS | Scoped implementation and evidence delivered with the baseline regression limitation; no commit or push performed. | - -### Change Impact - -| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | -| --- | --- | --- | --- | --- | --- | -| FR-1/2/4 | CON-7 per-request standard fields | LiteLLM/Ark request spans and export | `ModelTiming`, actual adapter tests | Wrong mode/type/unit/start boundary; fabricated or stale aggregate TTFT | R-1 Medium | -| FR-3/6 | CON-8/9 per-request Histogram | Global metrics pipeline | `record_model_ttft`, real `InMemoryMetricReader` | Duplicate/lost samples, usage/trace dependency, wrong dimensions | R-2 Medium | -| FR-4/5 | CON-8 lifecycle and failures | Streaming, retries, cancellation, close | Timing/adapter tests and metric fault injection | Telemetry replaces model error/output; attempts mix or leak | R-3 High | -| FR-1..6 | Additive compatibility and documentation | Existing attributes, tracing pages, component specs | Existing regression, bilingual checks, docs build | Consumers receive conflicting definitions or lose old attributes | R-4 Medium | - -R-1/2/4 cross observable contracts and are Medium. R-3 can affect model completion on a commonly executed path (High impact and exposure), so it is High before validation. No known material consumer remains untraced. Residual risks are bounded by local controlled-provider verification; no new live cloud export is claimed. - -### Test Portfolio - -| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | -| --- | --- | --- | --- | --- | --- | --- | -| R-1 | SDK timing and span exporter | Clock control and contract tests | Text/reasoning/tool output, mode, empty/unsupported, negative/zero interval, retry scope | Exact float seconds, Boolean mode, child-only fields, correct absence | New TTFT tests plus existing LiteLLM/Ark adapter assertions | VERIFIED | -| R-2 | Real OTel metrics reader | Integration/state transition | No usage, no recording span, no exporter, repeated chunks/final callbacks, retry/concurrency | Histogram type/name/unit, exact count/sum, model isolation, exact safe dimensions | New TTFT tests; existing Portal provider/late-provider tests | VERIFIED | -| R-3 | SDK stream and recorder boundary | Fault injection and lifecycle tests | Error/cancel/close before/after first output; metrics failure | Original exceptions and cleanup preserved; observed samples retained; bounded diagnostic without error details | New TTFT tests plus existing timing and adapter lifecycle tests | VERIFIED | -| R-4 | Consumers and documentation | Regression, type/build, static review | Legacy attributes, exports, bilingual identifiers/links | Existing assertions pass; equivalent definitions and valid documentation build | Affected suite, pre-commit, docs checks | VERIFIED | - -### Executed evidence - -- Before the production change, `uv run --extra dev pytest tests/test_model_ttft.py -q`: **13 failed, 5 passed** (18 collected/executed). This is the expected RED result. -- After adding final-callback and no-exporter cases, `uv run --extra dev pytest tests/test_model_ttft.py -q`: **20 passed**, zero failures/skips. Negative-clock diagnostics are asserted. -- `uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-ttft-coverage-final.json`: **156 passed**, zero failures/skips (156 collected/executed). -- Production changed-line coverage is the intersection of added working-diff lines and coverage.py executable lines: **21/21 (100%)**, with **4/4** changed decision arcs covered. No coverage exclusions were added. Existing uncovered unrelated Portal metrics branches are outside this diff. -- `uv run --extra dev pre-commit run --all-files` plus explicit checks for new files: **pass**. Ruff initially formatted test changes; the subsequent check passed. Hooks without applicable files were skipped, not counted as execution. -- `npm --prefix docs run types:check` and `npm --prefix docs run build`: **pass**. Bilingual code identifiers/commands, relative links, new-test function lengths, and `git diff --check`: **pass**. -- The existing `tests/frontend/server/runtime_artifacts/test_writer.py::test_success_uses_trusted_scope_and_hashes_utf8_bytes` fails on the untouched `d9ef697b` snapshot too: expected `text/markdown`, observed `application/octet-stream`. The snapshot imported its own unmodified `writer.py`, `service.py`, and `timing.py`; its targeted run had **1 failed**. No assertion or unrelated production code was changed to hide this failure. -- `uv run --extra dev --extra sandbox --extra extensions --extra codex pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`: **fail: 7950 passed, 1 failed, 53 skipped, 4 xfailed**, plus **6 passing subtests**, in 412.98s. 8008 selected; 7955 executed including expected failures; 53 skipped. The sole failure is the unchanged baseline MIME test above. The two-worker setting follows repository guidance; skipped/expected-failure tests do not prove behavior. Live cloud/provider tests: **not_run**, outside the approved local scope. External-engine smoke tests: **not_applicable**, those engines are unchanged. - -Final review confirms the existing first-output latch owns metric emission, duration calculation uses the stored SDK start rather than parent span timing, and metrics recording runs outside `span.is_recording()` guards. Only instrument recording failures are caught and diagnosed; model exceptions are not intercepted. Existing timestamps remain intact. The known baseline MIME mismatch is a repository-wide gate limitation, not TTFT acceptance evidence. - -## Commit and push verification (2026-11-02) - -The user explicitly authorized commit and push. PR #1190 had already been squash-merged as `c1d4096d`; the repair branch was rebased onto the fetched `origin/main` at `65f30f2881b5d09aca94ea0c5e3450852866748f`, without replaying the original PR commits. The production repair diff is unchanged. - -After synchronization, `uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q` passed all **156 tests**. `uv run --no-sync --extra dev pre-commit run --all-files` passed. - -`uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q` finished with **8044 passed, 1 failed, 55 skipped, 4 xfailed**, plus **6 passing subtests**, in 407.20s. The sole failure remains the previously reproduced baseline Markdown MIME mismatch; its production/test files are unchanged between the original PR head and the synchronized base. The repository-wide gate remains `fail`; no assertion was weakened. This authorization covers pushing `fix/apmplus-ttft`, not opening another PR. - -## Approved standards-only revision (2026-11-02) - -The user explicitly removed consumer compatibility as a requirement and authorized immediate implementation. This supersedes FR-1/2/4/5/6 preservation of custom telemetry: remove all `veadk.request.*` / `veadk.model.*` timing attributes and the custom first-token event. Native HTTP/Runner spans own request start/end; SDK spans use the exact SDK start as native `start_time`. Only the standard stream and TTFT attributes/Histogram remain. Failed requests use Status `ERROR` with bounded `error.type`; timeout and cancellation are identified, while explicit generator closure is not an error. Do not capture exception text. - -Update request context propagation, final telemetry/exporter hooks, timing/adapter tests, and both documentation languages. Preserve generator yield isolation, stream cleanup, independent retries, no-usage metrics, and no-output omission. Verify negative assertions for custom attributes/events, exact native start, request/model parentage, status/error privacy, and existing response behavior. Native request spans are the replacement for request-start attributes; this is not removal of request timing. The user approved this contract change; no old aliases or compatibility bridge are required. Historical test results above describe the preceding revision only. - -### Standards-only implementation and evidence (2026-11-02) - -Comparison base: `95fd4c63`; the working diff replaces custom telemetry without compatibility aliases, as explicitly requested. Production changes are limited to `timing.py`, removal of final-response annotation from `telemetry.py`, and removal of exporter annotation from `inmemory_exporter.py`. Native request spans retain request-boundary timing and preserve context across producer advancement/closure without leaking it through yields. Existing app factories and Runner use their existing installation points. No credentials, dependency metadata, deployment, commit, or push changes are part of this revision. - -| Gate | Status | Evidence or limitation | -| --- | --- | --- | -| Change Basis | PASS | Complete working diff against `95fd4c63`; no unrelated changes. | -| Contract | PASS | User-approved removal; updated CON-1..9 use native intervals and standard attributes/status. | -| Impact | PASS | S-1..4 include request/model spans, callbacks/exporters, lifecycle, and docs. | -| Portfolio | PASS | Native span and Histogram assertions, provider-boundary tests, HTTP/Runner tests, failure injection, regression. | -| Baseline | PASS | Four new regression cases failed before implementation, then passed. | -| Execution | BLOCKED | Scoped checks pass; default regression retains the previously reproduced unrelated MIME failure. | -| Evaluation | PASS | 56/56 changed executable production lines; no missing changed decision arcs. | -| Handoff | PASS | Local implementation and limitations documented; no compatibility alias or unverified cloud claim. | - -#### Change Impact - -| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | -| --- | --- | --- | --- | --- | --- | -| Standard-only | CON-1/2/6/7 | Request/model spans and exports | `timing.py`, annotation removals | Custom fields persist; native interval or parentage is wrong | S-1 Medium | -| Standard-only | CON-3/4/8/9 | TTFT and Histogram | Existing recorder plus timing/adapter tests | Missing/duplicate samples or changed units | S-2 Medium | -| Standard-only | CON-5 | Request context, retries, failure/close | Middleware, Runner wrapper, real SDK adapters | Context leak, wrong status, lost original error or cleanup | S-3 High | -| Standard-only | CON-1..9 | Bilingual specs and user docs | Updated tracing MDX and component pair | Old custom-field contract is presented as current | S-4 Medium | - -#### Test Portfolio - -| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | -| --- | --- | --- | --- | --- | --- | --- | -| S-1 | OTel exporter and ASGI/Runner | Contract/integration | Exact model start, request before body read, parentage, unsupported mode | Native times/parents; zero custom attributes/events | 84 focused and 294 affected tests | VERIFIED | -| S-2 | Real OTel reader and adapters | Controlled clock/state transitions | All output kinds, no output/usage, retries, no trace sampling, metric failure | Exact seconds/count/sum and omissions | Focused/affected tests retain prior Histogram assertions | VERIFIED | -| S-3 | Async producer and request spans | Failure injection/concurrency | Timeout, cancellation, explicit close, close error, HTTP 5xx, inherited scope | Original errors/outputs; correct ERROR/error.type; no exception text; context restored | Focused/affected tests and default regression | VERIFIED | -| S-4 | Bilingual documentation | Identifier/link review and site build | Current standard-only contract and historical predecessor labels | Equivalent identifiers and successful type/build checks | Documentation/static checks | VERIFIED | - -Executed checks: - -- `uv run --no-sync --extra dev pytest tests/test_model_ttft.py -q -k 'only_standard or model_failure'`: before implementation **4 failed, 20 deselected**; after implementation **4 passed, 20 deselected**. -- `uv run --no-sync --extra dev pytest tests/test_model_timing.py tests/test_model_ttft.py tests/models/test_model_timing_adapters.py -q`: **84 passed**, zero failures/skips, including the strengthened HTTP-before-body assertion. -- `MODEL_AGENT_API_KEY=offline-test-placeholder uv run --no-sync --extra dev pytest tests/models tests/test_model_timing.py tests/test_model_ttft.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py tests/test_runner.py tests/runner/test_runner_contract.py tests/integrations/agentkit/test_app.py tests/cloud/test_harness_app_contract.py tests/cloud/test_harness_app_http.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-standard-coverage.json`: **294 passed**, zero failures/skips. The value is synthetic and provider calls are controlled. Changed executable production-line coverage: **56/56 (100%)**; no coverage exclusions added. -- `uv run --no-sync --extra dev pytest -n 2 -m 'not codex_smoke and not piagent_smoke' -q`: **8053 passed, 1 failed, 55 skipped, 4 xfailed**, plus **6 passing subtests**, 422.58s. The sole failure is the previously reproduced `test_success_uses_trusted_scope_and_hashes_utf8_bytes` baseline mismatch. Production/test files for that failure remain unchanged. No failures were hidden or assertions loosened. -- `uv run --no-sync --extra dev pre-commit run --all-files`: **pass** after formatting; includes Ruff and secret checks. `npm --prefix docs run types:check`, `npm --prefix docs run build`, paired identifiers, relative links, function-length and diff-whitespace checks: **pass**. -- Live cloud/provider validation: **not_run**, outside the authorized local scope. The original feature's cloud evidence does not validate this new span topology. Residual compatibility impact is deliberate removal of custom fields and added native request parent spans. - -Publication authorization (2026-11-02): the user explicitly requested committing and pushing the standards-only revision. Fetch confirmed unchanged remote base `65f30f28` and branch head `95fd4c63`; rebase onto `origin/main` was up to date. After synchronization, all 294 affected tests and all applicable pre-commit hooks passed. The previously recorded full-regression baseline limitation remains unchanged. diff --git a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md b/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md deleted file mode 100644 index daa7f6fa4..000000000 --- a/prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md +++ /dev/null @@ -1,178 +0,0 @@ -# APMPlus 流式与 TTFT 遥测 - -[English](2026-11-02-apmplus-ttft.md) - -变更 ID：`apmplus-ttft`；创建/修订日期：2026-11-02；状态：approved。 -组件：[model-timing](../../../specs/model-timing/README.zh.md)。 -前序设计：[first-token-timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md)。 -检查版本：`feat/first-token-timestamps` 的 `d9ef697b82fde94373737aae518148df348e60b0`（PR #1190）。 - -当前契约：本文末尾的仅标准字段修订取代前文保留自定义字段的决定。前文保留历史证据。 - -## 背景与证据 - -[PR 评论](https://github.com/volcengine/veadk-python/pull/1190#issuecomment-6514480806) 要求补齐标准流式标记、以秒为单位的 TTFT Span 属性及真正的 TTFT Histogram 记录。2026-11-02 读取的指定 APMPlus Trace 规范（revision 261）和 Metrics 规范（revision 17）与这些要求一致。 - -`ModelTiming` 当前记录自定义时间戳和实际 SDK 流式模式。`PortalMetricRecorder` 已创建名称正确、单位为 `s` 的 TTFT Histogram，但记录逻辑仍为 TODO。`record_call_llm()` 在响应回调中执行，现有观测还受 usage 检查限制，无法保证每次 SDK 请求恰好记录一次 TTFT。原设计明确排除了 Histogram；本后续设计提出这一有限扩展。 - -## 目标与非目标 - -为每次可观测 SDK 请求的 Span 添加 `gen_ai.request.stream` 和 `gen_ai.chat_completions.streaming_time_to_first_token`，并在现有 Histogram 中记录同一个 TTFT 值一次。保留自定义时间戳和模型行为。 - -不包含 TPOT、无关指标改名、token 计数变更、客户端渲染耗时、供应商内部不可观测重试、新 exporter/配置/依赖、前端变更和云部署。历史云端证据不证明本次新变更。 - -## 要求与场景 - -- FR-1：已埋点的 `model_request` Span 使用实际 SDK 请求的布尔值设置 `gen_ai.request.stream`，不依赖 Runner 流式配置。保留 `veadk.model.streaming` 和旧属性。 -- FR-2：首个非空文本、推理或工具调用 delta 产生浮点秒数 `(first_token_time_unix_ns - model_start_time_unix_ns) / 1e9`，写入 `gen_ai.chat_completions.streaming_time_to_first_token`。复用自定义属性所用的同一请求开始时间戳。请求入口时间和外层 Span 开始时间不参与计算。 -- FR-3：首次观测时，在现有同名、单位为 `s` 的 Histogram 中记录同一个值一次，即使没有 usage 或可记录的 Trace Span。后续 chunk 和最终响应回调不能重复记录。每次可观测重试/降级 SDK 请求独立持有首次观测状态和样本。 -- FR-4：非流式、无输出和不支持埋点的请求没有 TTFT 属性/样本。实际 SDK 模式未知时，不从 Runner 配置推造。时钟回退时保留原始时间戳，省略负耗时并产生有限诊断；真正测得的零耗时有效，不是缺失值占位。 -- FR-5：失败、取消或关闭前已观测的样本应保留。保持原始输出、异常传播和资源清理。指标记录失败时产生有限诊断，不记录请求内容，也不替换模型结果/异常。 -- FR-6：新指标维度使用规范中的点分名称，且仅填写已知稳定值。包含实际请求模型；未知供应商/响应模型省略。不得加入提示词/输出正文、用户/会话/Trace ID 或响应 ID。继续使用现有全局 MeterProvider，不安装导出链路。 - -当元数据后出现生成 delta 时，只由生成 delta 记录 TTFT。当两个请求共用一个外层模型 Span 时，各 SDK 子 Span 独立保存属性和观测。关闭 tracing 但已配置指标 reader 时，已观测流式请求仍记录 Histogram。没有生成 delta 时，完成响应不能伪造样本。 - -## 设计、方案取舍与契约影响 - -由 `ModelTiming.observe()` 唯一负责观测。在本地保存请求开始时间和模型，使计算和指标记录不依赖读取 Span 属性。为 `PortalMetricRecorder` 添加职责单一、带类型注解的记录方法；仅移除被替代的 TTFT TODO。复用现有 instrument、单位和桶边界。 - -每次 SDK 请求的 `model_request` 子 Span 是标准 LLM Span 的权威位置，并标记 `gen_ai.span.kind=llm`，避免将聚合/重试所属 Span 的生命周期当成单次 SDK 请求。继续兼容现有向 `call_llm` 镜像自定义时间戳的行为；不向聚合 Span 复制标准 TTFT，避免后续无输出尝试遗留旧观测。文档明确该 Span 边界。现有 `gen_ai.is_streaming` 保留兼容。 - -替代方案：在 `record_call_llm()` 记录。不采用，因为回调次数、usage 缺失和重试需要额外共享状态，可能重复或遗漏样本。替代方案：重命名/删除自定义时间戳。不采用，因为时间戳仍有价值，删除既破坏消费者兼容，也不能满足耗时要求。 - -实现前更新 model-timing 双语契约：扩展 CON-2/4/6，新增覆盖 FR-3/5/6 的逐请求 Histogram 契约。在原设计添加后续设计说明，保留历史验收事实。同步更新两份 tracing MDX。无需修改持久化、权限、HTTP/事件载荷、公开模型调用签名或数据库。回滚删除新增标准遥测即可，原自定义时间戳仍可使用。 - -## 任务与验收 - -| 要求 | 任务 | 验收 | 验证 | 结果 | -| --- | --- | --- | --- | --- | -| FR-1..6 | T-1：同步双语设计/契约并评审 | AC-1：范围一致且设计获批 | 双语标识符、链接、直接设计评审 | pass：2026-11-02 获批 | -| FR-1/2/4 | T-2：先添加失败的 Span 契约测试，再实现 | AC-2：实际布尔模式；精确秒数；正确省略 | `tests/test_model_ttft.py`、`tests/test_model_timing.py`、`tests/models/test_model_timing_adapters.py` | pass：已实现并完成本地验证 | -| FR-3/5/6 | T-3：先添加 reader 指标测试，再接入记录 | AC-3：真实 Histogram 名称/单位/count/sum/维度；无重复或遗漏 | `tests/test_portal_metrics.py`、timing 与适配器测试 | pass：已实现并完成本地验证 | -| FR-1..6 | T-4：受影响/回归/静态/文档检查及评审 | AC-4：输出、清理、导出兼容；双语文档一致；变更生产行覆盖率 >=95% | 下列命令及相对检查版本的覆盖率 | 本地检查通过；默认回归 fail：一项已复现的基线 MIME 不匹配 | - -测试包含文本/推理/工具输出、纯元数据 chunk、重复 chunk、无 usage、实际 SDK 模式与 Runner 模式不同、非流式、无输出、重试/降级、并发请求、输出前后取消/关闭、禁用 tracing、已配置/未配置 MeterProvider、时钟回退、真正零耗时、指标记录失败。使用受控时钟与供应商边界，断言 Histogram 类型、单位 `s`、count、sum、维度及导出的 Span 属性。 - -根据仓库指南和清单确认的计划命令： - -- `uv run --extra dev pytest tests/test_model_ttft.py tests/test_model_timing.py tests/models/test_model_timing_adapters.py tests/test_portal_metrics.py -q` -- `uv run --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json` -- `uv run --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke"` -- `uv run --extra dev pre-commit run --all-files`（另对未跟踪新增文件显式执行变更文件检查） -- `npm --prefix docs run types:check`；`npm --prefix docs run build`；`git diff --check` - -使用仓库本地环境；记录环境阻碍，不修改机器全局配置。两个回归 worker 遵循仓库要求。真实供应商/云调用不属于本次本地变更验收；分别报告本地适配器/reader 证据和前序设计的真实测试。提交/推送仍需单独授权。 - -## 评审、风险与交付记录 - -`review-spec` 不可用，因此执行直接评审。已检查计算归属、回调重复、重试边界、缺失观测、指标维度/隐私、故障隔离、兼容性及双语等价性。设计澄清：标准字段位于可观测 SDK 请求子 Span，不放在聚合 Span。主要风险是重复样本、错误时间边界/单位、聚合字段残留，以及意外依赖 Trace 采样或 usage；验收场景直接覆盖这些风险。 - -用户于 2026-11-02 明确批准“创建新分支，立即修改”。已创建 `fix/apmplus-ttft`，并通过 `git pull --ff-only origin feat/first-token-timestamps` 同步 PR 基线。实现、组件契约及 MDX 同步已完成。因仓库级 AC-4 检查存在下方记录的既有失败，生命周期保留 approved。运行验证记录见下方。2026-11-02 已完成源码读取和规范核对；分支切换及 `git pull --ff-only` 成功。本设计下方及英文版本已记录实现证据、八个验证 Gate、Change Impact 和 Test Portfolio 表。 - -## 实现验证（2026-11-02） - -范围：`fix/apmplus-ttft` 相对 `d9ef697b82fde94373737aae518148df348e60b0` 的工作区差异，包含新增测试和设计文件。生产代码仅修改 `timing.py` 和 `portal_metrics.py`。没有无关用户改动。逐请求标准属性和 Histogram 记录已实现；最终仓库级验证存在一项已复现的基线失败，详见下方。 - -### Gate 状态 - -| Gate | 状态 | 证据或阻碍原因 | -| --- | --- | --- | -| Change Basis | PASS | 已检查相对 PR head 的全部已跟踪/未跟踪差异；新分支已从该 head 同步。 | -| Contract | PASS | FR-1..6 与 CON-7..9 保留旧字段，并定义标准 SDK 请求字段、单位、省略规则及指标归属。 | -| Impact | PASS | 下方 R-1..4 覆盖 Span、指标、生命周期和维护文档。无依赖清单、UI、载荷或部署变更。 | -| Portfolio | PASS | 受控时钟、真实 OTel reader/exporter、受控供应商边界下的真实模型适配器、故障注入及既有回归。 | -| Baseline | PASS | 实现前新增测试 13 项失败、5 项通过；缺少属性和指标观测导致预期失败。 | -| Execution | BLOCKED | 默认回归 7950 项通过、1 项已复现基线 MIME 失败。定向/受影响、静态及文档检查通过；不声明仓库级检查通过。 | -| Evaluation | PASS | 覆盖全部变更生产可执行行和变更分支；断言能识别错误单位、重复/缺失样本和错误 Span 范围。 | -| Handoff | PASS | 交付范围内实现及证据，并明确基线回归限制；未提交或推送。 | - -### Change Impact - -| Change ID | 变更契约 | 受影响面 | 仓库证据 | 失败模式 | 风险 | -| --- | --- | --- | --- | --- | --- | -| FR-1/2/4 | CON-7 逐请求标准属性 | LiteLLM/Ark 请求 Span 及导出 | `ModelTiming`、真实适配器测试 | 模式/类型/单位/起点错误；伪造或聚合 Span 残留 TTFT | R-1 Medium | -| FR-3/6 | CON-8/9 逐请求 Histogram | 全局指标链路 | `record_model_ttft`、真实 `InMemoryMetricReader` | 重复/遗漏样本、依赖 usage/trace、维度错误 | R-2 Medium | -| FR-4/5 | CON-8 生命周期和失败 | 流式、重试、取消、关闭 | 计时/适配器测试及指标故障注入 | 遥测替换模型异常/输出；请求混淆或泄漏 | R-3 High | -| FR-1..6 | 增量兼容及文档 | 旧属性、tracing 页面、组件契约 | 既有回归、双语检查、文档构建 | 消费者获得冲突定义或丢失旧属性 | R-4 Medium | - -R-1/2/4 跨可观测契约，定为 Medium。R-3 可能影响常用路径的模型完成行为（影响和暴露均为 High），验证前定为 High。没有已知但未追踪的重要消费者。残余风险以本地受控供应商验证为界，不声明新增云端真实导出验证。 - -### Test Portfolio - -| Risk ID | 边界 | 方法 | 场景 | 判定依据 | 证据 | 状态 | -| --- | --- | --- | --- | --- | --- | --- | -| R-1 | SDK 计时及 Span exporter | 时钟控制、契约测试 | 文本/推理/工具输出、模式、空/不支持、负/零间隔、重试范围 | 精确浮点秒数、布尔模式、仅子 Span 标准字段、正确缺失 | 新增 TTFT 测试及既有 LiteLLM/Ark 适配器断言 | VERIFIED | -| R-2 | 真实 OTel metrics reader | 集成/状态转换 | 无 usage、无录制 Span、无 exporter、重复 chunk/最终回调、重试/并发 | Histogram 类型/名称/单位、精确 count/sum、模型隔离、安全维度全集 | 新增 TTFT 测试；既有 Portal provider/延迟 provider 测试 | VERIFIED | -| R-3 | SDK 流及 recorder 边界 | 故障注入、生命周期测试 | 首输出前后异常/取消/关闭；指标失败 | 保留原异常与清理；已观测样本保留；有限诊断不含错误详情 | 新增 TTFT 测试及既有计时、适配器生命周期测试 | VERIFIED | -| R-4 | 消费者与文档 | 回归、类型/构建、静态评审 | 旧属性、导出、双语标识符/链接 | 既有断言通过；定义等价且文档构建有效 | 受影响套件、pre-commit、文档检查 | VERIFIED | - -### 已执行证据 - -- 生产修改前，`uv run --extra dev pytest tests/test_model_ttft.py -q`：**13 failed、5 passed**（收集/执行 18 项）。这是预期 RED 结果。 -- 增加最终回调及无 exporter 场景后，`uv run --extra dev pytest tests/test_model_ttft.py -q`：**20 passed**，零失败/跳过。已断言负时钟诊断。 -- `uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-ttft-coverage-final.json`：**156 passed**，零失败/跳过（收集/执行 156 项）。 -- 生产变更行覆盖率取工作区新增行与 coverage.py 可执行行的交集：**21/21（100%）**，变更分支 **4/4** 已覆盖。没有新增覆盖率排除。Portal metrics 既有无关分支缺口不在本次差异中。 -- `uv run --extra dev pre-commit run --all-files` 及新增文件显式检查：**pass**。Ruff 首次格式化测试改动后，后续检查通过。不适用的 hook 标为跳过，不算已执行。 -- `npm --prefix docs run types:check` 与 `npm --prefix docs run build`：**pass**。双语代码标识符/命令、相对链接、新增测试函数长度以及 `git diff --check`：**pass**。 -- 既有 `tests/frontend/server/runtime_artifacts/test_writer.py::test_success_uses_trusted_scope_and_hashes_utf8_bytes` 在未修改的 `d9ef697b` 快照同样失败：预期 `text/markdown`，实际 `application/octet-stream`。快照加载了自身未修改的 `writer.py`、`service.py`、`timing.py`；定向运行结果为 **1 failed**。没有修改断言或无关生产代码来隐藏该失败。 -- `uv run --extra dev --extra sandbox --extra extensions --extra codex pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`：**fail：7950 passed、1 failed、53 skipped、4 xfailed**，另有 **6 项子测试通过**，耗时 412.98s。选中 8008 项；执行 7955 项（含预期失败）；跳过 53 项。唯一失败为上述未修改的基线 MIME 测试。两个 worker 遵循仓库要求；跳过/预期失败不证明相关行为。真实云/供应商测试：**not_run**，不在批准的本地范围内。外部执行引擎 smoke：**not_applicable**，这些引擎未变更。 - -最终评审确认：指标由既有首次输出状态唯一触发；耗时从保存的 SDK 起点计算，不使用父 Span 计时；指标记录不受 `span.is_recording()` 限制。仅捕获并诊断 instrument 记录异常，不拦截模型异常。保留现有时间戳。已知基线 MIME 不匹配是仓库级检查限制，不属于 TTFT 验收证据。 - -## 提交与推送验证（2026-11-02） - -用户已明确授权提交和推送。PR #1190 已通过 squash 合并为 `c1d4096d`；修复分支已 rebase 到 fetch 后的 `origin/main`：`65f30f2881b5d09aca94ea0c5e3450852866748f`，没有重复应用原 PR 提交。生产修复差异保持不变。 - -同步后，`uv run --no-sync --extra dev pytest tests/models tests/test_model_ttft.py tests/test_model_timing.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py -q` 的 **156 项测试全部通过**。`uv run --no-sync --extra dev pre-commit run --all-files` 通过。 - -`uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q` 结果为 **8044 passed、1 failed、55 skipped、4 xfailed**，另有 **6 项子测试通过**，耗时 407.20s。唯一失败仍为此前已复现的基线 Markdown MIME 不匹配；其生产/测试文件在原 PR head 与同步后基线之间没有变化。仓库级检查仍为 `fail`，没有放宽断言。本次授权包含推送 `fix/apmplus-ttft`，不包含新建另一个 PR。 - -## 已批准的仅标准字段修订（2026-11-02） - -用户明确不考虑已有消费者，并授权立即实施。本修订替代 FR-1/2/4/5/6 中保留自定义遥测的决定：移除全部 `veadk.request.*` / `veadk.model.*` 计时属性及自定义首 Token 事件。原生 HTTP/Runner Span 负责请求起止时间；SDK Span 将精确 SDK 开始时间设为原生 `start_time`。只保留标准流式与 TTFT 属性/Histogram。失败请求使用 Status `ERROR` 和有限类别的 `error.type`；区分超时、取消，主动关闭生成器不算错误。不采集异常正文。 - -同步请求上下文传递、最终遥测/导出器钩子、计时/适配器测试及双语文档。保留生成器 yield 隔离、流清理、独立重试、无 usage 指标及无输出省略行为。验证无自定义属性/事件、精确原生起点、请求/模型父子关系、错误状态/隐私及原响应行为。原生请求 Span 替代请求开始属性，不删除请求计时能力。用户已批准该契约变化，无需旧别名或兼容桥接。上方历史测试结果仅适用于前一修订。 - -### 仅标准字段实现与证据（2026-11-02） - -比较基线：`95fd4c63`；工作区差异按用户明确要求替代自定义遥测，不保留兼容别名。生产修改仅包含 `timing.py`、移除 `telemetry.py` 中最终响应注解、移除 `inmemory_exporter.py` 中导出器注解。原生请求 Span 保留请求边界计时，并在生产者推进/关闭时绑定上下文，不跨 yield 泄漏。应用工厂和 Runner 复用既有安装点。本修订不包含凭证、依赖清单、部署、提交或推送变更。 - -| Gate | 状态 | 证据或限制 | -| --- | --- | --- | -| Change Basis | PASS | 已检查相对 `95fd4c63` 的全部工作区差异；无无关修改。 | -| Contract | PASS | 用户批准删除；更新的 CON-1..9 使用原生区间及标准属性/状态。 | -| Impact | PASS | S-1..4 覆盖请求/模型 Span、回调/导出器、生命周期和文档。 | -| Portfolio | PASS | 原生 Span 与 Histogram 断言、供应商边界测试、HTTP/Runner 测试、故障注入及回归。 | -| Baseline | PASS | 四个新增回归场景在实现前失败，实现后通过。 | -| Execution | BLOCKED | 范围内检查通过；默认回归保留此前已复现的无关 MIME 失败。 | -| Evaluation | PASS | 覆盖 56/56 个变更生产可执行行；无缺失变更分支。 | -| Handoff | PASS | 本地实现与限制已记录；无兼容别名或未经验证的云端声明。 | - -#### Change Impact - -| Change ID | 变更契约 | 受影响面 | 仓库证据 | 失败模式 | 风险 | -| --- | --- | --- | --- | --- | --- | -| Standard-only | CON-1/2/6/7 | 请求/模型 Span 及导出 | `timing.py`、注解移除 | 自定义字段残留；原生区间或父子关系错误 | S-1 Medium | -| Standard-only | CON-3/4/8/9 | TTFT 和 Histogram | 既有 recorder 与计时/适配器测试 | 样本遗漏/重复或单位改变 | S-2 Medium | -| Standard-only | CON-5 | 请求上下文、重试、失败/关闭 | 中间件、Runner 包装、真实 SDK 适配器 | 上下文泄漏、状态错误、原异常或清理丢失 | S-3 High | -| Standard-only | CON-1..9 | 双语契约与用户文档 | 更新的 tracing MDX 和组件文档对 | 把旧自定义字段契约表述为现状 | S-4 Medium | - -#### Test Portfolio - -| Risk ID | 边界 | 方法 | 场景 | 判定依据 | 证据 | 状态 | -| --- | --- | --- | --- | --- | --- | --- | -| S-1 | OTel exporter 和 ASGI/Runner | 契约/集成 | 精确模型起点、读取 body 前请求范围、父子关系、未知模式 | 原生时间/父子关系；零自定义属性/事件 | 84 项定向与 294 项受影响测试 | VERIFIED | -| S-2 | 真实 OTel reader 和适配器 | 受控时钟/状态转换 | 所有输出类型、无输出/usage、重试、不采样 Trace、指标失败 | 精确秒数/count/sum 及省略规则 | 定向/受影响测试保留先前 Histogram 断言 | VERIFIED | -| S-3 | 异步生产者和请求 Span | 故障注入/并发 | 超时、取消、主动关闭、关闭异常、HTTP 5xx、继承范围 | 原始异常/输出；正确 ERROR/error.type；无异常正文；上下文恢复 | 定向/受影响测试及默认回归 | VERIFIED | -| S-4 | 双语文档 | 标识符/链接评审及站点构建 | 现行仅标准字段契约和前序历史标记 | 标识符等价，类型/构建检查成功 | 文档/静态检查 | VERIFIED | - -已执行检查： - -- `uv run --no-sync --extra dev pytest tests/test_model_ttft.py -q -k 'only_standard or model_failure'`：实现前 **4 failed、20 deselected**；实现后 **4 passed、20 deselected**。 -- `uv run --no-sync --extra dev pytest tests/test_model_timing.py tests/test_model_ttft.py tests/models/test_model_timing_adapters.py -q`：**84 passed**，零失败/跳过，包含加强的读取 HTTP body 前断言。 -- `MODEL_AGENT_API_KEY=offline-test-placeholder uv run --no-sync --extra dev pytest tests/models tests/test_model_timing.py tests/test_model_ttft.py tests/test_portal_metrics.py tests/test_tracing.py tests/test_tracing_content.py tests/test_inmemory_exporter.py tests/test_runner.py tests/runner/test_runner_contract.py tests/integrations/agentkit/test_app.py tests/cloud/test_harness_app_contract.py tests/cloud/test_harness_app_http.py -q --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-standard-coverage.json`：**294 passed**，零失败/跳过。该值为合成占位值，供应商调用受控。生产变更可执行行覆盖率：**56/56（100%）**；没有添加覆盖率排除。 -- `uv run --no-sync --extra dev pytest -n 2 -m 'not codex_smoke and not piagent_smoke' -q`：**8053 passed、1 failed、55 skipped、4 xfailed**，另有 **6 项子测试通过**，耗时 422.58s。唯一失败为此前已复现的 `test_success_uses_trusted_scope_and_hashes_utf8_bytes` 基线不匹配。该失败涉及的生产/测试文件未修改。没有隐藏失败或放宽断言。 -- `uv run --no-sync --extra dev pre-commit run --all-files`：格式化后 **pass**，包含 Ruff 与密钥扫描。`npm --prefix docs run types:check`、`npm --prefix docs run build`、双语标识符、相对链接、函数长度及 diff 空白检查：**pass**。 -- 真实云/供应商验证：**not_run**，超出本次授权的本地范围。原功能的云端证据不能证明新的 Span 拓扑。剩余兼容性影响是有意删除自定义字段，以及增加原生请求父 Span。 - -发布授权（2026-11-02）：用户明确要求提交并推送仅标准字段修订。Fetch 确认远端基线 `65f30f28` 和分支 head `95fd4c63` 未变化；rebase 到 `origin/main` 已是最新。同步后 294 项受影响测试及所有适用 pre-commit 检查通过。此前记录的全量回归基线限制未变化。 diff --git a/prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.md b/prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.md deleted file mode 100644 index 3aa821005..000000000 --- a/prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.md +++ /dev/null @@ -1,85 +0,0 @@ -# Stabilize PR #1190 CI tests - -[中文版](2026-10-28-stabilize-concurrent-tests.zh.md) - -Change ID: `pr1190-ci`; created/revised: 2026-10-28; status: approved. -Comparison base: feature commit `7527a832`; upstream `23014771`. -Related design: [first-token timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.md). - -## Evidence and scope - -Unit Tests run `40649026439`, Python 3.10 job `122684493009`, reports 1 failed, 7,937 passed, 46 skipped, 4 xfailed. The failing startup-prefetch test assumes `tool-codex` is inspected before `tool-codex-snapshot`. Production intentionally uses `asyncio.gather` and `asyncio.to_thread`, so either order is valid. Python 3.12 was cancelled by matrix fail-fast. - -The earlier local full regression also exposed a baseline Sidecar test that inherits developer model upstream settings, activating a stable relay while asserting a fixed fake discovery URL. `run_with_harness_sidecar` already supports an explicit `env` mapping. - -Goal: deterministic tests for the actual contracts. Non-goals: runtime changes, serializing production concurrency, weakening assertions, retries/skips, CI configuration changes, frontend changes, dependencies, additional cloud deployments. - -## Requirements and design - -- FR-1: Both configured Sandbox tools are inspected exactly once, regardless of scheduling order, and their final cached states appear in the system-info response. -- FR-2: Explicitly exercise both inspection orders using a bounded thread Event; compare exact call multiplicities without requiring a production order. -- FR-3: Poll the returned state within a bounded deadline instead of treating entry into the inspection stub as cache publication. -- FR-4: The fake Sidecar child receives exact discovery endpoints in an explicitly isolated environment, even if the parent has model/MCP upstream variables. - -Change only `tests/cli/test_studio_rbac.py` and `tests/extensions/harness/sidecar_runtime/test_sidecar.py`, plus bilingual design/evidence. Preserve every existing response and endpoint assertion. No component spec changes: all public/runtime/permission/data/observability contracts are unchanged. Rollback reverts this test-only commit. - -## Tasks and acceptance - -| Requirement | Task | Acceptance | Evidence | -| --- | --- | --- | --- | -| FR-1/2 | T-1: force both thread orders, then correct the ordered assertion | AC-1: reverse scheduling fails before the correction; both schedules pass after it | Targeted pytest, original CI failure | -| FR-3 | T-2: wait for both published response states | AC-2: exact existing model-state assertions pass | Same parameterized TestClient test | -| FR-4 | T-3: give the Sidecar fake an explicit empty environment | AC-3: exact endpoint assertions pass with parent upstream variables present | Fake runtime and real child subprocess test | -| All | T-4: required gates, publish, inspect CI | AC-4: affected suites, full default regression, pre-commit and remote CI green; production diff coverage stays >=95% | Repository commands below | - -Commands: `uv run --no-sync --extra dev pytest tests/cli/test_studio_rbac.py tests/extensions/harness/sidecar_runtime/test_sidecar.py -n 2 -q`; `uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`; `uv run --no-sync --extra dev pre-commit run --all-files`. Reuse feature coverage and real cloud evidence because production code is unchanged; verify its source hashes. - -## Review and authorization - -2026-10-28: User authorized repairing CI on PR #1190 after completing the Feishu design document. Earlier commit/push authorization persists for this branch. Direct design review (`review-spec` unavailable) confirms test-only scope, exact multiplicity/state/URL oracles, bounded synchronization, unchanged production concurrency and isolation from real credentials. English/Chinese identifiers and acceptance criteria agree. No design blocker remains. - -Risks: thread entry does not imply cache publication; response-state polling addresses this. Local Python 3.12 differs from CI's 3.10/3.12 matrix; remote results are required for delivery. Cloud revalidation is not applicable to a test-only repair; preserve the previously executed 6/6 real cloud conclusion. - -## Verification record - -2026-10-28, `7527a832` plus this test-only diff, Python 3.12.13: - -- Original ordered assertion with controlled schedules: 1 passed, 1 failed; reverse order reproduces the exact CI failure. -- Parent-upstream injection before explicit `env={}`: 1 failed with fixed discovery URL versus relay URL. Original isolated single-case execution passed, confirming the environment-dependent mechanism. -- After corrections: 3 targeted cases passed (two schedules and child environment). -- Combined affected run: 185 passed, 4 failed. All 174 Studio cases passed; four unrelated loopback requests used the local machine proxy and received HTTP 403. Rerunning the complete 15-case Sidecar file with command-scoped `NO_PROXY=localhost,127.0.0.1,::1 no_proxy=localhost,127.0.0.1,::1` passed. Thus all 189 affected cases passed in the appropriate local environment; no network test assertion or proxy policy was changed. -- All-files pre-commit passed after formatting; bilingual identifiers, literal commands, relative links and whitespace checks passed. -- All nine production file hashes match the original real-cloud build. Production changed-line coverage remains 100% (208/208); real cloud E2E remains 6/6 pass. This repair adds no production executable lines. -- Full default regression with the same command-scoped loopback bypass and `--junitxml` outside Git: **7,942 passed, 0 failed, 42 skipped, 4 xfailed; 6 subtests passed; 472.66s**. The 7,988 selected cases comprise 7,946 executed cases (including four expected failures) and 42 skipped cases. Final remote 3.10/3.12 results are tracked on the published PR. The user subsequently limited additional test execution to failed cases; no additional broad test run is planned. - - -### Gate status - -| Gate | Status | Evidence | -| --- | --- | --- | -| Change Basis | PASS | Complete test/design diff against `7527a832`; upstream `23014771` unchanged; no unrelated work. | -| Contract | PASS | Exact tool multiplicities, published states and child discovery endpoints; production contracts unchanged. | -| Impact | PASS | R-CI-1/2 cover the affected test oracles and environment boundary. | -| Portfolio | PASS | Two controlled thread schedules, TestClient state publication, real fake-runtime/child processes. | -| Baseline | PASS | Reverse-order assertion and parent-upstream injection both observed RED before correction. | -| Execution | PASS | Targeted 3 cases; all 189 affected cases; full default regression; all-files pre-commit. | -| Evaluation | PASS | Original state/URL assertions retained; duplicate calls still fail; source hashes and 208/208 production coverage unchanged. | -| Handoff | PASS | Bilingual design/evidence reconciled; final published CI evidence is linked from PR #1190. | - -### Change Impact - -| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | -| --- | --- | --- | --- | --- | --- | -| FR-1/2/3 | Test scheduling and completion oracle | Startup-prefetch test and system-info cache response | `asyncio.gather`, `asyncio.to_thread`, `test_system_info_prefetches_codex_model_env_state_on_startup` | False CI failure on valid scheduling, or checking states before publication | R-CI-1 Medium | -| FR-4 | Test subprocess environment | Fake Sidecar and child execution | `run_with_harness_sidecar(env=...)`, child-environment test | Parent upstream variables change expected discovery endpoints | R-CI-2 Medium | - -Both risks cross owned integration boundaries; inherent impact/exposure/hazard/detection are Medium/Medium/Medium/Low. No material unknown remains in the changed test scope. Residual uncertainty is bounded to untested host loads; no load/performance claim is made. - -### Test Portfolio - -| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | -| --- | --- | --- | --- | --- | --- | --- | -| R-CI-1 | Threaded provider stub and real ASGI response | Controlled schedules and state transitions | Codex first; snapshot first; exact per-kind final state | Both tool IDs exactly once; controlled first entry; all original state/error assertions | RED: 1 failed/1 passed; GREEN: both cases and affected/full suites | VERIFIED | -| R-CI-2 | Real fake-runtime and child subprocesses | Parent-environment injection and isolation | Model/MCP parent upstreams; explicit empty child base environment | Exit 0 and exact original model/MCP URLs | RED: 1 failed; GREEN: targeted case and all 15 Sidecar tests | VERIFIED | - -Production, frontend, dependencies, CI policies, credentials and cloud behavior are not changed. Existing source-hash evidence discriminates accidental production drift. No new tests of formatting or duplicated implementation were added. Opt-in Codex/Pi smoke checks are outside this test-only repair; remote CI still runs its existing Codex smoke job. Final remote results are authoritative at https://github.com/volcengine/veadk-python/pull/1190/checks. diff --git a/prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.zh.md b/prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.zh.md deleted file mode 100644 index a525de1d3..000000000 --- a/prd-spec/bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.zh.md +++ /dev/null @@ -1,85 +0,0 @@ -# 稳定 PR #1190 CI 测试 - -[English](2026-10-28-stabilize-concurrent-tests.md) - -Change ID：`pr1190-ci`；创建/修订：2026-10-28；状态：approved。 -比较基线：功能提交 `7527a832`；上游 `23014771`。 -关联设计：[首 Token 时间戳](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md)。 - -## 证据与范围 - -Unit Tests 运行 `40649026439` 的 Python 3.10 作业 `122684493009`：1 failed、7,937 passed、46 skipped、4 xfailed。启动预取测试要求先检查 `tool-codex`，再检查 `tool-codex-snapshot`。生产代码使用 `asyncio.gather` 与 `asyncio.to_thread` 并发执行，两种顺序都有效。Python 3.12 被矩阵 fail-fast 取消。 - -此前本地全量回归还暴露了一条 Sidecar 基线测试：继承开发机模型上游配置后启用稳定中继，却断言固定的伪运行时发现地址。`run_with_harness_sidecar` 已支持显式 `env` 映射。 - -目标：按真实契约稳定测试。非目标：修改运行时、串行化生产并发、放宽断言、添加重试或跳过、修改 CI 配置、前端、依赖和再次部署云端。 - -## 需求与设计 - -- FR-1：两个已配置 Sandbox 工具均恰好检查一次，不依赖调度顺序；最终缓存状态出现在 system-info 响应中。 -- FR-2：通过有时限的线程 Event 明确覆盖两种检查顺序；比较精确调用次数，不要求生产顺序。 -- FR-3：有界轮询响应状态，不能把进入检查桩当作缓存已发布。 -- FR-4：伪 Sidecar 的子进程在显式隔离环境中收到精确发现地址，即使父进程存在模型/MCP 上游变量。 - -仅修改 `tests/cli/test_studio_rbac.py`、`tests/extensions/harness/sidecar_runtime/test_sidecar.py` 和双语设计/证据。保留全部现有响应及地址断言。不修改组件规格：公共接口、运行时、权限、数据与可观测契约均不变。回滚只需撤回本次测试提交。 - -## 任务与验收 - -| 需求 | 任务 | 验收 | 证据 | -| --- | --- | --- | --- | -| FR-1/2 | T-1：控制两种线程顺序，再修正顺序断言 | AC-1：修正前反向调度失败，修正后两种调度均通过 | 定向 pytest 与原始 CI 失败 | -| FR-3 | T-2：等待两种响应状态均发布 | AC-2：全部现有模型状态精确断言通过 | 同一个参数化 TestClient 测试 | -| FR-4 | T-3：为伪 Sidecar 显式提供空环境 | AC-3：父进程存在上游变量时，精确地址断言仍通过 | 伪运行时与真实子进程测试 | -| 全部 | T-4：必需检查、推送并确认 CI | AC-4：受影响套件、默认全量回归、pre-commit 与远端 CI 通过；生产变更行覆盖率保持 >=95% | 下述仓库命令 | - -命令：`uv run --no-sync --extra dev pytest tests/cli/test_studio_rbac.py tests/extensions/harness/sidecar_runtime/test_sidecar.py -n 2 -q`；`uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`；`uv run --no-sync --extra dev pre-commit run --all-files`。生产代码不变，复用功能覆盖率与真实云端证据，并确认源码哈希。 - -## 审查与授权 - -2026-10-28：用户授权完成飞书方案后修复 PR #1190 CI；此前对此分支的提交、推送授权继续有效。直接设计审查（`review-spec` 不可用）确认仅修改测试、精确次数/状态/地址断言、有界同步、生产并发不变，且隔离真实凭证。双语标识与验收一致，无设计阻塞。 - -风险：进入检查线程不代表缓存已发布，通过响应状态轮询解决。本地 Python 3.12 与 CI 的 3.10/3.12 矩阵不同，交付需远端结果。仅测试修复不适用再次云端验证；保留此前真实云端 6/6 通过的结论。 - -## 验证记录 - -2026-10-28，`7527a832` 加本次仅测试变更，Python 3.12.13： - -- 原有顺序断言加受控调度：1 passed、1 failed；反向顺序复现原 CI 失败。 -- 显式 `env={}` 前注入父进程上游变量：1 failed，固定发现地址与中继地址不符。原始单用例隔离运行通过，确认问题依赖环境。 -- 修正后：3 项定向用例通过（两种调度与子进程环境）。 -- 合并受影响套件：185 passed、4 failed。Studio 的全部 174 项通过；另四项回环请求走本机代理并收到 HTTP 403。对完整 15 项 Sidecar 文件使用命令级 `NO_PROXY=localhost,127.0.0.1,::1 no_proxy=localhost,127.0.0.1,::1` 后全部通过。因此 189 项受影响用例在正确本地环境中均通过；未修改网络断言或代理策略。 -- 格式修正后 all-files pre-commit 通过；双语标识、字面命令、相对链接与空白检查通过。 -- 九个生产文件哈希与原真实云端构建一致。生产变更行覆盖率仍为 100%（208/208），真实云端 E2E 仍为 6/6 通过。本次修复未新增生产可执行行。 -- 默认全量回归使用同一命令级回环直连配置，`--junitxml` 保存于 Git 外：**7,942 passed、0 failed、42 skipped、4 xfailed；6 subtests passed；472.66s**。选中 7,988 项，包括已执行 7,946 项（含四项预期失败）及跳过 42 项。最终远端 3.10/3.12 结果由推送后的 PR 记录。用户随后要求额外测试仅运行失败项，不再安排广泛测试。 - - -### Gate 状态 - -| Gate | Status | 证据 | -| --- | --- | --- | -| Change Basis | PASS | 对 `7527a832` 检查完整测试/设计差异；上游 `23014771` 未变；无无关变更。 | -| Contract | PASS | 工具精确调用次数、已发布状态及子进程发现地址；生产契约不变。 | -| Impact | PASS | R-CI-1/2 覆盖受影响测试断言与环境边界。 | -| Portfolio | PASS | 两种受控线程调度、TestClient 状态发布、真实伪运行时/子进程。 | -| Baseline | PASS | 修正前反向顺序断言与父进程上游注入均已观察到 RED。 | -| Execution | PASS | 3 项定向用例、全部 189 项受影响用例、默认全量回归与 all-files pre-commit。 | -| Evaluation | PASS | 保留原状态/地址断言；重复调用仍失败；源码哈希及 208/208 生产覆盖率不变。 | -| Handoff | PASS | 双语设计/证据同步；最终推送版本 CI 证据由 PR #1190 链接提供。 | - -### Change Impact - -| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | -| --- | --- | --- | --- | --- | --- | -| FR-1/2/3 | 测试调度与完成判定 | 启动预取测试与 system-info 缓存响应 | `asyncio.gather`、`asyncio.to_thread`、`test_system_info_prefetches_codex_model_env_state_on_startup` | 有效调度导致 CI 误报，或状态发布前检查响应 | R-CI-1 Medium | -| FR-4 | 测试子进程环境 | 伪 Sidecar 与子进程执行 | `run_with_harness_sidecar(env=...)`、子进程环境测试 | 父进程上游变量改变预期发现地址 | R-CI-2 Medium | - -两项风险均跨越自有集成边界；固有影响/暴露/变更危险/检测困难为 Medium/Medium/Medium/Low。本次测试范围没有重大未知项。剩余不确定性限于未测的主机负载；不作负载或性能结论。 - -### Test Portfolio - -| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | -| --- | --- | --- | --- | --- | --- | --- | -| R-CI-1 | 线程化提供方桩与真实 ASGI 响应 | 受控调度与状态转换 | Codex 先执行、snapshot 先执行、各类型精确最终状态 | 两个工具 ID 各一次；受控首个入口；原有全部状态/错误断言 | RED：1 failed/1 passed；GREEN：两用例与受影响/全量套件 | VERIFIED | -| R-CI-2 | 真实伪运行时与子进程 | 父环境注入与隔离 | 父模型/MCP 上游；显式空子进程基环境 | 退出 0，原有模型/MCP 地址完全一致 | RED：1 failed；GREEN：定向用例及全部 15 项 Sidecar 测试 | VERIFIED | - -生产、前端、依赖、CI 策略、凭证与云端行为均不变。现有源码哈希证据可以识别意外生产漂移。没有新增格式测试或重复实现测试。需显式启用的 Codex/Pi smoke 不属于仅测试修复；远端 CI 仍执行既有 Codex smoke 作业。最终远端结果以 https://github.com/volcengine/veadk-python/pull/1190/checks 为准。 diff --git a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md b/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md deleted file mode 100644 index ba3ef90c6..000000000 --- a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.md +++ /dev/null @@ -1,119 +0,0 @@ -# First-token timestamps - -[中文版](2026-10-28-first-token-timestamps.zh.md) - - -Successor: [APMPlus streaming and TTFT telemetry](../../bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md) adds standard per-request attributes and TTFT Histogram recording. The historical scope and evidence below predate that extension. - -Change ID: `first-token-timestamps`; created/revised: 2026-10-28; status: approved (implementation and local verification complete; current publication checks are tracked in PR #1190). -Component: [model-timing](../../../specs/model-timing/README.md). Base: `23014771`. - -## Background, scope, and approval - -A360 needs timestamps to analyze model and Agent waiting time. Existing `portal_metrics.py` defines TTFT/TPOT instruments but leaves recording as TODO; response tracing alone does not preserve first-output receipt. The user explicitly narrowed scope to first-token timestamps, timing definitions/ranges, and non-streaming distinction, then authorized implementation on a new branch, changed-line coverage >=95%, and real cloud E2E. This approval covers isolated test deployment. The user subsequently authorized committing and pushing this feature branch. PR creation is not requested. - -Goals: additive timing attributes on request/model spans, receipt-time capture without usage dependency, documented scopes, live cloud proof. Non-goals: TTFT/TPOT histograms, client-render timing, provider inference timestamps, hidden provider retry instrumentation, external-engine model interception, frontend changes, dependency upgrades. - -## Requirements and scenarios - -- FR-1: HTTP requests and direct Runner calls establish isolated request timing before preprocessing (CON-1/5). -- FR-2: SDK requests capture model start and first generated delta for text/reasoning/tool-call streams; empty/metadata/final aggregate events are ignored (CON-2/3/6). -- FR-3: Non-streaming and unsupported/no-output paths expose explicit status with absent first-token timestamp; retries and cancellation retain accurate attempt evidence (CON-4/5). -- FR-4: Existing cloud exporters and JSON dumps retain the timing attributes without exposing content or changing responses (CON-6). - -Given a stream beginning with role metadata, when text arrives, then its receipt timestamp is latched once. Given reasoning or tool arguments precede text, the first generated delta is tagged by type. Given no usage, timing remains present. Given a non-streaming request, completion never becomes a first token. Given two parallel requests or resumed generator iterations, timestamps remain associated with the correct invocation. Given a failed pre-output attempt and retry, child attempt spans are distinct. Given generator cancellation, attempt spans end and the original cancellation propagates. - -## Design and impact - -Use a small shared timing module with request ContextVar, ASGI middleware, yield-safe Runner propagation, content-delta classification, and a per-SDK-request span recorder. A timed LiteLLM client subclass intercepts the actual SDK call before ADK aggregation; Ark capture is at its raw event loop. This avoids estimating first output from final telemetry and avoids globally patching third-party clients. Supported HTTP factories install the middleware once. Existing annotation processing copies request timing to invocation/agent spans. Final telemetry marks unsupported paths without inventing model start. - -Affected code: timing module, LiteLLM client/RetryingLiteLlm, ArkLlm, Runner, telemetry, in-memory annotation processor, AgentKit/Harness factories. Generated AgentKit projects already use the shared factory. No auth or database contracts change. Existing tools, content redaction, retry/fallback behavior, and exports remain intact. Rollback removes additive fields/code; no migration is required. - -## Tasks and acceptance - -| Requirement | Task | Acceptance | Test/command | Result | -| --- | --- | --- | --- | --- | -| FR-1 | T-1: request boundary/context | AC-1: correct start/source; no context leakage | `uv run --extra dev pytest tests/test_model_timing.py -q` | pass: request/context contracts | -| FR-2/3 | T-2: adapter instrumentation | AC-2: first delta latched; non-streaming absent; attempts terminate | timing and adapter regression tests | pass: 55 timing/adapter cases | -| FR-4 | T-3: span/export wiring | AC-3: attributes survive export and dump | tracing/integration regression tests | pass: actual cloud exporter/dump | -| FR-1/2/3/4 | T-4: verification | AC-4: changed executable line coverage >=95%; required checks pass | coverage JSON against `23014771`; `uv run --extra dev pre-commit run --all-files`; `uv run --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke"` | pass: 100% coverage, static/docs checks; fail: one existing default-regression case | -| FR-1/2/3/4 | T-5: isolated live cloud E2E | AC-5: deployed branch code, real streaming/non-streaming model calls, exported timestamps verified | isolated AgentKit Runtime; protected environment credentials; HTTP calls and exported span assertions | pass: 6 real cloud cases, source hashes verified, Runtime deleted | - -## Review, risks, and delivery - -Direct design review completed because `review-spec` is unavailable. PRD/spec responsibilities, bilingual identifiers, no-usage/empty/non-streaming semantics, generator context and resource cleanup, request source, privacy, compatibility, testability, and deployment authorization have been reconciled; no design blocker remains. User authorization is the implementation request following the agreed scope. Implementation review verified raw SDK interception, yield-safe request context, stream cleanup, compatible client injection, no-content timing, and factory/export consumers. The feature-specific acceptance evidence is complete. AC-4's repository-wide default-regression condition remains fail for one existing Sidecar test reproduced on the comparison base; this PRD stays approved rather than claiming all delivery gates passed. SDK boundaries do not expose internal provider retry start. HTTP timing starts at ASGI entry and is not browser-visible wait. - -## Verification conclusions (2026-10-28) - -Comparison base: `2301477104f6f77e76c8182529545950e2d8ae6e`; branch: `feat/first-token-timestamps`. The inspected diff includes every modified tracked file and new untracked production/test/design file. The user's original dirty checkout is preserved in a separate worktree. Python 3.12.13, google-adk 2.7.1, LiteLLM 1.83.14, and the repository environment with all extras were used; test commands retained that environment with `--no-sync`. No dependency metadata changed. - -Old behavior did not preserve first generated delta receipt. CON-1..6 now define additive UTC Unix-nanosecond attributes, source/mode/type/status, per-SDK-request attempt spans, and unchanged response/error propagation. HTTP factories, Runner, raw adapter loops, final telemetry, existing exporters/dumps, and bilingual user documentation are the affected consumers. Generated AgentKit projects already call the shared factory. No frontend UI, schema migration, authentication, or metric histogram contract changes. - -### Gate status - -| Gate | Status | Evidence or blocking reason | -| --- | --- | --- | -| Change Basis | PASS | Complete tracked/untracked diff inspected against `23014771`; original work preserved. | -| Contract | PASS | FR-1..4 and CON-1..6 agree with code and both document languages. | -| Impact | PASS | R-1..7 map request, model, lifecycle, export, factories, compatibility, and docs consumers. | -| Portfolio | PASS | Controlled clocks, raw SDK boundaries, failure injection, ASGI contracts, cloud E2E, and existing regression. | -| Baseline | PASS | Missing timing module was RED; close-before-iteration was RED then GREEN. Existing Harness HTTP test preconditions were corrected without changing assertions; two collection-context cases are GREEN. | -| Execution | PASS | Changed behavior checks executed; exact final counts below. One unrelated default-regression failure is reproduced on the comparison base and remains `fail`. | -| Evaluation | PASS | 208/208 changed executable production lines; 53/54 changed branch arcs; all material feature risks verified; the remaining Ark optional-close guard branch is explained below. | -| Handoff | PASS | Bilingual contracts/docs reconciled, live evidence saved without content/credentials, isolated cloud Runtime deleted; commit/push subsequently authorized. | - -### Change Impact - -| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | -| --- | --- | --- | --- | --- | --- | -| FR-1 | CON-1/5 request source and propagation | Runner, ASGI request/invocation spans | `timing.py`, `runner.py`, application factories | Request timing leaks across yields/concurrent requests or begins after preprocessing | R-1 High | -| FR-2 | CON-2/3 first delta | LiteLLM and Ark raw SDK responses | `timed_lite_llm.py`, `ark_llm.py` | Metadata/aggregates counted; reasoning/tool output missed; usage dependency | R-2 High | -| FR-3 | CON-4 mode/status | Model spans and unsupported engines | `ModelTiming`, `mark_uninstrumented_model` | Non-streaming completion or invocation start falsely becomes first-token/model start | R-3 High | -| FR-3 | CON-2/5 attempts and termination | Retry, error, cancellation, stream closure | `RetryingLiteLlm`, `_TimedStream`, Ark response loop | Leaked spans/resources, replayed output, lost first-output evidence | R-4 High | -| FR-4 | CON-6 export | OTel processors/exporters and trace dump | `inmemory_exporter.py`, `telemetry.py`, live `/e2e/evidence` | Timing disappears on export or sensitive content is added | R-5 Medium | -| FR-1/4 | Additive compatible wiring | AgentKit/Harness factories, generated apps, existing callers | Existing AgentKit/Harness/Runner/model test contracts and generator factory call sites | Request events, route/session behavior, or public client injection regresses | R-6 High | -| FR-1..4 | Maintained definitions | PRD/spec and tracing pages in both languages | Paired `.md`/`.zh.md`, `.mdx`/`.en.mdx` | Scope/identifiers disagree or MDX breaks the docs build | R-7 Medium | - -High ratings reflect common public exposure plus timing/lifecycle hazards; Medium ratings reflect cross-module export/document boundaries. No new authorization or persistence risk is introduced. Coverage reduces execution uncertainty; it does not reduce failure impact severity. - -### Test Portfolio - -| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | -| --- | --- | --- | --- | --- | --- | --- | -| R-1 | ASGI/async generators | Clock control, concurrency, context/closure contracts | HTTP vs Runner, inherited start, parallel yields, errors/close, non-HTTP scope | Correct source/start; caller context restored; request isolation | `tests/test_model_timing.py`; 2 concurrent live cloud calls | VERIFIED | -| R-2 | Actual owned adapters; provider boundary controlled | Equivalence partitions and adapter integration | Text/reasoning/tool deltas; empty/metadata/aggregate; missing usage | Timestamp latches once on first generated delta before ADK aggregation | Both new test modules; 4 real cloud adapter/mode cases | VERIFIED | -| R-3 | Timing state/telemetry | Mode/status contracts | Non-streaming, no output, unsupported, no recording tracer | Explicit status and absence of fabricated model/first-token time | Unit/tracing tests and both real cloud non-streaming cases | VERIFIED | -| R-4 | SDK request/iterator lifecycle | Failure injection and real VeADK retry integration | Pre-output 429 retry, error/cancel, close before/after iteration, close error | Distinct child spans, preserved output/errors, original stream closes once, terminal outcome | `tests/models/test_model_timing_adapters.py` and existing retry/fallback tests | VERIFIED | -| R-5 | Actual exporter/dump | Integration and privacy inspection | Cloud-exported request/model fields; source fingerprint | Expected attributes/parent/order survive actual dump; timing adds no content | 6 sanitized live evidence files, credential-content check, pre-commit scans | VERIFIED | -| R-6 | Factories and existing SDK callers | Contract/affected/default regression | Routes, session creation/config, Runner events, adapters/retries/fallbacks | Existing assertions retained; additive timing middleware and fields | 244 affected tests; final default-regression and baseline conclusion below | VERIFIED | -| R-7 | Docs build and paired files | Type/build, identifiers and relative links | Chinese/English definitions and valid MDX | Equivalent fields/IDs/scopes; site compiles and type-checks | Docs commands, paired-language/link check, `git diff --check` | VERIFIED | - -### Executed checks - -- `uv run --no-sync --extra dev pytest tests/models/test_model_timing_adapters.py tests/test_model_timing.py -q`: **55 passed**, zero failures/skips. Provider calls are controlled at the SDK boundary; these are local adapter tests. -- `COVERAGE_FILE=/tmp/veadk-first-token-delivery.coverage uv run --no-sync --extra dev pytest tests/test_tracing_content.py tests/test_tracing.py tests/test_inmemory_exporter.py tests/test_runner.py tests/runner/test_runner_contract.py tests/integrations/agentkit/test_app.py tests/cloud/test_harness_app_contract.py tests/cloud/test_harness_app_http.py tests/models tests/test_model_timing.py --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-first-token-coverage-delivery.json --cov-report= -q`: **244 selected/executed/passed**, zero failures/skips. -- `uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`: **7,987 selected; 7,945 executed (including 4 expected failures); 7,940 passed, 1 failed, 42 skipped, 4 xfailed; 6 subtests passed; 472.86s; status: fail (existing comparison-base failure)**. Two workers match repository policy. The Codex/Pi smoke markers are excluded by the repository default; external-engine model instrumentation is outside this feature's scope. Skipped/expected-failure cases provide no live evidence. -- Comparison-base execution with full test collection, `-n 2 -k test_run_wraps_child_with_sidecar_environment -q`: **1 failed**. The remaining default-regression failure is the same existing Sidecar child-model-URL assertion (fixed port versus the relay URL). It is not changed or suppressed by this feature. -- `uv run --no-sync --extra dev pre-commit run --all-files` and explicit `--files` for newly added Python/design/spec files: **pass** for Ruff, formatting and applicable secret/dependency checks. Hooks with no matching file are reported skipped, not executed. -- `npm --prefix docs run types:check` and `npm --prefix docs run build`: **pass**. Docs dependencies came from the existing pnpm lock; no package/lock changes. -- Paired-language identifiers, relative links, full production-file SHA256 versus the cloud build, credential-content inspection, and `git diff --check`: **pass**. - -Changed-line coverage is computed from the entire Git diff plus all lines in new untracked production Python modules, intersected with coverage.py executable lines. Tests and Markdown are not production executable lines. No coverage exclusions were added. Result: **100% (208/208)**. Both new production modules have 100% line and branch coverage. The overall changed branch arcs are **53/54**; the unexecuted arc is Ark's optional missing-`close` guard, while the verified real Ark SDK stream implements async `close`. Normal/early-close/error paths use that actual interface. - -The timestamp, status/absence, one-event latch, request isolation, parent relationships, original output and terminal cleanup assertions discriminate plausible defects; aggregate coverage alone is not the oracle. - -### Real cloud E2E - -Region: `cn-beijing`; isolated Runtime: `r-yey87ec8hs2hv32antzi`; actual model: `doubao-seed-2-1-pro-260628`; result: **6/6 pass**. The branch wheel was deployed to the cloud Runtime with all nine changed production files matching SHA256. Calls used the real LiteLLM Chat and Ark Responses adapters and real model service, through the actual VeADK app factory/middleware and Runner; evidence came from the built-in trace exporter/dump. This is distinct from locally controlled SDK-boundary tests. - -Chat streaming/non-streaming, Responses streaming/non-streaming, and concurrent Chat/Responses streams returned nonempty real output and completed. Streaming spans had `http` source, correct `call_llm` parent, `sdk_request` scope, `observed` status/type and request-start <= model-start <= first-token <= span-end. Non-streaming spans had actual SDK `streaming=false`, `non_streaming` status, and no first-token time/type. Concurrent requests retained distinct request starts/session evidence. Exported parent fields agreed with child attempts. The isolated Runtime was deleted after evidence capture. - -Sanitized evidence is retained outside Git in `veadk-first-token-20261028`; conclusions: `cloud-verification.json`; individual cases: `chat-stream.json`, `chat-nonstream.json`, `responses-stream.json`, `responses-nonstream.json`, `concurrent-chat.json`, `concurrent-responses.json`; diff coverage: `changed-coverage.json`. Only verification conclusions are recorded here; no credential or troubleshooting history is included. - -### Delivery limits - -Request start is server ASGI ingress or direct Runner execution, not browser submission/render. Model start is adapter SDK request, not provider inference. Opaque LiteLLM/provider retries remain within one SDK request; external/custom engines have explicit unavailable status. No new TTFT/TPOT histogram or cross-host duration guarantee is added. Cloud proof covers one Beijing Runtime and the two supported adapters/model modes; no broad provider matrix or load benchmark is claimed. The existing Sidecar regression above remains outside this change. Commit and push are subsequently authorized; no PR is requested. Git history and the remote feature branch record publication. - -Pre-publication verification (2026-10-28): fetched and rebased against `origin/main` (`23014771`, unchanged); all applicable pre-commit hooks passed and all 244 affected tests passed again. Production SHA256 values still match the real cloud E2E build. - -CI follow-up (2026-10-28): [test stabilization](../../bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.md) corrects the concurrent Sandbox test oracle and isolates the existing Sidecar fixture. The former baseline failure is resolved. Latest local default regression: **7,942 passed, 0 failed, 42 skipped, 4 xfailed; 6 subtests passed**. Historical failures above describe the original run. All nine production hashes, 100% (208/208) changed production-line coverage, and 6/6 real cloud E2E evidence remain unchanged. PR creation and the CI follow-up are now explicitly authorized. Published checks are available at [PR #1190](https://github.com/volcengine/veadk-python/pull/1190/checks). diff --git a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md b/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md deleted file mode 100644 index 2c2a8b664..000000000 --- a/prd-spec/features/first-token-timestamps/2026-10-28-first-token-timestamps.zh.md +++ /dev/null @@ -1,119 +0,0 @@ -# 首 Token 时间戳 - -[English](2026-10-28-first-token-timestamps.md) - - -后续设计：[APMPlus 流式与 TTFT 遥测](../../bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md) 添加逐请求标准属性和 TTFT Histogram 记录。下列历史范围与证据早于该扩展。 - -变更 ID：`first-token-timestamps`；创建/修订：2026-10-28；状态：approved（实现与本地验证已完成；当前发布检查由 PR #1190 记录）。 -组件：[model-timing](../../../specs/model-timing/README.zh.md)。基线：`23014771`。 - -## 背景、范围和授权 - -A360 需要时间戳分析模型和 Agent 等待时间。现有 `portal_metrics.py` 定义了 TTFT/TPOT 仪表，但实际记录仍为 TODO；单靠响应 Trace 无法保留首输出接收时间。用户明确将范围收敛为首 Token 时间戳、计时定义/范围、区分非流式，并授权新建分支实现、变更行覆盖率 >=95% 和真实云端 E2E。授权覆盖隔离测试部署。用户随后授权提交并推送本功能分支，未要求创建 PR。 - -目标：在请求/模型 Span 上新增计时属性，不依赖 usage 采集接收时间，记录范围定义，提供真实云端证据。非目标：TTFT/TPOT 直方图、客户端渲染计时、服务端推理时间、Provider 隐藏重试采集、外部执行引擎模型拦截、前端修改、依赖升级。 - -## 需求和场景 - -- FR-1：HTTP 请求和直接 Runner 调用在预处理前建立隔离请求计时（CON-1/5）。 -- FR-2：SDK 请求记录模型开始及正文/推理/工具调用流的首个生成增量；忽略空包、元数据和最终聚合事件（CON-2/3/6）。 -- FR-3：非流式、不支持和无输出路径明确标记状态且不提供首 Token 时间；重试和取消保留准确尝试证据（CON-4/5）。 -- FR-4：现有云端导出器和 JSON dump 保留计时属性，不泄露内容，不改变响应（CON-6）。 - -流以角色元数据开始时，正文到达后只锁存一次接收时间。推理或工具参数先于正文时，首个生成增量按类型标记。没有 usage 时仍有计时。非流式响应完成不能作为首 Token。两个并发请求或恢复生成器迭代时，时间戳仍属于正确调用。首输出前失败并重试时，各尝试子 Span 独立。取消生成器时，尝试 Span 结束且原取消异常继续传播。 - -## 设计与影响 - -使用小型公共计时模块，包含请求 ContextVar、ASGI 中间件、不会跨 yield 泄漏的 Runner 传播、生成增量识别和每次 SDK 请求的 Span 记录器。计时 LiteLLM 客户端子类在 ADK 聚合之前拦截实际 SDK 调用；Ark 在原始事件循环采集。避免从最终遥测估计首输出，也避免全局修改第三方客户端。支持的 HTTP 工厂仅安装一次中间件。现有标注处理器将请求计时复制到 invocation/agent Span。最终遥测为不支持的路径标记状态，不伪造模型开始。 - -影响代码：计时模块、LiteLLM 客户端/RetryingLiteLlm、ArkLlm、Runner、telemetry、内存标注处理器、AgentKit/Harness 工厂。生成的 AgentKit 项目已使用共享工厂。鉴权和数据库契约不变。现有工具、内容脱敏、重试/fallback 和导出行为保持一致。回滚移除新增字段与代码，无需迁移。 - -## 任务与验收 - -| 需求 | 任务 | 验收 | 测试/命令 | 结果 | -| --- | --- | --- | --- | --- | -| FR-1 | T-1：请求入口/上下文 | AC-1：起点和来源准确；上下文不泄漏 | `uv run --extra dev pytest tests/test_model_timing.py -q` | pass：请求/上下文契约 | -| FR-2/3 | T-2：适配器采集 | AC-2：锁存首增量；非流式缺省；尝试结束 | 计时与适配器回归测试 | pass：55 项计时/适配器用例 | -| FR-4 | T-3：Span/导出接入 | AC-3：导出和 dump 保留属性 | tracing/integration 回归测试 | pass：真实云端 exporter/dump | -| FR-1/2/3/4 | T-4：验证 | AC-4：变更可执行行覆盖率 >=95%；必需检查通过 | 相对 `23014771` 的 coverage JSON；`uv run --extra dev pre-commit run --all-files`；`uv run --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke"` | pass：100% 覆盖率、静态/文档检查；fail：一项既有默认回归 | -| FR-1/2/3/4 | T-5：隔离真实云端 E2E | AC-5：部署分支代码、真实流式/非流式模型调用、核对导出时间戳 | 隔离 AgentKit Runtime；受保护的环境凭证；HTTP 调用与导出 Span 断言 | pass：6 项真实云端用例、源码指纹一致、Runtime 已删除 | - -## 评审、风险和交付 - -因 `review-spec` 不可用，已直接完成设计评审。PRD/spec 职责、双语标识、无 usage/空包/非流式语义、生成器上下文和资源清理、请求来源、隐私、兼容性、可测试性及部署授权已对齐，无设计阻塞。用户授权来自确认范围后的实现请求。实现评审核对了原始 SDK 拦截、yield 安全的请求上下文、流清理、兼容的 client 注入、不采集内容的计时，以及工厂/导出消费者。需求自身验收证据完整。AC-4 的仓库默认回归条件仍为 fail：一项既有 Sidecar 测试已在对比基线复现，因此 PRD 保持 approved，不宣称全部交付门禁通过。SDK 边界无法暴露 Provider 内部重试开始。HTTP 计时起于 ASGI 入口，不代表浏览器可见等待。 - -## 验证结论（2026-10-28） - -对比基线：`2301477104f6f77e76c8182529545950e2d8ae6e`；分支：`feat/first-token-timestamps`。检查范围包含所有已修改的受版本管理文件，以及尚未跟踪的新增生产代码、测试和设计文件。独立 worktree 保留了用户原工作区的未提交改动。验证环境为 Python 3.12.13、google-adk 2.7.1、LiteLLM 1.83.14，安装仓库全部 extras；测试命令通过 `--no-sync` 保留该环境。依赖元数据未修改。 - -旧行为不保留首个生成增量的接收时间。CON-1..6 现在定义增量添加的 UTC Unix 纳秒属性、来源/模式/类型/状态、每次 SDK 请求的尝试 Span，以及保持原有响应和异常传播。受影响的消费者包括 HTTP 工厂、Runner、适配器原始事件循环、最终遥测、现有 exporter/dump 和双语用户文档。生成的 AgentKit 项目已调用共享工厂。前端 UI、数据迁移、认证和指标直方图契约均无变更。 - -### Gate 状态 - -| Gate | Status | 证据或阻断原因 | -| --- | --- | --- | -| Change Basis | PASS | 对 `23014771` 检查完整的已跟踪/未跟踪 diff；保留原工作区。 | -| Contract | PASS | FR-1..4、CON-1..6 与代码和两种语言的文档一致。 | -| Impact | PASS | R-1..7 映射请求、模型、生命周期、导出、工厂、兼容性和文档消费者。 | -| Portfolio | PASS | 受控时钟、原始 SDK 边界、故障注入、ASGI 契约、云端 E2E 和既有回归。 | -| Baseline | PASS | 计时模块缺失时为 RED；迭代前关闭用例 RED 后转为 GREEN。既有 Harness HTTP 测试补齐前置条件，断言未变；完整收集上下文中的两项用例为 GREEN。 | -| Execution | PASS | 已执行变更行为验证，最终精确数量见下文。一项无关的默认回归失败在对比基线上复现，其检查状态仍为 `fail`。 | -| Evaluation | PASS | 变更可执行生产行 208/208，变更分支弧 53/54；所有实质性需求风险均已验证，下文说明 Ark 可选关闭保护分支。 | -| Handoff | PASS | 双语契约/文档对齐，保存不含内容/凭证的真实证据，删除独立云端 Runtime；用户随后授权提交/推送。 | - -### Change Impact - -| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk | -| --- | --- | --- | --- | --- | --- | -| FR-1 | CON-1/5 请求来源与传播 | Runner、ASGI 请求/invocation Span | `timing.py`、`runner.py`、应用工厂 | 时间在 yield/并发请求间串用，或晚于预处理开始 | R-1 High | -| FR-2 | CON-2/3 首个增量 | LiteLLM 与 Ark 原始 SDK 响应 | `timed_lite_llm.py`、`ark_llm.py` | 把元数据/聚合响应算成首 Token，漏掉推理/工具增量，依赖 usage | R-2 High | -| FR-3 | CON-4 模式/状态 | 模型 Span 与不支持的引擎 | `ModelTiming`、`mark_uninstrumented_model` | 把非流式完成或 invocation 起点伪装成首 Token/模型起点 | R-3 High | -| FR-3 | CON-2/5 尝试与终止 | 重试、异常、取消、流关闭 | `RetryingLiteLlm`、`_TimedStream`、Ark 响应循环 | Span/资源泄漏、输出重放、首输出证据丢失 | R-4 High | -| FR-4 | CON-6 导出 | OTel processor/exporter 与 Trace dump | `inmemory_exporter.py`、`telemetry.py`、真实 `/e2e/evidence` | 导出丢失时间属性，或添加敏感内容 | R-5 Medium | -| FR-1/4 | 兼容的增量接入 | AgentKit/Harness 工厂、生成应用、既有调用方 | 既有 AgentKit/Harness/Runner/模型测试契约和生成器工厂调用点 | 请求事件、路由/会话行为或公共 client 注入回归 | R-6 High | -| FR-1..4 | 持续维护的定义 | 两种语言的 PRD/spec 和 Tracing 页面 | 成对 `.md`/`.zh.md`、`.mdx`/`.en.mdx` | 范围/标识符不一致，或 MDX 破坏文档构建 | R-7 Medium | - -High 对应常用公共路径与计时/生命周期变更风险；Medium 对应跨模块的导出/文档边界。未引入新的授权或持久化风险。覆盖率降低执行范围的不确定性，不降低故障影响严重度。 - -### Test Portfolio - -| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status | -| --- | --- | --- | --- | --- | --- | --- | -| R-1 | ASGI/异步生成器 | 时钟控制、并发、上下文/关闭契约 | HTTP 与 Runner、继承起点、并行 yield、异常/关闭、非 HTTP scope | 来源/起点正确，恢复调用方上下文，请求相互隔离 | `tests/test_model_timing.py`；2 次并发真实云端调用 | VERIFIED | -| R-2 | 真实自有适配器；受控 Provider 边界 | 等价类与适配器集成 | 文本/推理/工具增量，空值/元数据/聚合，缺少 usage | ADK 聚合前首个生成增量锁定时间，且只记录一次 | 两个新增测试模块；4 个真实云端适配器/模式用例 | VERIFIED | -| R-3 | 计时状态/遥测 | 模式/状态契约 | 非流式、无输出、不支持（`unsupported`）、无 recording tracer | 状态明确，不伪造模型/首 Token 时间 | 单元/Tracing 测试及两个真实云端非流式用例 | VERIFIED | -| R-4 | SDK 请求/迭代器生命周期 | 故障注入与真实 VeADK 重试集成 | 输出前 429 重试，异常/取消，迭代前后关闭，关闭异常 | 独立子 Span，保留输出/异常，原始流只关闭一次，终态正确 | `tests/models/test_model_timing_adapters.py` 及既有重试/fallback 测试 | VERIFIED | -| R-5 | 实际 exporter/dump | 集成与隐私检查 | 云端导出的请求/模型字段，源码指纹 | 真实 dump 保留属性/父子关系/时间顺序；计时不添加内容 | 6 份脱敏真实证据，凭证内容检查，pre-commit 扫描 | VERIFIED | -| R-6 | 工厂和既有 SDK 调用方 | 契约/受影响/默认回归 | 路由、会话创建/配置、Runner 事件、适配器/重试/fallback | 保留既有断言；计时中间件和字段为增量变更 | 244 项受影响测试；下文最终默认回归和基线结论 | VERIFIED | -| R-7 | 文档构建和成对文件 | 类型/构建、标识符和相对链接 | 中英文定义与有效 MDX | 字段/ID/范围等价；文档编译及类型检查通过 | 文档命令、双语/链接检查、`git diff --check` | VERIFIED | - -### 已执行检查 - -- `uv run --no-sync --extra dev pytest tests/models/test_model_timing_adapters.py tests/test_model_timing.py -q`：**55 项通过**，无失败/跳过。Provider 调用在 SDK 边界受控，这是本地适配器测试。 -- `COVERAGE_FILE=/tmp/veadk-first-token-delivery.coverage uv run --no-sync --extra dev pytest tests/test_tracing_content.py tests/test_tracing.py tests/test_inmemory_exporter.py tests/test_runner.py tests/runner/test_runner_contract.py tests/integrations/agentkit/test_app.py tests/cloud/test_harness_app_contract.py tests/cloud/test_harness_app_http.py tests/models tests/test_model_timing.py --cov=veadk --cov-branch --cov-report=json:/tmp/veadk-first-token-coverage-delivery.json --cov-report= -q`：**244 项选中/执行/通过**，无失败/跳过。 -- `uv run --no-sync --extra dev pytest -n 2 -m "not codex_smoke and not piagent_smoke" -q`：**选中 7,987 项；执行 7,945 项（含 4 项预期失败）；7,940 项通过、1 项失败、42 项跳过、4 项 xfailed；另有 6 个子测试通过；472.86s；状态：fail（对比基线的既有失败）**。两个 worker 符合仓库要求。仓库默认回归排除 Codex/Pi smoke 标记；外部引擎模型拦截不在本需求范围。跳过和预期失败的用例不作为真实验证证据。 -- 对比基线以完整测试收集上下文执行 `-n 2 -k test_run_wraps_child_with_sidecar_environment -q`：**1 项失败**。剩余默认回归失败为相同的既有 Sidecar 子进程模型 URL 断言（固定端口与 relay URL），本需求未修改或屏蔽该用例。 -- `uv run --no-sync --extra dev pre-commit run --all-files` 及对新增 Python/设计/spec 文件显式执行 `--files`：Ruff、格式及适用的凭证/依赖检查均 **pass**。无匹配文件的 hook 标记为跳过，不算执行通过。 -- `npm --prefix docs run types:check` 和 `npm --prefix docs run build`：均 **pass**。文档依赖来自既有 pnpm lock，package/lock 未修改。 -- 双语标识符、相对链接、全部生产文件 SHA256 与云端构建一致性、凭证内容检查以及 `git diff --check`：均 **pass**。 - -变更行覆盖率按完整 Git diff 加新增未跟踪生产 Python 模块的全部行，再与 coverage.py 可执行行求交集计算。测试与 Markdown 不属于生产可执行行。未添加任何覆盖率排除项。结果：**100%（208/208）**。两个新增生产模块的行和分支覆盖率均为 100%。整体变更分支弧为 **53/54**；未执行分支是 Ark 可选的缺少 `close` 保护分支，而经验证的真实 Ark SDK Stream 具备异步 `close`。正常/提前关闭/异常路径使用该真实接口。 - -时间值、状态/字段缺失、事件只锁定一次、请求隔离、父子关系、原始输出和终态资源关闭断言，能够区分相应缺陷；累计覆盖率本身不是测试判据。 - -### 真实云端 E2E - -地域：`cn-beijing`；独立 Runtime：`r-yey87ec8hs2hv32antzi`；真实模型：`doubao-seed-2-1-pro-260628`；结果：**6/6 通过**。云端 Runtime 部署本分支 wheel，全部 9 个生产变更文件的 SHA256 一致。通过实际 VeADK 应用工厂/中间件及 Runner，调用真实 LiteLLM Chat、Ark Responses 适配器和模型服务；证据来自内置 Trace exporter/dump。它与本地受控 SDK 边界测试分别记录。 - -Chat 流式/非流式、Responses 流式/非流式及并发 Chat/Responses 流式调用，均返回非空真实输出并完成。流式 Span 的来源为 `http`，父 Span 为 `call_llm`，范围为 `sdk_request`，状态/类型为 `observed`，且请求开始 <= 模型开始 <= 首 Token <= Span 结束。非流式 Span 的实际 SDK `streaming=false`、状态为 `non_streaming`，无首 Token 时间/类型。并发请求保留不同的请求起点与会话证据。导出的父 Span 字段与子尝试一致。采集证据后已删除独立 Runtime。 - -脱敏证据保留在 Git 之外的 `veadk-first-token-20261028` 目录；结论：`cloud-verification.json`；各场景：`chat-stream.json`、`chat-nonstream.json`、`responses-stream.json`、`responses-nonstream.json`、`concurrent-chat.json`、`concurrent-responses.json`；变更覆盖率：`changed-coverage.json`。本文仅保留验证结论，不包含凭证和排障历史。 - -### 交付边界 - -请求起点是服务端 ASGI 入口或直接 Runner 执行，不是浏览器提交/渲染。模型起点是适配器 SDK 请求，不是 Provider 推理。不可见的 LiteLLM/Provider 内部重试计入一次 SDK 请求；外部/自定义引擎明确标记不可用。未新增 TTFT/TPOT 直方图或跨主机耗时保证。云端证据覆盖北京一个 Runtime、两个支持的适配器及模型调用模式，不宣称完整 Provider 矩阵或负载基准。上述既有 Sidecar 回归在本次变更范围之外。用户随后授权 commit 和 push，未要求创建 PR。发布记录见 Git 历史和远端功能分支。 - -发布前验证（2026-10-28）：已 fetch 并相对 `origin/main`（`23014771`，未变化）执行 rebase；全部适用的 pre-commit hook 通过，244 项受影响测试再次全部通过。生产文件 SHA256 仍与真实云端 E2E 构建一致。 - -CI 后续修复（2026-10-28）：[测试稳定性修复](../../bugfixes/pr1190-ci/2026-10-28-stabilize-concurrent-tests.zh.md)修正 Sandbox 并发测试断言，并隔离既有 Sidecar 测试环境。原基线失败已解决。最新本地默认全量回归：**7,942 passed、0 failed、42 skipped、4 xfailed；6 subtests passed**。上文失败属于原始运行历史。九个生产源码哈希、100%（208/208）生产变更行覆盖率及真实云端 E2E 6/6 证据均不变。用户现已明确授权创建 PR 和修复 CI。推送后的检查结果见 [PR #1190](https://github.com/volcengine/veadk-python/pull/1190/checks)。 diff --git a/specs/model-timing/README.md b/specs/model-timing/README.md deleted file mode 100644 index 51b3fa60e..000000000 --- a/specs/model-timing/README.md +++ /dev/null @@ -1,31 +0,0 @@ -# Model timing - -[中文版](README.zh.md) - -Component ID: `model-timing`; revision: 2026-11-02; status: active. - -## Responsibility and interfaces - -Own native request/model spans and standard streaming TTFT in `veadk/tracing/telemetry/timing.py`, with model adapters, Runner, and VeADK HTTP factories. `portal_metrics.py` owns the existing Histogram instrument; the configured global MeterProvider owns export. No new configuration, credentials, dependencies, or agent response fields are introduced. - -## Contracts - -- CON-1: VeADK AgentKit/Harness HTTP factories create a native `http_request` SERVER span at ASGI entry, before body parsing, ending when the application finishes. Direct Runner execution owns a `runner_request` span. An inherited HTTP request span is reused by Runner. Neither boundary includes pre-ingress client/network/gateway delays. -- CON-2: Each observable SDK request has a `model_request` CLIENT child under the current model/agent context. Its native start is the local SDK start used by TTFT calculation. VeADK-issued retries/fallbacks have separate spans; hidden provider/LiteLLM retries remain within the observed SDK request. This is not provider inference start. -- CON-3: First output is the first nonempty text, reasoning, or tool-call delta. Empty/role/id/signature metadata, usage, heartbeats, and completion-only aggregates do not count. A chunk may contain several tokens. First-output receipt is internal state, latched once without requiring usage or storing content. -- CON-4: `gen_ai.request.stream` is the actual SDK Boolean mode. `gen_ai.chat_completions.streaming_time_to_first_token` is floating-point seconds from SDK start to first output. Non-streaming/no-output/uninstrumented paths omit TTFT. Unknown actual SDK mode is not inferred from Runner configuration. -- CON-5: Spans end on completion, failure, cancellation, and explicit generator closure. Request context is attached only during producer advancement/closure, not across generator yields. Model failures set native Status `ERROR` with `error.type=llm_error`, `timeout`, or `cancelled`. Request failures use `request_error`, `timeout`, or `cancelled`; HTTP 5xx uses `http_error`. Explicit generator closure is not an error. Original outputs, exceptions, and cleanup are preserved. -- CON-6: Native start/end timestamps use OpenTelemetry units. TTFT converts the local Unix-nanosecond difference to seconds; no cross-host or monotonic-clock guarantee is introduced. Negative intervals are omitted with a bounded diagnostic; genuine zero elapsed time is valid. Already observed TTFT survives later interruption. -- CON-7: SDK spans carry `gen_ai.span.kind=llm` and `gen_ai.request.model`. Standard model fields belong to each SDK span, not its aggregate owner. Do not export `veadk.request.*`, `veadk.model.*`, or a custom first-token event; do not duplicate native span times in attributes. No compatibility aliases are retained, as explicitly authorized by the user. -- CON-8: Record the same observed TTFT exactly once in the existing `gen_ai.chat_completions.streaming_time_to_first_token` Histogram, unit `s`, independent of usage and trace sampling. No observations means no sample. Metric-recording failures emit a bounded diagnostic without backend details and do not replace model output/error. -- CON-9: TTFT metric dimensions are the actual `gen_ai.request.model` and existing conversational `gen_ai.operation.name=chat`. Unknown provider/response-model values are omitted. No prompts, responses, exception text, or per-request identifiers are added. Export configuration remains owned by the existing MeterProvider. - -## Compatibility and security - -This intentionally replaces custom timing fields and their mirrored aggregate fields with native span boundaries and standard telemetry. Callers must inspect request/SDK spans and standard TTFT; no legacy aliases remain. Application responses and public Agent invocation signatures do not change. The HTTP middleware does not buffer bodies. New request spans can change trace parentage. Exception text is not recorded by this instrumentation. Rollback requires reverting the coherent timing, hook, test, and documentation change. - -## Verification and change record - -Tests: `tests/test_model_timing.py`, `tests/test_model_ttft.py`, `tests/models/test_model_timing_adapters.py`, and affected Runner/application/exporter tests. Cover native start/parentage, absence of custom fields/events, actual SDK mode, first-output classification, failures/privacy, retry/close/cancellation, yield/task isolation, and real in-memory Histogram data. Changed production-line coverage must reach at least 95%; no exclusions may be added to satisfy it. - -[Design and executed evidence](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.md). The standards-only revision supersedes the predecessor's custom-field contracts. Historical cloud results do not validate this revision; current verification is local unless explicitly recorded otherwise. diff --git a/specs/model-timing/README.zh.md b/specs/model-timing/README.zh.md deleted file mode 100644 index efd216b5c..000000000 --- a/specs/model-timing/README.zh.md +++ /dev/null @@ -1,31 +0,0 @@ -# 模型计时 - -[English](README.md) - -组件 ID：`model-timing`；修订日期：2026-11-02；状态：active。 - -## 职责与接口 - -负责 `veadk/tracing/telemetry/timing.py` 中的原生请求/模型 Span 及标准流式 TTFT，配合模型适配器、Runner 和 VeADK HTTP 工厂。`portal_metrics.py` 管理现有 Histogram instrument；已配置的全局 MeterProvider 负责导出。不引入新配置、凭证、依赖或 Agent 响应字段。 - -## 契约 - -- CON-1：VeADK AgentKit/Harness HTTP 工厂在 ASGI 入口、请求体解析前创建原生 `http_request` SERVER Span，应用执行结束时关闭。直接执行 Runner 时拥有 `runner_request` Span。Runner 复用继承的 HTTP 请求 Span。两种边界均不含入口之前的客户端、网络和网关耗时。 -- CON-2：每次可观测 SDK 请求，在当前模型/Agent 上下文下拥有 `model_request` CLIENT 子 Span。原生开始时间就是 TTFT 计算使用的本地 SDK 起点。VeADK 发起的重试/降级分别创建 Span；供应商/LiteLLM 内部不可观测重试仍计入同一次 SDK 请求。这不是服务端开始推理时间。 -- CON-3：首输出为首个非空文本、推理或工具调用 delta。空增量、角色/id/签名元数据、usage、心跳和仅完成时返回的聚合内容不计入。一个 chunk 可含多个 token。首输出接收时间仅作为内部状态锁定一次，不依赖 usage，也不保存内容。 -- CON-4：`gen_ai.request.stream` 为实际 SDK 布尔模式。`gen_ai.chat_completions.streaming_time_to_first_token` 为 SDK 起点到首输出的浮点秒数。非流式/无输出/未埋点路径省略 TTFT。实际 SDK 模式未知时不从 Runner 配置推导。 -- CON-5：Span 在完成、失败、取消和主动关闭生成器时结束。仅在推进/关闭生产者时绑定请求上下文，不跨生成器 yield 保留。模型失败设置原生 Status `ERROR`，`error.type=llm_error`、`timeout` 或 `cancelled`。请求失败使用 `request_error`、`timeout` 或 `cancelled`；HTTP 5xx 使用 `http_error`。主动关闭生成器不算错误。保留原始输出、异常及清理行为。 -- CON-6：原生起止时间戳采用 OpenTelemetry 单位。TTFT 将本地 Unix 纳秒差值换算为秒，不引入跨主机或单调时钟保证。负间隔省略并产生有限诊断；真正零耗时有效。后续中断不影响已经观测的 TTFT。 -- CON-7：SDK Span 携带 `gen_ai.span.kind=llm` 和 `gen_ai.request.model`。标准模型字段属于每次 SDK Span，不属于聚合的所属 Span。不导出 `veadk.request.*`、`veadk.model.*` 或自定义首 Token 事件，不在属性中重复原生 Span 时间。根据用户明确授权，不保留兼容别名。 -- CON-8：同一 TTFT 观测在现有 `gen_ai.chat_completions.streaming_time_to_first_token` Histogram 中恰好记录一次，单位为 `s`，独立于 usage 和 Trace 采样。没有观测就没有样本。指标记录失败时产生不含后端详情的有限诊断，不替换模型输出/异常。 -- CON-9：TTFT 指标维度为实际 `gen_ai.request.model` 和既有对话操作 `gen_ai.operation.name=chat`。未知供应商/响应模型省略。不添加提示词、响应、异常正文或逐请求标识。导出配置仍由现有 MeterProvider 管理。 - -## 兼容与安全 - -本变更有意用原生 Span 边界和标准遥测替代自定义计时字段及其聚合镜像字段。调用方应查看请求/SDK Span 和标准 TTFT；不保留旧别名。应用响应与公开 Agent 调用签名不变。HTTP 中间件不缓存请求体。新增请求 Span 可能改变 Trace 父子关系。本埋点不记录异常正文。回滚需要整体还原计时、钩子、测试和文档改动。 - -## 验证与变更记录 - -测试：`tests/test_model_timing.py`、`tests/test_model_ttft.py`、`tests/models/test_model_timing_adapters.py` 以及受影响的 Runner/应用/导出器测试。覆盖原生起点/父子关系、无自定义字段/事件、实际 SDK 模式、首输出分类、失败/隐私、重试/关闭/取消、yield/任务隔离及真实内存 Histogram 数据。生产变更行覆盖率至少 95%，不得为达标新增排除。 - -[设计与执行证据](../../prd-spec/bugfixes/apmplus-ttft/2026-11-02-apmplus-ttft.zh.md)。仅标准字段修订取代前序自定义字段契约。历史云端结果不证明本修订；除非明确另行记录，本次验证均为本地验证。