為什麼掛在這裡

etcd 的寫入不是一條直線走完的:gRPC 收下請求、轉成 raft 提案、落碟、套用成狀態——這四段各自可能在不同的 goroutine 上。原始碼讀得出來有 go func(),但讀不出來「一個 Put 對應幾次落碟」。

所以六個點沿著整條寫入路徑鋪開:kvServer.Put(收下 Put)、EtcdServer.Put(伺服器 API)、processInternalRaftRequestOnce(送進 raft 提案)、wal.Save(寫入 WAL,計數與計時各一個)、applyEntryNormal(套用單筆)。

流量分成五個相位:一分鐘完全沒有客戶端流量、每秒一寫、單客戶端全速、兩客戶端全速、只送讀取。第一個和最後一個相位是對照組——它們告訴你,哪些數字根本不是你的請求造成的。

請求那一側:五個來源,同一個數字

收下 Put、伺服器 API、送進 raft 提案、套用單筆 四個點,全部 9,472,一個不多一個不少。而 etcd 自己的 /metrics 說 grpc_put_ok 9,472、mvcc_puts 9,472、proposals_committed 9,472;我的客戶端腳本也數到 9,472。

五個獨立來源,沒有一個需要相信另一個。 這件事本身不有趣,但它是後面所有數字的地基:當某一個數字對不上時,你才知道那是真的對不上,不是量錯了。

「WAL 寫了幾次」有三個答案,而且都對

落碟那一側就不一樣了。同一段 WAL 工作,手上有三個數字:

wal.Save 這個函式被進入幾次(探針,959 行)        22,555
進去之後真的走到底幾次(計時區間,960 行起)        17,404
etcd 自己數的 fsync 次數(etcd_disk_wal_fsync…)    9,421

三個都是對的,因為它們數的是三件不同的事。而分相位看,它們在哪裡分岔就看得見了:

相位              客戶端寫入   Save 進入   每次寫入幾次 Save   每次寫入幾次 fsync
每秒一寫                 87        174            2.000              1.00
單客戶端全速          3,867      7,734            2.000              1.00
兩客戶端全速          5,518      9,496            1.721             0.991

2.000 是結構,1.721 是流量。 閒的時候,一次寫入固定進兩次 Save——那是 raft 的 Ready 迴圈的形狀,跟負載無關,兩位小數都不差。多個客戶端同時打進來之後才掉下來:多個提案被合進同一個 Ready 回合,一起寫下去。

批次化不是「忙的時候才啟動的最佳化」,是「忙的時候才有東西可以合併」。 這句話不是從原始碼推出來的,是三個相位的比值自己排出來的。

而且它重現了。同一天稍早用四個客戶端跑過一輪:2.000 / 2.000 / 1.691。前兩個相位一模一樣,第三個隨並行度移動。

然後是最後一個相位

最後一分鐘只送讀取,不寫。照理說寫入路徑上的點應該全部靜止。

收下 Put 確實停在 9,472 沒有再動,套用單筆 也是。但 wal.Save 從 17,404 跳到 22,555——多了 5,151 次。

而那個相位客戶端送出的讀取,正好是 5,151 次。

一次讀,就是一次 wal.Save 呼叫。 而且那 5,151 次一次都沒讓計時區間關起來——960 行的計數停在 17,404 不動。回原始碼看,Save 的第一件事就是:

if raft.IsEmptyHardState(st) && len(ents) == 0 { return nil }

線性讀走 raft 的 ReadIndex,產生一個沒有 entry、HardState 也沒變的 Ready 回合,Save 進去、判斷、返回——沒有碰磁碟。

這件事在稍早那一輪也一樣:讀取 4,480 次,Save 多 4,480 次。兩輪都分毫不差。

結果

如果只看「wal.Save 被呼叫 22,555 次」這一個數字,你會以為這五分半裡有兩萬多次落碟。實際落碟是 9,421 次,而其中有 5,151 次呼叫來自從來不寫入的請求。

一個計數點告訴你某段程式跑了幾次,這是它唯一保證的事。它跑了幾次,和它做了幾次事,是兩個問題——而分辨這兩者的方法不是讀原始碼,是讓流量停下來,看哪些數字跟著停。

📊 本文的遠端觀測面板(實測數據,可線上檢視):https://codebull-service-b7lha2dtrq-uc.a.run.app/public/etcd-write-path-20260905/ 面板收的是這次 run 的完整上傳。Metrics 分頁看得到五個相位的斜率轉折;Behavior Graph 分頁是文章開頭那張圖的互動版,把時間軸拖到最後一分鐘,寫入 WAL 還在動而 收下 Put 已經停了。(面板時間軸是本地時間 UTC+8,對應內文的 UTC 時間。)

這一輪對被觀測服務做了什麼:server/main.go 加了一行 blank import 把 SDK 帶進二進位檔,並用 -gcflags="all=-dwarflocationlists=true -N -l" 編譯。業務邏輯一個字沒動,沒有加任何 log 或計數器。六個觀測點全部是 etcd 跑起來之後才掛上去的。