Skip to content

feat(bash): 在终端标题栏展示最近一次 LLM call 输出速度 (tok/s) - #87

Merged
lloydzhou merged 10 commits into
mainfrom
feature/last-call-speed
Sep 10, 2026
Merged

feat(bash): 在终端标题栏展示最近一次 LLM call 输出速度 (tok/s)#87
lloydzhou merged 10 commits into
mainfrom
feature/last-call-speed

Conversation

@lloydzhou

Copy link
Copy Markdown
Owner

变更

  • 在 transport 层(claude_sse.awk)记录 LLM 响应的开始/结束毫秒时间戳。
  • USAGE 事件追加 start_ms / end_ms 字段,速度计算下沉到 transport 层之后由上层一次性完成。
  • stats.json 新增 last_call_speed_tok_per_sec 字段。
  • term_title.awk 标题栏增加 S:<speed>tok/s 展示。
  • 删除不再使用的 util_date_ms
  • 更新 tests/test.sh async bash 标题栏 golden。

测试

make test-bash:221 passed / 0 failed。

- claude_sse.awk 在 transport 层记录 start_ms/end_ms
- USAGE 事件下沉时间字段,上层用 output_tokens/duration 计算速度
- stats.json 新增 last_call_speed_tok_per_sec
- term_title.awk 标题栏增加 S:<speed>tok/s
- 删除未使用的 util_date_ms
- 更新 tests/test.sh async bash 标题栏 golden

Tested: make test-bash (221 passed)
@lloydzhou

Copy link
Copy Markdown
Owner Author

代码 review 意见

总体评价

实现简洁,把耗时记录下沉到 transport 层是对的;测试已全绿(221/0)。

逐文件检查

src/awk/claude_sse.awk

  • date_ms() 跨平台策略合理:perl → GNU date → systime()*1000
  • ⚠️ 潜在 bug:macOS fallback。macOS 的 BSD date 不支持 %Ndate +%s%3N 会输出类似 17890393423N 的字符串;awk ms+0 会把它转成 17890393423,比真实毫秒时间戳少两位,导致速度算错约 100 倍。虽然 macOS 通常有 perl,不会走到这步,但 fallback 应该更健壮。
    • 建议:加一层 python3 -c 'import time; print(int(time.time()*1000))' fallback,或在 fallback 后校验 ms 是否为纯数字。
  • start_msBEGIN 中设置,比第一个 SSE 事件到达略早一点(awk 启动 vs curl 首字节),误差在毫秒级,可接受。
  • 流式重试时 start_ms 不会重置,速度会被重试时间摊薄,这是合理的用户感知口径。

src/agent.sh

  • USAGE 分支计算速度逻辑正确,有 _dur>0 除零保护。
  • current_context_tokens 更新时机从循环末尾提前到 USAGE 事件时,不影响语义(token 数已确定),且下一轮 compact 能更早拿到正确值。
  • util_date_ms 已删除且无残留引用,干净。
  • 速度是整数除法(tok/s),对标题栏展示足够。

src/awk/stats.awk

  • 新字段 last_call_speed_tok_per_sec 顺序放在 sub_agent_request_count 之后、last_updated 之前,合理。

src/awk/term_title.awk

  • jnum() 取不到 key 时返回 0,所以旧 stats.json 或初始状态会显示 S:0tok/s,graceful。

tests/test.sh

  • async bash 标题栏 golden 已更新为包含 S:...tok/s,覆盖了新格式。

建议修复

唯一需要修的是 date_ms() 的 macOS fallback。可以改成:

function date_ms(    cmd, ms) {
    cmd = "perl -MTime::HiRes=time -e \047printf \042%d\\n\042, time * 1000\047"
    if ((cmd | getline ms) > 0 && ms ~ /^[0-9]+$/) { close(cmd); return ms + 0 }
    close(cmd)
    cmd = "python3 -c \047import time; print(int(time.time()*1000))\047"
    if ((cmd | getline ms) > 0 && ms ~ /^[0-9]+$/) { close(cmd); return ms + 0 }
    close(cmd)
    cmd = "date +%s%3N"
    if ((cmd | getline ms) > 0 && ms ~ /^[0-9]+$/) { close(cmd); return ms + 0 }
    close(cmd)
    return systime() * 1000
}

版本一致性说明

本次改动只涉及 Bash 版本的 stats/标题栏,不影响 system prompt、tools.json 或请求体,因此按当前 PR 范围不需要同步 Go/Rust/C。如果后续决定所有 runtime 都要展示这个速度,再单独提 PR 对齐。

- transport 层记录 SSE 流 start/end 毫秒时间戳(读流开始→流结束,不含建连/TTFB)
- agent 层 speed = output_tokens / duration_ms * 1000,duration>0 除零守卫
- stats.json 写入 last_call_speed_tok_per_sec,终端标题栏展示 S:xx tok/s
- compact/sub_agent 的 usage 不更新 speed,口径与 bash 版一致
- tests/test.sh Test 40 增加 speed 字段检查
- 三版本 e2e 均 222 passed
原 date_ms 三级 fallback 在 macOS 上两级是坏的:
- date +%s%3N: BSD date 不认 %N,返回垃圾值
- systime(): macOS bwk awk 无此函数,直接崩溃
- 实际全靠系统 perl 兜底

新方案:
- curl -w 在 SSE 流末尾追加标准 event:timing 块(time_total/time_starttransfer)
- 块沿现有管道自然流转,openai/responses 转换层各加 2 行透传规则
- claude_sse.awk END 里直接算:speed = out / (total - ttfb)
  口径对齐 Go/Rust/C:读流开始→流结束,排除建连/TLS/TTFB
- USAGE 第 5 字段携带算好的 speed,bash 侧零计算
- --retry 时 -w 只在最终成功传输输出一次,speed 不含重试等待
- 零 fallback、零外部进程、零新依赖、毫秒精度
@lloydzhou

Copy link
Copy Markdown
Owner Author

Follow-up: Bash 版 speed 计时重构(f3ff4a8)

问题:date_ms() 三级 fallback 在 macOS 上两级是坏的

实测(macOS /usr/bin/awk 为 bwk awk 20200816):

分支 macOS 实际行为
perl -MTime::HiRes ✅ 正常(当前实际走的路径)
date +%s%3N ❌ BSD date 不认 %N,输出垃圾值 "17890412273N"(秒×10+3)
systime() ❌ gawk 扩展,bwk awk 无此函数,calling undefined function 直接崩溃

即 fallback 能工作全靠系统自带 perl,且 --retry 等待时间被计入 duration。

新方案:curl -w 构造标准 SSE timing 块

curl -w '\nevent: timing\ndata: {"time_total":%{time_total},"time_starttransfer":%{time_starttransfer}}\n\n'
  • -w 在 SSE 流末尾追加标准 event: timing 块,沿现有管道自然流转:
    http_stream.awk(body 全量穿透,零改动)→ sse_convert(openai/responses 各加 2 行透传规则)→ claude_sse.awk
  • claude_sse.awk 新增 event == "timing" 分支捕获,END 里 awk 浮点直接算好:
    speed = output_tokens / (time_total - time_starttransfer)
  • USAGE 第 5 字段携带算好的 speed,bash 侧零计算
  • 口径对齐 Go/Rust/C:读流开始→流结束,排除建连/TLS/TTFB(Go 的 startMsbufio.NewScanner(resp.Body) 前,Rust 在 read_sse 前,语义等价于 total - ttfb
  • 实测确认 --retry-w 只在最终成功传输输出一次:speed 不含失败重试的等待时间
  • 零 fallback、零外部进程、零新依赖(-w 是 curl 远古特性)、毫秒精度

gen > 0 守卫仅为除零防御(响应极小时 total == ttfb),与原版 _dur > 0 一脉相承。

测试

  • awk 单元验证:Claude 路径 50/(10-3)=7 ✓、OpenAI 全管道透传 ✓、gen=0 → speed=0
  • 真实 curl 输出格式验证(\n 转义 → 标准 SSE 块)✓
  • make test-bash: 222 passed, 0 failed(与 Go/Rust/C e2e 测试数一致)

跨 provider review 发现的口径差异(bash 在 message_stop/[DONE]/
response.completed 才发 USAGE,失败终态/中断不发 → speed 保留旧值):

- Go responses 失败终态(response.failed/incomplete/error)也发
  USAGE → speed 被部分输出的偏低值覆盖;Rust 同路径同问题;
  C 中断场景(收到 message_start 的 in 但未到 message_stop)
  流中 USAGE 使守卫通过 → 写 speed=0
- 修复:三版本统一"正常终结"标志
  - Go: Usage.Stopped(message_stop/[DONE]/completed=true,
    failed=false),store.RecordUsage 仅 Stopped 时写 speed
  - Rust: UsageEvent.stopped(同上四处置值),agent 仅
    last_stopped 时写 speed
  - C: accum->stopped(SSE_STOP 置位)守卫 speed 写入

C 版计时口径修复(对齐 bash 传输时间):
- 原 start_ms 在 curl_easy_perform 前打点,含 DNS/TCP/TLS/TTFB
- 改为 perform 成功后 curl_easy_getinfo 查
  CURLINFO_TOTAL_TIME_T / CURLINFO_STARTTRANSFER_TIME_T,
  与 bash 的 curl -w 同一套计时器(time_total - time_starttransfer,
  仅传输时间);补发最终 USAGE 覆盖流中 now_ms 口径时间戳
  (token 字段为 0,>0 守卫不重复累加)

C 版 speed 恒 0 的根因修复:
- agent 层 stream_display_callback 的 SSE_USAGE case 漏记
  start_ms/end_ms(transport 层另一份 accumulator 有记,agent
  层读自己这份)→ dur 恒 0

亚毫秒截断(三版本):整数 ms dur 截断为 0 → speed=0 偶发;
传输真实发生时向上取整至少 1ms(对齐 bash awk 浮点行为)

tests/test.sh Test 40 补 S5 断言 speed > 0(原只查字段存在,
C 版恒 0 未被发现的盲区)

四版本 e2e 各 223 passed
@lloydzhou

Copy link
Copy Markdown
Owner Author

Code Review: last-call speed (tok/s) 全链路

口径矩阵(已验证一致)

speed 分母统一为「传输时间」=流式 body 传输全程,排除 DNS/TCP/TLS/TTFB:

版本 计时来源 精度
bash curl -w time_total - time_starttransfer awk 浮点(微秒)
C curl_easy_getinfo(TOTAL/STARTTRANSFER_TIME_T)(与 -w 同一套计时器) 整数 ms(向上取整)
Go/Rust 响应头已读、body 首读前打点 → 流结束 整数 ms(向上取整)
  • 失败终态(response.failed/incomplete/error)与中断:四版本均不更新 speedStopped 标志 / stopped 守卫 / bash 侧 USAGE 只在正常终结时发出)
  • 亚毫秒传输:dur 向上取整至少 1ms,对齐 bash awk 浮点行为(否则整数截断偶发 speed=0)
  • --retry:curl 内部重试只算最终成功传输(-wCURLINFO_*_TIME_T 语义一致;Go/Rust 每次请求重新打点)

Review 中发现并已修复的问题

  1. C speed 恒 0stream_display_callback 的 SSE_USAGE 漏记 start/end(transport 层另一份 accumulator 有记,agent 层读自己这份)→ dur=0
  2. C 口径偏宽:原在 curl_easy_perform 前打点,含建连+TLS+TTFB,真实网络 speed 系统性偏低
  3. Go/Rust failed 终态覆盖 speed:responses 失败终态也发 USAGE,部分输出的偏低值覆盖旧 speed
  4. 测试盲区:Test 40 原只断言字段存在不断言值(C 恒 0 未被发现)→ 已补 S5 断言 speed > 0

遗留差异(token 记账层面,建议 follow-up,不影响 speed)

USAGE 发出时机架构不同(bash=解析器 END 汇总一次;Go/Rust/C=流中逐事件)导致:

  • 中断场景:C 在 message_start 即发 USAGE(in/cache)→ 中断时 in>0 守卫通过,stats 累加部分 token;bash 中断无 USAGE,不累加
  • Go failed 终态RecordUsage 无条件累加 token(累加在 Stopped 判断之前)→ 部分输出计入总量;bash 不计入

两者均为统计口径的轻微偏差,如需严格对齐需把 token 累加也纳入「正常终结」守卫,或把 port 版 USAGE 改为终结时汇总发出。

测试基建发现

mock server 的 responses 分支挂在 /responses,而 agent 拼接 base-url + /responses——--base-url http://x/v1 会请求 /v1/responses 得 404(四版本 speed 均 0)。真实 API 不受影响(端点本就带 /v1 或不带),但建议 mock 补 /v1/responses 路由或测试统一用不带 v1 的 base-url。

验证

  • 四版本 e2e 各 223 passed, 0 failed(含新增 S5 断言)
  • 三 provider(claude/openai/responses)× 四版本 speed 横向验证通过
  • 旧 session(stats.json 无 speed 字段)兼容性实测:四版本均正确补字段、旧值保留累加

debian:11 (bullseye) 的 bullseye-security InRelease 元数据过期
(invalid since 2d),导致所有 Debian 11 container 构建 job 的
apt-get update 退出 100。加 -o Acquire::Check-Valid-Until=false
跳过检查(与代码改动无关的 CI 基建问题)
bullseye LTS 已于 2026-08-31 结束,deb.debian.org 上的
bullseye-security 旧版包已清理(install 阶段 404)。
sed 替换占位行改为指向 archive.debian.org(EOL 官方归档,
包永久可用),配合已有的 Check-Valid-Until=false
bullseye 已于 2026-08-31 结束 LTS,镜像进入元数据过期+pool 清理
的半死状态。切换 bookworm(支持至 2026+6/2028 LTS)。

⚠️ 兼容性变化:Linux 构建产物 glibc 下限从 2.31 升至 2.36,
不再支持 Ubuntu 22.04 (2.35) 及更早;Ubuntu 24.04+/Debian 12+ 不受影响。

同时清理 bullseye EOL 的临时 workaround(archive/snapshot sed
替换与 Check-Valid-Until=false,debian:12 活仓库无需)
替代 debian:11(bullseye 已 EOL,镜像进入元数据过期+pool 清理
半死状态)和 debian:12(glibc 2.36 会放弃 Ubuntu 22.04 等系统,
违背 v4.3.1 的 2.31 基线承诺)。

ubuntu:20.04 (focal) glibc 同为 2.31:
- 门禁 GLIBC_MIN=2.31 / deb 声明 libc6 (>= 2.31) / README 承诺全部不变
- focal 仍在 archive.ubuntu.com 正常服务(主仓/security 均 200),
  且 Ubuntu Release 无 Valid-Until 字段,不存在 Debian 的过期检查问题
- 产物兼容性完全等价:Debian 11/12/13、Ubuntu 20.04/22.04/24.04+
@lloydzhou

Copy link
Copy Markdown
Owner Author

审查结论:暂不建议合并

审查范围:e27cb91 → a17de1c。发现两项需要修正的行为问题。

1. 中:Go 与其他版本的计时终点不一致

位置:go/transport.go:293–305,尤其第 304 行。

Go 在收到协议结束事件时记录结束时间;Bash、C、Rust 的 Claude 路径则等待响应流结束。结束事件与连接关闭之间存在延迟时,同一响应会得到明显不同的速度。

已使用本地模拟服务串行实测:输出 100 个词元,约 0.25 秒后发送结束事件,再等待 2 秒关闭连接。四版本均成功退出,用量一致,持久化速度分别为:

版本 速度(词元/秒)
Bash 44
Go 392
C 44
Rust 44

这不是舍入误差,违反四版本行为一致性的要求。建议统一计时边界;若改用协议结束事件,也需要同步其他版本,并补充可控时延的数值断言。

2. 中:C 中断时可能覆盖上次成功调用的速度

位置:c/agent.c:1034–1040

新增写入逻辑仅检查 accum->stopped,但该标记不代表正常完成:

  • c/transport.c:676–678:取消时发送中断停止事件,并返回成功状态码。
  • c/agent.c:150–154:任何停止事件都会设置 stopped
  • 因此,中断能够绕过错误退出分支,并进入新增速度写入逻辑。

例如,Claude 已返回输入用量、尚未返回输出用量时中断,可能将旧速度覆盖为零,而不是保留上次成功值。

此项为代码路径确认,尚未实际执行交互中断复现。建议明确区分正常完成和中断,再决定是否更新速度,并补充“成功后失败/中断保留旧值”的回归测试。

测试与构建说明

  • 新增速度测试只检查正数,无法发现上述计时差异或中断覆盖;断言位于 tests/test.sh:2541–2555,Go、Rust 当前持续集成任务并不执行该脚本。
  • 未发现从 Debian 11 切换 Ubuntu 20.04 新增明确的门禁绕过。原有 GLIBC 2.31 符号上限检查仍有效,发布任务依赖该检查。但符号检查不能证明最低支持系统上的启动及动态依赖兼容性;本次未在 Ubuntu 20.04 中实际安装、运行发布包。这属于既有验证缺口,不单独作为本次阻塞项。

已完成的验证及边界

  • 持续集成:38 项成功、2 项跳过。
  • 四版本构建命令成功,其中 C 显示无需重建;Go 单元测试通过。
  • 四版本串行定向计时复现完成;差异格式检查通过。
  • 四份工具定义哈希一致;本次差异未修改提示词或请求构建逻辑。
  • 未运行全量端到端测试,也未完成三种协议、旧会话和全部失败路径验证。
  • 全程未修改源码、未提交、未合并。

建议修复上述两项行为问题、补齐对应回归测试后再合并。

@lloydzhou
lloydzhou merged commit 2618ab5 into main Sep 10, 2026
36 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant