Skip to content

Commit c1d4096

Browse files
authored
feat(tracing): add request and first-token timestamps (#1190)
* feat(tracing): add request and first-token timestamps * test: stabilize concurrent startup prefetch and isolate sidecar environment
1 parent f987746 commit c1d4096

22 files changed

Lines changed: 1566 additions & 23 deletions

File tree

‎docs/content/docs/framework/tracing.en.mdx‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -187,3 +187,22 @@ In a multi-agent scenario, spans are linked through `parent_span_id`, showing th
187187
<Callout type="info" title="OpenTelemetry Compatibility">
188188
VeADK's field naming follows the OpenTelemetry generative-AI conventions, so you can import tracing data directly into any OpenTelemetry-compatible system for analysis and visualization.
189189
</Callout>
190+
191+
192+
## Request, model, and first-token timestamps
193+
194+
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.
195+
196+
| Attribute | Meaning |
197+
| --- | --- |
198+
| `veadk.request.start_time_unix_ns` | HTTP ASGI entry in VeADK AgentKit/Harness apps, or direct VeADK Runner execution entry. |
199+
| `veadk.request.start_source` | `http` or `runner`; an inherited HTTP timestamp takes precedence. |
200+
| `veadk.model.start_time_unix_ns` | Start of one adapter SDK request, not provider inference start. |
201+
| `veadk.model.streaming` | Actual model SDK request mode, independent of HTTP SSE transport. |
202+
| `veadk.model.first_token_time_unix_ns` | Receipt of the first nonempty generated content delta. |
203+
| `veadk.model.first_token_type` | `text`, `reasoning`, or `tool_call`. |
204+
| `veadk.model.first_token_status` | `observed`, `non_streaming`, `no_output`, or `unsupported`. |
205+
206+
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.
207+
208+
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.

‎docs/content/docs/framework/tracing.mdx‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -185,3 +185,22 @@ Tracing 数据由一系列 **Span** 组成,每个 Span 记录一次操作(
185185
<Callout type="info" title="与 OpenTelemetry 的兼容性">
186186
VeADK 的字段命名遵循 OpenTelemetry 生成式 AI 规范,你可以直接将 Tracing 数据导入到 OpenTelemetry 兼容的系统中进行分析和可视化。
187187
</Callout>
188+
189+
190+
## 请求、模型与首 Token 时间戳
191+
192+
启用 OpenTelemetry Tracing 后,VeADK 默认 LiteLLM 和 Ark Responses 适配器会在模型 Span 上添加以下扩展属性。时间戳统一采用 UTC Unix 纳秒。
193+
194+
| 属性 | 含义 |
195+
| --- | --- |
196+
| `veadk.request.start_time_unix_ns` | VeADK AgentKit/Harness 应用的 HTTP ASGI 入口,或直接调用 VeADK Runner 的执行入口。 |
197+
| `veadk.request.start_source` | `http` 或 `runner`;继承的 HTTP 时间戳优先。 |
198+
| `veadk.model.start_time_unix_ns` | 一次适配器 SDK 请求的开始,不是服务端开始推理。 |
199+
| `veadk.model.streaming` | 实际模型 SDK 请求模式,与 HTTP SSE 传输独立。 |
200+
| `veadk.model.first_token_time_unix_ns` | 收到首个非空生成内容增量的时间。 |
201+
| `veadk.model.first_token_type` | `text`、`reasoning` 或 `tool_call`。 |
202+
| `veadk.model.first_token_status` | `observed`、`non_streaming`、`no_output` 或 `unsupported`。 |
203+
204+
首 Token 采集排除角色/id/签名元数据、空增量、usage、心跳和仅完成时返回的聚合内容。不依赖 token usage 或内容采集。一个 chunk 可含多个 token,因此这里表示 SDK 侧观测到首输出的时间。非流式调用没有首 Token 时间戳,不能用响应完成时间替代。
205+
206+
每次 SDK 请求建立 `model_request` 子 Span,所属模型 Span 同时记录最近一次尝试的字段。VeADK 发起的重试和 fallback 分别记录尝试;LiteLLM/Provider 内部重试计入所观测的 SDK 请求(`veadk.model.request_scope=sdk_request`)。不支持的外部/自定义引擎明确标记,不用 invocation Span 起点替代模型开始。未使用 VeADK HTTP 工厂的应用需要安装请求计时中间件或使用 VeADK Runner,才能建立请求时间戳。客户端渲染计时和 TTFT/TPOT 直方图上报属于独立能力。
Lines changed: 85 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,85 @@
1+
# Stabilize PR #1190 CI tests
2+
3+
[中文版](2026-10-28-stabilize-concurrent-tests.zh.md)
4+
5+
Change ID: `pr1190-ci`; created/revised: 2026-10-28; status: approved.
6+
Comparison base: feature commit `7527a832`; upstream `23014771`.
7+
Related design: [first-token timestamps](../../features/first-token-timestamps/2026-10-28-first-token-timestamps.md).
8+
9+
## Evidence and scope
10+
11+
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.
12+
13+
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.
14+
15+
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.
16+
17+
## Requirements and design
18+
19+
- 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.
20+
- FR-2: Explicitly exercise both inspection orders using a bounded thread Event; compare exact call multiplicities without requiring a production order.
21+
- FR-3: Poll the returned state within a bounded deadline instead of treating entry into the inspection stub as cache publication.
22+
- FR-4: The fake Sidecar child receives exact discovery endpoints in an explicitly isolated environment, even if the parent has model/MCP upstream variables.
23+
24+
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.
25+
26+
## Tasks and acceptance
27+
28+
| Requirement | Task | Acceptance | Evidence |
29+
| --- | --- | --- | --- |
30+
| 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 |
31+
| FR-3 | T-2: wait for both published response states | AC-2: exact existing model-state assertions pass | Same parameterized TestClient test |
32+
| 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 |
33+
| 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 |
34+
35+
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.
36+
37+
## Review and authorization
38+
39+
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.
40+
41+
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.
42+
43+
## Verification record
44+
45+
2026-10-28, `7527a832` plus this test-only diff, Python 3.12.13:
46+
47+
- Original ordered assertion with controlled schedules: 1 passed, 1 failed; reverse order reproduces the exact CI failure.
48+
- 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.
49+
- After corrections: 3 targeted cases passed (two schedules and child environment).
50+
- 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.
51+
- All-files pre-commit passed after formatting; bilingual identifiers, literal commands, relative links and whitespace checks passed.
52+
- 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.
53+
- 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.
54+
55+
56+
### Gate status
57+
58+
| Gate | Status | Evidence |
59+
| --- | --- | --- |
60+
| Change Basis | PASS | Complete test/design diff against `7527a832`; upstream `23014771` unchanged; no unrelated work. |
61+
| Contract | PASS | Exact tool multiplicities, published states and child discovery endpoints; production contracts unchanged. |
62+
| Impact | PASS | R-CI-1/2 cover the affected test oracles and environment boundary. |
63+
| Portfolio | PASS | Two controlled thread schedules, TestClient state publication, real fake-runtime/child processes. |
64+
| Baseline | PASS | Reverse-order assertion and parent-upstream injection both observed RED before correction. |
65+
| Execution | PASS | Targeted 3 cases; all 189 affected cases; full default regression; all-files pre-commit. |
66+
| Evaluation | PASS | Original state/URL assertions retained; duplicate calls still fail; source hashes and 208/208 production coverage unchanged. |
67+
| Handoff | PASS | Bilingual design/evidence reconciled; final published CI evidence is linked from PR #1190. |
68+
69+
### Change Impact
70+
71+
| Change ID | Changed contract | Affected surface | Repository evidence | Failure mode | Risk |
72+
| --- | --- | --- | --- | --- | --- |
73+
| 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 |
74+
| 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 |
75+
76+
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.
77+
78+
### Test Portfolio
79+
80+
| Risk ID | Boundary | Method | Cases | Oracle | Evidence | Status |
81+
| --- | --- | --- | --- | --- | --- | --- |
82+
| 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 |
83+
| 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 |
84+
85+
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.

0 commit comments

Comments
 (0)