iT邦幫忙

2026 iThome 鐵人賽

DAY 18
0
AI Engineering

Harness Engineering × Pi Agent 實戰:打造可觀測、可評估的 AI Coding Agent系列 第 18 篇

Day18:Agent 為什麼跑這麼久?Session 時間戳看不見的執行開銷

  • 分享至 

  • xImage
  •  

第一輪實驗結束了,但有些問題答不出來

Day 9 到 Day 17,量測台跑了 100 多次執行,回答了五個問題:AGENTS.md 值多少、Skills 值多少、搜尋工具值多少、規則放哪裡有沒有差、thinking 調高調低差多少。

這些答案都建立在同一批數字上:成功率、成本、tokens、工具呼叫次數、耗時。全部從 session 記錄算出來。

但 Day 17 有一個數字我一直沒辦法解釋:thinking high 的 T2 任務耗時 115 秒,是 off 那組 53 秒的兩倍多。那多出來的 62 秒,到底花在哪裡?

今天就來回答這個問題——順便說明為什麼土炮的量測方式到這裡就到頂了。

先把時間軸榨乾

session 記錄裡每一則訊息都有時間戳。assistant 訊息的時間戳減掉前一則訊息的時間戳,大致就是「等模型回應」的時間;toolResult 減掉 assistant,大致就是「跑工具」的時間。

拿一次 T5 資料遷移(thinking high)的執行來算:

一次執行的時間都花在哪

結果非常一面倒:

項目 時間 佔比
等模型回應 63.4 秒 97.5%
跑工具 1.5 秒 2.3%

這個 agent 幾乎整個生命都在等模型講話。 32 次工具呼叫——讀檔、跑 pytest、跑 check.py——全部加起來只有一秒半。

這個發現本身就值得記住:優化 coding agent 的執行速度,跟你的工具寫得多快幾乎無關。 唯一有意義的槓桿是「少跑幾輪」和「每輪少送一點 context」,這正好呼應 Day 14 的成本結構(六成的錢花在輸入)。

然後就撞牆了

上面那張圖看起來很有用,但它其實是猜的。四個問題它答不了:

一、那 63 秒裡面發生了什麼?
第 5 輪等了 11.3 秒,是第 7 輪的 4.5 倍。為什麼?是 prompt 太長、模型想比較久、串流中途卡住、還是排隊等資源?記錄裡只有一個時間戳,沒有「送出請求」「收到第一個 chunk」「收到最後一個 chunk」的分界。

二、平行呼叫的工具,各自花多久?
圖上有四輪標了「N 個工具同時跑」,其中一輪同時呼叫 8 個。這 8 個工具的耗時被壓成一個數字,分不開。如果其中一個特別慢,我看不出來。

三、工具的開始時間根本沒有被記錄。
我是拿「上一則訊息的時間戳」當工具的起點——但那其實是模型輸出結束的時間。模型輸出到工具開始執行之間的空檔(參數解析、權限檢查、排程)全被算進「跑工具」。所以那 1.5 秒是高估的。

四、session 之外的時間完全看不到。
runner 量到這次執行 68.4 秒,session 記錄推算出來是 65.0 秒。中間有 3.4 秒不知去向——Pi 啟動、載入設定與 extension、寫檔收尾。佔了 5%,而且完全在記錄之外。

這不是多加幾個欄位就能解決的

你可能會想:那就在 session 記錄裡多寫幾個時間戳?

問題是要加的不是欄位,是結構。我要回答的問題長這樣:

一次 turn
├─ 一次模型請求
│  ├─ 送出請求(多大?)
│  ├─ 等第一個 chunk(多久?)
│  └─ 串流完成(中途重試過嗎?)
└─ 8 個工具
   ├─ read a.py     ← 各自多久?
   ├─ read b.py
   └─ ...

這就是 span:每個操作有開始時間、結束時間、父子關係、以及自己的屬性。一堆平鋪的時間戳拼不出這棵樹;就算拼得出來,每加一種新操作就要改一次解析程式。

這正是 trace 這個東西存在的理由。它不是「更花俏的 log」,它是為了回答「時間花在哪一層」而設計的資料結構。

好消息:Pi 早就內建了

我原本以為要自己在 Pi 外面量。翻原始碼才發現,Pi 已經把 span 寫好了——而且是一套設計得很乾淨的體系:

pi.harness.run             一次執行
├─ pi.harness.turn         一輪(一則回應 + 它那批工具)
│  ├─ pi.harness.step      一次「可重試的嘗試」
│  │  ├─ pi.ai.request     模型請求(provider、model、usage、time_to_first_chunk_ms)
│  │  └─ pi.harness.sleep  重試前的等待
│  └─ pi.harness.tool      每一個工具呼叫,各自一條
└─ pi.harness.checkpoint

上面那四個答不出來的問題,這套 span 全部都能回答。

但是——這就是明天的主題——Pi 的 CLI 和高階 SDK 都沒有把這個開關接出來。pi -p 跑一百次,一個 span 都拿不到。要拿到它,得自己動手。

明天

Day19 拆這套 span 契約:Pi 用什麼結構描述自己的執行、每個 span 帶哪些屬性,以及為什麼它刻意不綁定任何一家 telemetry 廠商。Day20 再動手把它接到 OpenTelemetry,讓上面那四個問題真的有答案。


上一篇
Day17:Thinking 越低越省嗎?Off/Low/High 實驗揭露反直覺成本曲線
下一篇
Day19:Pi 的 Trace 契約已經完整,為什麼執行時卻沒有 Span?
系列文
Harness Engineering × Pi Agent 實戰:打造可觀測、可評估的 AI Coding Agent 共 19 篇
圖片
  熱門推薦
圖片
{{ item.channelVendor }} | {{ item.webinarstarted }} |
{{ formatDate(item.duration) }}
直播中

尚未有邦友留言

立即登入留言