iT邦幫忙

2026 iThome 鐵人賽

DAY 27
0
AI Engineering

Backend 工程師的 Azure GenAI 實戰系列 第 27

Day 27:用 Application Insights 追一次 LLM request:缺的自己補,多的自己關

  • 分享至 

  • xImage
  •  

configure_azure_monitor() 的官方宣傳是一行搞定:裝上套件、呼叫一次,request 與 dependency 就出現在 Application Insights。對這個 backend,一行之後的實況是:Day 27 想追的五件事——request trace、dependency call、correlation id、model latency、streaming trace——只有第一件直接可用,而且連它都會在一個具體條件下無聲消失;其餘四件的缺口形狀各不相同,不全是空白

這一篇把那四格的缺口逐格補上,也把它多給的逐項關掉;讀完你會知道一行設定的邊界在哪裡,以及 Day 8 開始在每行 log 累積的 correlation id,怎麼在 trace 的世界裡繼續當權威。

一行之後的實際狀態

先把地圖攤開。對照這棵樹(azure-monitor-opentelemetry 1.8.9,2026-08 釘版),一行 configure_azure_monitor() 之後:

想追的東西 一行之後的狀態
request trace 有——但寫錯位置會無聲消失,見下節
dependency call 空白。distro 綁的 instrumentation 清單沒有 httpx,而這棵樹自己建的六個 client 全走 httpx(Azure SDK 內部流量是例外,見後文的 token-fetch span)
correlation id operation_Id,但那不是這個 API 從 Day 5 用到現在的 id
model latency 只有 HTTP 層——而且那個數字不是它看起來的意思
streaming trace server span 已粗涵蓋整條 stream;缺的是語意層生命週期與終端所有權,且所有權模型與 Day 22 audit 不同構,假設同構會推錯

distro 支援的 instrumentation 是八個:azure_sdkdjangofastapiflaskpsycopg2requestsurlliburllib3azure/monitor/opentelemetry/_constants.py:74-85)。沒有 httpx,也沒有任何 OpenAI SDK 的東西。

社群那套 opentelemetry-instrumentation-openai-v2 也補不上——Responses API 的 instrumentation 在那邊還是 open issue(#3436),而 Day 5 把整個系列釘在 Responses API 上。

所以每條 trace 的 dependency 半邊,得自己蓋。

Request trace:免費的那格會無聲消失

distro 的自動 FastAPI instrumentation 原理是把 fastapi 模組命名空間裡的 FastAPI 換成 instrumented 子類。問題是這棵樹的 main.py 在 import 時就把原本的類別綁進模組全域,create_app() 用的是那個舊參照——自動 instrumentation 換掉的是命名空間裡的名字,換不到已經綁走的參照。

症狀不是錯誤訊息,是從頭到尾一個 server span 都沒有,而且無聲無息。這種「正確性取決於 import 順序」的東西不該留著賭,所以這裡明確關掉自動路徑、改對 app 實例動手:

configure_azure_monitor(
    instrumentation_options={"fastapi": {"enabled": False}},
    ...
)
FastAPIInstrumentor.instrument_app(
    app,
    exclude_spans=["receive", "send"],
    excluded_urls=r"^https?://[^/]+/health$",
)

呼叫位置是 create_app()——這棵樹從 Day 2 起所有 fake/real 切換都收在單一組裝點,telemetry 沒有理由例外。

實際入口是 core/telemetry.pyconfigure_telemetry(settings):連線字串沒設就整條 no-op——不裝 provider、不 patch 任何 client,CI 與本機開發不需要任何 Azure 資源。

函式做成可重入,因為 entrypoint 有兩個——app 之外,tools/index_corpus.py 這支 CLI 也自己呼叫一次,一次灌 corpus 是這系列最貴的 embedding 支出,正是想看 dependency span 的場合。

excluded_urls 那個 regex 是錨定的,因為它的比對方式是對完整 URLre.searchopentelemetry/util/http/__init__.py:74-83)——寫一個裸的 health,會連 /api/v1/healthz、query string 提到 health 的請求一起吞掉。

排除 /health 的理由是流量結構:Container Apps 對它跑三個 probe——startup 只在啟動期(每 3 秒),穩態是 liveness 與 readiness 各每 10 秒、合計每 10 秒兩筆。這個排除在真環境驗過而且不是空泛的「零筆」(japaneast,2026-08-21):容器自己的 access log 最近 200 行有 181 行是 GET /health,同一時段 AppRequests 裡 probe 0 筆——排除是在 OTel 那層生效的,不是因為沒人打它。

/ 則刻意排除。同一個 34 分鐘的窗裡,/ 收到 3 筆不是我發出的請求(ingress 是 external,掃描流量打得到)。分界是「流量由誰產生」:probe 是你自己設定的、已知答案的高頻流量(穩態下 liveness+readiness 每分鐘 12 筆,app 活著就不停);打到 / 的是外部流量,看得見它正是 observability 存在的目的。附帶一個限制:exporter 預設把 ClientIP 歸零成 0.0.0.0,所以 telemetry 答不出「誰打的」。

Dependency call:清單裡沒有 httpx

這棵樹自己建的 client 對上游的呼叫——Azure OpenAI(openai SDK 底層)、AI Search 查詢面與索引面、JWKS 抓取、embeddings、agent framework——全部走 httpx,而 httpx 不在 distro 的清單上。全樹掃出來是六個 client 建構點,分散在六個檔案;只補其中一個,比如只補 Search 索引面,/rag 的 Search 查詢照樣沒有 span——查詢面與索引面是兩個不同的 client。

做法是在組裝點逐 client 注入,不做全域 patch:

def instrumented_httpx_client(**kwargs: Any) -> httpx.AsyncClient:
    client = httpx.AsyncClient(**kwargs)
    if _installed:
        HTTPXClientInstrumentor.instrument_client(client)
    return client

兩個理由。第一,「哪些 client 被追蹤」變成讀組裝點就能回答的問題;第二,全域 patch 疊在 per-client instrumentation 上的行為沒有任何地方規範過,不賭。

補完 transport 層還不夠——httpx span 只知道 HTTP,不知道「這是一次模型呼叫」。語意層自己發:/chat/ragchat {deployment} span 由組裝點的 decorator(TracingChatService)包上去,/rag 另有 rag.retrievalrag.assemble_contextrag.generation 三個 stage span,接的是 Day 14 就在發的 stage latency log,不是新機器。

補完之後,一次 /rag 在樹上長這樣:

Day 27 的 /rag span 樹:最上層是 POST /api/v1/rag 的 SERVER span,掛 correlation_id;底下三個 INTERNAL stage——rag.retrieval 裡有 embeddings {deployment}(掛 gen_ai.request.model)與 azure.search.query(掛 azgenai.search.hit_count),各自往下接一個 httpx 的 POST span,標注「只是傳輸層」;rag.assemble_context 沒有上游呼叫;rag.generation 裡是 chat {deployment}(掛 gen_ai.usage 與 azgenai.outcome),往下接 POST /openai/v1/responses 的 httpx span,標注「回到 header 就結束,不是生成時間」。另有一條虛線:retrieval 的 hits 為零時整個 generation stage 不存在——Day 14 的結構性 no-answer

注意最後那條虛線:fake index 為空時 /rag 走 Day 14 的結構性 no-answer,樹上沒有 generation stage——span 樹忠實反映「零 hits 就不呼叫 LLM」這條兩個月前的裁決。這正是 trace 好用的地方——架構裁決變成看得見的形狀。

「關掉 auto instrumentation」是錯的說法

上面那行 instrumentation_options={"fastapi": {"enabled": False}},我在文件裡一度描述成「關掉了自動 instrumentation」。部署到 Container Apps 之後,trace 裡多出一個沒人寫的 span,把這句話拆穿了:

GET /msi/token        CLIENT    target: localhost:12356

那是 managed identity 取 token 的呼叫。它不是我們注入的六個 client 發的(azure-identity 不在那六個裡面)。來源是 distro 的 azure_sdk instrumentation:那個選項只關掉你指名的那一個,其餘七個照舊。三個沒安裝所以是空操作,但 azure_sdk 有裝,而且只在部署後才看得到——本機沒有 identity endpoint,這個 span 結構上長不出來。

它值得記的原因是成本形狀:冷取 2.68 秒,之後有 token cache 只要 6–8 毫秒(japaneast,2026-08-21 實測)。冷啟動後第一個剛好觸發它的請求,會平白掛上一段跟模型完全無關的多秒延遲——不知道這個 span 存在的人,會對著自己的程式碼找那兩秒半。

Correlation id:operation_Id 不是你的 id

Application Insights 有自己的識別體系:operation_Id,也就是 W3C trace id,同一棵樹上所有 span 共用。很自然的想法是「那就用它當 correlation id」——但這個 API 從 Day 5 起的對外契約是 X-Correlation-Id:進來、回去、error envelope 裡都是它,Day 8 起每行 log 也是它。契約不跟著 telemetry 搬家。

所以裁決是:correlation_id 維持權威,trace id 只是傳輸層附掛。它掛在 server span 與每一個我們自己寫的 span 上;instrumentation 產的 span(httpx 的、framework 的)不掛,靠樹狀關聯。查詢一律先用 correlation_id 找到 root,再撈整棵樹:

AppRequests
| where TimeGenerated > ago(1h)
| where tostring(Properties['correlation_id']) == 'your-id-here'
| project OperationId

拿到 OperationId 之後對 AppDependencies 查同值,整棵樹就出來了。

correlation id 現在會被複製進第二個保存區,所以有一件事升級了:入站 X-Correlation-Id 從 Day 27 起先驗證再採用——恰好一個 header(重複出現即棄用)、1–128 bytes、ASCII 可見字元(VCHAR,0x21–0x7E)、不做任何正規化。不合格不拒絕請求(Day 5 錯誤契約一字不動),改用自生 UUID,代價寫進契約:回寫的 header 值可能與你送的不同。

一個部署後才拿到證據的性質:correlation middleware 跑在身份驗證之前。live session 裡兩筆被拒絕的請求——一筆 422、一筆 401——都帶著 correlation id 出現在 AppRequests(2026-08-21)。被拒絕的請求也追得到,這對查「為什麼一直 401」的人不是小事。

出站方向則刻意不帶 X-Correlation-Id:往 Azure OpenAI 與 AI Search 的請求只帶標準 traceparent(httpx instrumentation 自己注入)。我們的 id 是這個 backend 的對外契約,上游不認得它,多送只是把 caller 可控的文字再複製去一個地方。

Model latency:httpx span 量到的不是生成延遲

這是本篇最重要的一個數字關係。httpx instrumentation 的 span 包的是 handle_async_request()——這個呼叫在拿到 status code 與 response headers 時就返回,body 以 stream 形式在 span 區塊之外被消費(opentelemetry/instrumentation/httpx/__init__.py:989-1035,0.64b0)。也就是說:httpx span 在 headers 回來就結束了

對一般請求這只是誤差;對串流是量級錯誤。同一次 /chat/stream 呼叫(真 gpt-5-mini,japaneast,2026-08-21)的三個數字:

量測 量的是什麼
httpx span 1.067 s 送出請求 → response headers 回來
gen_ai.response.time_to_first_chunk 2.410 s → 第一個內容 chunk
chat chat-mini 語意 span 2.568 s 整段生成

一次 /chat/stream 的三個時間量(gpt-5-mini,japaneast,2026-08-21):時間軸上兩排長條,顏色不代表狀態——語意 span 那排是 chat chat-mini 整段生成,從 0 到 2.568 秒,第一個內容 chunk(TTFB)的菱形落在 2.410 秒;httpx span 那排的「送出請求到 response headers」只從 0 到 1.067 秒就結束,其後灰色一段是「headers 已回、chunk 未到」的 1.343 秒空窗。httpx 長條只涵蓋整段生成的四成——把它讀成模型延遲就是把這個請求低估一半以上

headers 在 1.07 秒回來,第一個 chunk 到 2.41 秒才出現:中間 1.343 秒嚴格說是「headers 已回、內容一個 byte 都還沒到」的空窗——該次回報 64 個 reasoning tokens,推理確實發生在裡面,但這段時間由模型推理、服務端排程、網路遞送各佔多少,這次量測沒有分解。量測證明得了的是:把 httpx span 當「模型跑了多久」,這個請求會被低估超過一半。

部署到 ACA 的第二次量測更極端:0.233 s 對 2.074 s,涵蓋率只剩 11%。兩次量測不是對照實驗(prompt 與 reasoning token 都不同),42% 到 11% 的差距不歸因於環境;能主張的只有方向——transport span 遠小於生成延遲,不能當生成延遲用

https://ithelp.ithome.com.tw/upload/images/20260827/20168288aMoPHJtzoE.png
忍喵11% 圈起來。dashboard 上那條漂亮的 dependency latency 曲線,量到的可能是你最不關心的那一段。

生成延遲的正確載體是語意 span 自己的 duration,串流另有一個一級屬性:gen_ai.response.time_to_first_chunk,semantic convention 定義的起算點是「client 送出生成請求」那一刻(opentelemetry/semconv/_incubating/attributes/gen_ai_attributes.py:271,單位秒)。

這個定義決定了實作:span 必須在 responses.create 之前開始,等 adapter 交回 stream 物件才起算會系統性低估。

鍵名從 semconv import 而不是抄字串——它住在 _incubating 底下,上游改名時要在 import 當場炸,不是安靜地送一個死鍵。

同一種 span,兩個生產者

/agent 不用我們發 span——agent framework 只要看到全域 tracer provider 就自己發 invoke_agentchatexecute_tool/chat/rag 走 openai SDK、不經過 framework,那兩條路的 chat span 只能我們自己發。於是這棵樹必然有兩個 chat span 生產者

兩者長得像是裁決不是巧合:span 名同為 chat {deployment}、共用 gen_ai.operation.namegen_ai.request.model,一個測試釘住這個交集,framework 升版改名會變紅,而不是樹默默裂成兩半。

但別在沒讀過的欄位上過濾——實測兩邊的 gen_ai.provider.name不一致:我們發的是 azure.ai.openai,framework 的 chatopenaiinvoke_agentmicrosoft.agent_framework

agent 那棵樹也值得一看(japaneast,2026-08-21,一次 run):invoke_agent 全長 6.8 秒,兩次模型呼叫 3.7 秒+3.1 秒,中間的 execute_tool 0 毫秒。這一輪的成本由兩次模型呼叫主導、工具趨近於零——與 Day 16/17 用 token 計數推出的方向一致。一次 trivial 本機工具的 run 當然定不了「工具永遠便宜」這種通則;它展示的是這個結構在 trace 上直接讀得出來,不用再推。

Streaming:一個 span,兩條路會來關它

串流的 span 沒辦法是 context manager:它在請求送出前開始,而 body iteration 發生在開它的函式返回之後。所以它由一個物件持有,aclose() 做成 idempotent——因為合法會走到它的路有兩條:終端事件路徑(知道 usage 與 status)與 exit path(只知道 stream 結束了),先到先寫,後到無害。

一個實測推翻設計的細節:第一版把 owner 寫成 async generator、清理放 finally。測試抓出從未被 iterate 的 generator,aclose() 不會執行 finally——沒有懸掛中的 frame 可以丟 GeneratorExit 進去。「建了 stream 但沒人消費」恰好是最需要關 span 的情境,generator 設計在那裡剛好洩漏。改成 async-iterator 類別才守得住。

還有一個容易推錯的對照:Day 22 的 streaming audit 是兩個互斥的 owner(pre-stream finalizer 與 post-transfer observer),span 是一個 owner 貫穿全程。兩者不同構——從 audit 的所有權模型推 span 的行為,或反過來,都會對「disconnect 時記了什麼」得出錯的答案。

server span 這層倒是簡單:ASGI instrumentation 在最後一個 body message(more_body 為 false)才關 server span(opentelemetry/instrumentation/asgi/__init__.py:1026-1033),所以它天生涵蓋整條 SSE。

多的自己關

前面是它沒給的;這節是它多給的。每一項都要明確動手關,沒有「預設就是關的」這回事。

Logs 與 metrics exporter 關掉。 log 的歸屬不變:stderr,然後交給 hosting pipeline——Container Apps 本來就把容器輸出收進 Log Analytics。不關的話同一批行被 ingest 兩次、計費兩次,而且 Day 22 那句「audit 只是寫 JSON 行到 process log stream」的誠實聲明就不再字字為真。

代價也照實講:在 App Insights 點進一個 span 看不到那個請求的 log,要自己跨到 Log Analytics 用 correlation_id join。

內容開關有兩個,各關各的。 framework 的 enable_sensitive_data 與 OTel 的 OTEL_INSTRUMENTATION_GENAI_CAPTURE_MESSAGE_CONTENT,任一開著,prompt 與回覆內容就會被複製進第二個保存區——那是資料治理決策,不是方便性設定。framework 那個必須程式化設 False:它的設定物件是 import 時建好的 singleton,事後設環境變數無效,而傳 None 會讓它重讀環境、把決定權交還給別人。

這三個環境鍵是用寫的,不是用留白的,而且藏著一個計費陷阱:distro 讀的是 os.environ,這個 repo 的設定走 pydantic-settings——寫在 .env 裡 distro 根本讀不到,log 與 metric 照送、沒有錯誤訊息、唯一的症狀是帳單。所以 configure_telemetry() 在呼叫 distro 之前把三個鍵寫進 os.environ,既有值衝突就啟動失敗(三個鍵全部驗完才寫任何一個,不留一半被改過的環境),不做靜默覆寫。

record_exception=False,每個自有 span 都是。 OTel 預設 True,會把例外的 message 原文寫進 span event——上游細節逐字繞過上面所有規則。分類走 span status 與兩個封閉值域的自有屬性:azgenai.outcomesuccessrejectederror)與 azgenai.error.code,後者直接讀 Day 22 已封閉的 error code 集合,不另抄一份。

sampling 明設 1.0。 distro 的預設不是全收,是 rate-limited sampler、每秒 5 條 trace。跟著文章做、單發一個請求卻在 portal 找不到的人,多半是被這個預設吃掉的。lab 開全收因為丟掉你正在找的那一個請求就沒戲了;真實流量下請調低。

關完之後,誠實記一個實物:「內容不進 telemetry」是靠屬性名稱強制的,值繞得過去。 兩個內容開關都關著,framework 的 execute_tool span 仍帶著 gen_ai.tool.description——工具函式的完整 docstring 原文。那個開關管 prompt、completion、tool arguments,不管工具的自我描述;而 forbidden-attribute-name 測試也放它過去,因為這個鍵名不含任何禁字。

這次的暴露很小(那是我們自己 repo 的 docstring),但對「工具描述寫著內部細節」的人不成立——這是先寫成推論、後來真的抓到實物的一條誠實邊界。

查 KQL 之前,先知道的兩件事

取證階段踩到兩個「回答看起來像答案」的坑,直接影響你信不信自己查出來的數字,各換來一條規則。

第一,兩個 CLI 查詢面用兩套表名。 az monitor app-insights query 走 classic Application Insights schema,表名是 requestsdependenciestracesaz monitor log-analytics query --workspace <GUID> 走 workspace schema,表名是 AppRequestsAppDependenciesAppTraces

把 workspace 表名丟給 classic 面,錯誤是一句沒有 inner error 的 BadArgumentError: The request had some invalid properties——完全看不出是表名的問題。

規則:KQL 取證一律走 log-analytics query 加 workspace GUID,一套 schema 用到底。

第二,-o tsv 會對某些查詢印出不是答案的數字。 同一句 requests | count-o tsv1-o json 裡的真值是 12(2026-08-21,azure-cli 對 app-insights 面實測)。那個 1 看起來完全像一個合理的計數——尤其當你在驗證「某東西應該是 0 筆或很少筆」的時候。規則:要當證據用的數字,用 json 讀,不用 tsv 讀。

https://ithelp.ithome.com.tw/upload/images/20260827/20168288PqJFwq6NaN.png
忍喵:最危險的不是報錯的查詢,是回一個合理數字的錯查詢。你的 runbook 裡有幾條在用 -o tsv

成本

Application Insights 這裡是 workspace-based,計費就是 Log Analytics ingestion。Azure Retail Prices API(japaneast、USD,查核 2026-08):

Meter 級距 價格
Analytics Logs Data Ingestion 0 GB 起 0.00 USD / GB
Analytics Logs Data Ingestion 5 GB 起 3.34 USD / GB
Analytics Logs Data Retention 0.15 USD / GB / 月

每月前 5 GB 免費直接體現在 meter 的級距定價裡;注意額度算在 billing account 上,不是 per workspace——多開一個 workspace 不會多一份 5 GB。

retention 那條 meter 也不是從第一天開始算。Application Insights 的資料(classic 或 workspace-based 皆同)含 90 天免費 retention(查核 2026-08,Azure Monitor 定價;一般 Analytics Logs 表是 31 天)。

0.15 USD/GB/月收的是超過免費窗之後的保留。關掉 logs、metrics、live metrics、performance counters 與排除 /health,同時也都是成本決定:穩態 probe 流量每 10 秒兩筆,是這個 app 原本最大的資料量來源。

依 Day 9 的口徑,並把範圍講準:最終計了多少帳的權威是 Cost Management + Billing,不是自己數的 span 數。帳單出來之前想看 ingestion 量,workspace 自己的 Usage 表與「Usage and estimated costs」才是工具——它們估算,帳單裁決。

這天的誠實邊界

  • 兩次串流量測不是對照實驗。 42% 與 11% 各自成立於自己那次請求(prompt 與 reasoning token 都不同),只主張「transport span 遠小於生成延遲」這個方向,不主張比例。
  • /rag/agent 的 Search 側是 fake 驅動。 azure.search.query 的 0 ms 只證明 span 有發,不代表真 Search 的延遲形狀。
  • invoke_agent 那棵子樹不是我們的。 framework 升版可以改名——有測試會抓,但那部分的樹形不在這個 codebase 的控制範圍內。
  • indexing 路徑只有 transport span。 tools/index_corpus.py 不經過 retriever 的呼叫點,有 httpx span、沒有語意 embeddings span。
  • content-free 靠屬性名稱強制gen_ai.tool.description 是已知繞過的實物(正文已記)。
  • auto 與 manual FastAPI instrumentation 同時開的行為未驗——shipped 組合永遠關著 auto,那個組合從沒跑過,測試證明的是 shipped 組合的唯一 server span。
  • 非 Azure 主機啟動時會印兩行 ERROR traceback(Azure VM resource detector 打 IMDS 逾時)。無害,但照著做的人會以為壞了——要找的是 Transmission succeeded 那行。

用到的 Azure 服務

  • Application Insights(workspace-based)+ Log Analytics workspace——本篇主角,用量遠低於 5 GB 免費級距,跑完即拆
  • Azure OpenAI in Microsoft Foundry(chat-mini,常駐)——live 量測的模型呼叫
  • Azure Container Apps + Container Registry + Key Vault + Microsoft Entra ID——端到端驗證用(連線字串走 Key Vault reference、managed identity 解析),跑完即拆

下一篇

Trace 讓你看見一次 request「跑了多久、經過哪裡、掛在哪」,但它答不了另一個問題:回答的品質有沒有退化。Day 28 進 evaluation——golden questions、regression dataset,以及自動評測的邊界在哪裡。


本文由作者規劃與撰寫,AI(Claude)協助草稿整理與程式碼驗證;技術內容與觀點由作者確認並負責。


上一篇
Day 26:CLI scripts first,Bicep later:轉換是兩個軸,不是一個開關
下一篇
Day 28:GenAI Evaluation:exit code 只發給重跑會給同一個答案的那一層
系列文
Backend 工程師的 Azure GenAI 實戰35
圖片
  熱門推薦
圖片
{{ item.channelVendor }} | {{ item.webinarstarted }} |
{{ formatDate(item.duration) }}
直播中

尚未有邦友留言

立即登入留言