先決定要站在哪裡看

被觀測的是一支小程式:同一個行程裡起一個 gRPC server(grpc-go 內建的 health 服務)和一個 client,所有呼叫都走同一條 HTTP/2 連線。前段一個 goroutine 每秒呼叫 24 次,後段換成八個 goroutine 各每秒 3 次——總速率不變,只改同時在路上的呼叫有幾個。

我寫的只有一行 client.Check(ctx, req)。站在這一行,看得到的是「它回來了」;站在網卡,看得到的是位元組,看不出是誰送的。所以點掛在中間幾個地方:呼叫端那一行(一次呼叫)、server 的 handler(處理 RPC)、grpc-go 收到 DATA 之後決定送 PING 的那一行——client 和 server 各一個(client 送出 BDP ping、server 送出 BDP ping)——以及最後真正把位元組交給 socket 的那一行(寫進 socket),抓它這次寫了幾個 bytes。

我以為一次 unary RPC 在線上就是一個請求、一個回應。那為什麼 socket 被寫的次數,會是呼叫次數的五倍?

前段:一個 caller

窗口是 2026-10-05 13:50:45Z 到 13:56:15Z。前段程式自己數到 3,452 次呼叫,處理 RPC 也是 3,452。到這裡帳是平的。

不平的是另外三個數字:server 送出 BDP ping 3,452 次、client 送出 BDP ping 3,451 次、寫進 socket 18,245 次。每一次呼叫,兩端都各送了一次 PING;socket 每次呼叫被寫了 5.3 次。

線上真正的帳

觀測點只告訴我「送了」,沒告訴我線上長什麼樣。所以我把同一支程式再跑一次,這次一個點都不掛,從行程外面用 strace 只攔 write,把每一次寫進 socket 的位元組拆成 HTTP/2 frame。前段 2,880 次呼叫,兩端寫出去的 frame 是這樣(逐字從解碼結果整理):

                        client          server
HEADERS                 2,880           2,879
DATA                    2,880           2,879
HEADERS(trailers)         —           2,879
WINDOW_UPDATE           2,879           2,879
PING                    2,879           2,879
PING ACK                2,879           2,879

一次呼叫,我寫的那部分是五個 frame:client 的 HEADERS、DATA,server 的 HEADERS、DATA、trailers。另外六個不在我的程式裡。 其中一次 server 的寫入,逐字是這 30 個位元組:

00 00 04 08 00 00 00 00 00 | 00 00 00 0b                 ← WINDOW_UPDATE,增量 11
00 00 08 06 00 00 00 00 00 | 02 04 10 10 09 0e 07 07     ← PING

增量 11,正好是那一次請求 DATA 的大小——觀測點抓到的 size=11 也是這個數。PING 的八個位元組是 grpc-go 寫死的 bdpPing,原始碼旁邊還留了一句註解:「Easter-egg: what does the ping message say?」整段 strace 裡這個負載出現 6,502 次,對方回的 ACK 也是 6,502 次。

這是 grpc-go 的 BDP(頻寬延遲乘積)估算器。bdp_estimator.go 的規則很簡單:收到 DATA 時,如果手上沒有一個等待回應的 PING,就開始一輪新的估算——先送一個 WINDOW_UPDATE,再送 PING,等 ACK 回來算一次往返時間。估算值要到 16MB 才會停;一個回應只有幾個位元組的服務,永遠到不了。

八個 caller,同樣的速率

後段程式數到 3,960 次呼叫。server 送出 BDP ping 掉到 495 次,client 送出 BDP ping 496 次——3,960 ÷ 8 = 495。寫進 socket 只剩 3,947 次,每次呼叫不到一次。

八個 caller 被同一個節拍推著,每 1/3 秒一起到。第一個請求的 DATA 開啟一輪估算、送出 PING;另外七個在 ACK 回來之前就到了,只是被加進同一輪的樣本裡(這一步是從原始碼和計數推的,誰先到、ACK 何時回,沒有點在看)。PING 是「一輪一次」,不是「一次呼叫一次」——一個 caller 時,每一輪剛好只有一次呼叫。

不掛點的那一輪也一樣:後段 2,880 次呼叫,client 送 381 次 PING、server 送 361 次,2,880 ÷ 8 = 360 波;socket 兩端合計寫 2,551 次,前段是 16,688 次——同樣 2,880 次呼叫,差 6.5 倍。回應也開始擠進同一次寫入——server 有 28 次寫入一次裝了三個呼叫的 HEADERS、DATA、trailers。

我以為一次 gRPC 呼叫的線上成本是固定的。現在我知道,它取決於同一條連線上同時有幾個呼叫:同樣每秒 24 次,一個人叫的時候,控制 frame 比資料 frame 還多。

誠實說

觀測會改變它的節奏,所以兩組數字分開用。 前段只有一個 caller 時,觀測點讓每次呼叫變慢,程式只跑到每秒 21 次(3,452 次,目標是 3,960);不掛點時跑滿 2,880 次 / 2 分鐘。帳的形狀——前段一次呼叫一輪 PING、後段一波一輪——兩組完全一樣;frame 的種類與數量只引用不掛點的那一輪。

延遲只引用對照組。 主窗口量到的呼叫延遲 p50,前段 25.614 毫秒、後段 87.829 毫秒,幾乎全是觀測點自己的成本。另一輪只在呼叫端掛計時:

            前段(1 個 caller)   後段(8 個 caller)
p50         0.427 ms              0.537 ms
p95         1.123 ms              1.481 ms
p99         1.231 ms              1.969 ms

這一輪沒有把「有 PING」和「沒有 PING」放在一起比,所以多出來的那一輪往返到底讓一次呼叫慢了多少,我沒量。

圖上是五座島。 發出呼叫、處理呼叫、收到 DATA 決定送 PING、寫進 socket,在 grpc-go 裡各是不同的 goroutine——caller 自己的、server 為每個串流開的、兩端各一個讀 socket 的、兩端各一個 loopyWriter。堆疊不會跨過 go func(),所以它們之間沒有邊,接起來的是計數:3,452 = 3,452 = 3,452。寫進 socket 這一格兩端都有,我從堆疊分出來:前段 client 9,143 次、server 9,102 次。

能不能關掉,是讀原始碼來的。 grpc-go 只要設定了任何一種初始 window 大小(client 的 WithInitialWindowSize / WithInitialConnWindowSize,server 的 InitialWindowSize / InitialConnWindowSize),就會把 StaticWindowSize 設成 true,不建立 BDP 估算器。這一輪沒有實際關掉它重跑。

這是 loopback。 往返時間不到一毫秒,ACK 總是在下一次呼叫之前回來,所以前段才會每次呼叫都開一輪新的估算。真實網路的往返更長,一輪會涵蓋更多呼叫,比例會不一樣。

結果

我現在知道,「一次 RPC」在線上不是一個固定的東西。同樣每秒 24 次,一個 caller 讓兩端每次呼叫都多寫六個控制 frame、socket 被寫將近六次;八個 caller 共用同一條連線時,八次呼叫才多一輪,socket 一次呼叫還寫不到一次。成本跟著的不是呼叫的數量,是它們有沒有擠在一起。

📊 本文的遠端觀測面板(實測數據,可線上檢視):https://codebull-service-b7lha2dtrq-uc.a.run.app/public/grpc-frames-20261005/ Metrics 分頁裡呼叫次數的累積線在後段開始那一刻變陡(前段被觀測拖到每秒 21 次);Logs 分頁可以看到 bytes=17(PING / ACK)、bytes=13(WINDOW_UPDATE)與 size=11、size=7(觸發 PING 的請求與回應 DATA)。(面板時間軸是本地時間 UTC+8,對應內文的 UTC 窗口。)

這一輪對被觀測程式做了什麼:main.go 加了一行 blank import 把 SDK 帶進二進位檔,並用 -gcflags="all=-N -l -dwarflocationlists=true" 編譯。業務邏輯一個字沒動,沒有加任何 log 或計數器(程式每個相位結束時印的呼叫數是 demo 本來就有的對帳來源)。六個觀測點全部是行程跑起來之後才掛上去的:main.callOne:56(計數)與 main.callOne:55–62(計時)、health.(*Server).Check:62、transport.(*http2Server).handleData:786、transport.(*http2Client).handleData:1215(抓 size)、transport.(*bufWriter).flushKeepBuffer:369(抓 w.offset)。延遲來自另一個行程的對照輪(只掛計時);frame 帳來自另一輪不掛任何點、在 strace --seccomp-bpf -e trace=write 底下跑的行程,兩輪各段 2 分鐘,程式與參數相同。窗口最後程式依設計自行結束,所以觀測工具會回報事件流已中斷;最後一筆事件在 13:56:15Z。