先決定要站在哪裡看
goleveldb 是嵌在程式裡的 KV 資料庫,沒有網路邊界:沒有 slow query log、沒有封包可以抓。db.Put(key, val, nil) 回傳 nil,中間發生的事全在同一個 process 的堆疊裡。它的文件說,同時進來的寫入會被「合併」——一個人拿到寫入鎖,順手把排隊的人一起寫掉。
被觀測的是一支小程式:每秒 24 筆、每筆 1KB,前四分鐘一個 goroutine 寫,後四分鐘八個 goroutine 寫,總速率不變。八個 writer 每個每秒 3 筆,由各自的 ticker 推動。
點掛在寫入路徑的四個地方:Put 進門的那一行(呼叫 Put)、putRec 裡被合併的人拿到回覆就 return 的那一行(交給別人寫)、writeJournal 的第一行(寫 WAL)、以及 unlockWrite 的第一行(放鎖並回覆)。最後這個點抓它自己的參數 merged——拿鎖的人這一趟順手帶走了幾個別人的寫入。
我以為八個人同時到,會是一個人拿到鎖、把另外七個一起寫掉。那 merged 應該大多是 7 才對,不是嗎?
前四分鐘:一個寫入者
窗口是 2026-10-05 07:01:53Z 到 07:09:53Z。前四分鐘程式自己數到 5,755 筆,圖上 呼叫 Put 也是 5,755,寫 WAL 也是 5,755,merged 5,755 次全是 0。每一筆都自己拿鎖、自己寫 WAL,5,755 ÷ 5,755 = ×1.00。沒有人可以合併,到這裡沒有意外。
每一波,都是兩個人
後四分鐘程式數到 5,760 筆,圖上 呼叫 Put 也是 5,760;寫 WAL 掉到 1,440,交給別人寫 是 4,320。1,440 + 4,320 = 5,760:不是自己寫,就是被別人帶走。
merged 不再只有 0,但也幾乎沒有 7:
merged(順手帶走幾個) 次數
0 691
6 691
1 29
5 29
兩兩成對,而且 691 + 29 = 720——四分鐘、八個 writer 各每秒 3 筆,正好 720 波。我把 放鎖並回覆 的事件按時間排起來看:691 次 merged=6,每一次都緊跟在一次 merged=0 後面,相隔 6 到 37 毫秒;29 次 merged=5 也全部跟在 merged=1 後面,相隔 6 到 34 毫秒。波與波之間隔 273 毫秒以上。
面板 Logs 分頁上窗口最後幾秒長這樣(逐字,面板時間是 UTC+8):
[15:09:50.104] leveldb.(*DB).unlockWrite:141 merged=0 overflow=0
[15:09:50.134] leveldb.(*DB).unlockWrite:141 merged=6 overflow=0
[15:09:50.436] leveldb.(*DB).unlockWrite:141 merged=0 overflow=0
[15:09:50.465] leveldb.(*DB).unlockWrite:141 merged=6 overflow=0
所以每一波都是同一個形狀:第一個到的人拿到鎖,身後一個人都沒有,自己寫一次 WAL;它放開鎖時另外七個已經在等了,其中一個拿到鎖,把剩下六個一起寫掉。兩次 WAL,帶走六個。帳兜得起來:691×1 + 691×7 + 29×2 + 29×6 = 5,760,跟程式自己數的一筆不差;merged 加起來 4,320,也正好是另一個點 交給別人寫 數到的次數。
為什麼第一個人帶不走任何人,原始碼裡看得到:writeLocked 只會收「此刻已經在等的人」(select 帶 default),而且這一步在寫 WAL 之前。八個 ticker 幾乎同時響,第一個人搶到鎖的那一瞬間,其他人多半還在路上(這一步是推論,見誠實段)。
我以為合併就是一個人幫所有人寫。現在我知道,它幫的是「它拿到鎖那一刻已經在門口的人」——同時到的八個人,在它眼裡是兩批。
那合併的代價呢
合併不是免費的:被帶走的人要等拿鎖的那個人把整批寫完,才拿得到回覆。我原本打算直接讀主窗口裡 一次寫入 的計時,A 段 p50 3.690 毫秒、B 段 14.649 毫秒,慢了四倍。
但那個數字有一大半是我自己。我把同一支程式再跑一次,這次 leveldb 裡一個點都不掛,只留呼叫端的計時:
A 段(1 個寫入者) B 段(8 個寫入者)
p50 0.108 ms 0.158 ms
p95 0.156 ms 0.298 ms
p99 0.198 ms 0.394 ms
合併的代價是 p50 多 0.05 毫秒,不是好幾毫秒。另一輪只在 putRec 的合併分支上掛一個點——A 段一次都沒走到那一行——A 段 p50 也變成 1.429 毫秒:點一掛上去,整個函式就被換成一份副本,沒走到那一行也一樣慢。所以主窗口裡的毫秒數全篇不拿來比較。
那「每波兩次」會不會也是我造成的?持鎖時間被觀測拉長,門口自然站了更多人。我又換了兩種更輕的觀測方式重跑:只數、不收堆疊,B 段 WAL 寫入 1,438 次;鎖裡面一個點都不放、只數被帶走的人,5,760 − 4,321 = 1,439。最後一輪 leveldb 裡什麼都不掛,從行程外面用 strace 只看寫進日誌檔的 write:B 段最常見的還是「先一筆、再七筆」(572 次寫一筆、638 次寫七筆),只是同一波的兩次寫入從相隔 6–37 毫秒縮成大約 0.5 毫秒。形狀是 leveldb 的,間隔是我的。
誠實說
圖是從原始事件重建的。 觀測工具與面板畫的圖都多了一條不可能的邊:交給別人寫 → 寫 WAL。被合併的寫入在第 334 行就 return,永遠到不了 WAL;可是每一次 WAL 寫入的堆疊都經過 putRec(第 362 行),而工具只用函式名比對。原始事件的堆疊帶著行號,這張圖改用函式加行號重建,四條邊都有堆疊支撐,沒有多出任何一條。呼叫 Put → 寫 WAL 那條虛線中間隔的兩層是 putRec 和 writeLocked,我沒有掛點。
「其他人還在路上」是讀原始碼加時間戳推的,不是量到的。 我量到的是每波兩個拿鎖的人、相隔 6–37 毫秒;誰在什麼時候抵達門口,沒有點在看。
這個 720 波是我的 ticker 造出來的。 八個 writer 被同一個節拍推著,才會每 1/3 秒一起到。真實流量不會這麼整齊,merged 的分佈會更散——那 29 次 1+5 就是到達稍微錯開時的樣子。
觀測會改變它的節奏。 見上一節:主窗口裡同一波兩個拿鎖的人相隔 6–37 毫秒,沒有觀測點時大約 0.5 毫秒。「每波兩次」在四種觀測設定下都在,但 691/29 這組精確的分佈只量了有點的那一輪;沒有點的那一輪是從日誌檔的寫入大小反推的,跨 32KB 區塊被切開的寫入有一部分拼不回來,所以只引用形狀,不引用次數。
這一輪的「寫 WAL」沒有 fsync。 程式傳 nil 當寫入選項,sync 是 false,writeJournal 寫進日誌、交給作業系統就回來了。開了同步寫入,每一次 WAL 的成本會完全不同,這一輪沒有量。compaction 也不在觀測範圍內。
結果
我現在知道,「同時到」對一個寫入鎖來說不是一個時刻,是一個先後順序。合併省掉的 WAL 寫入是實在的——這一輪從 5,760 次降到 1,440 次——但它省多少,取決於拿到鎖的那一瞬間門口站了幾個人,而不是同一秒裡來了幾個人。
📊 本文的遠端觀測面板(實測數據,可線上檢視):https://codebull-service-b7lha2dtrq-uc.a.run.app/public/leveldb-write-merge-20261005/ Metrics 分頁裡 writeJournal 的累積線在 B 段開始那一刻折彎,Logs 分頁可以看到 merged=0、merged=6 一對一對出現。面板自己的 Behavior Graph 分頁上有那條多出來的 交給別人寫 → 寫 WAL,原因見上一節。(面板時間軸是本地時間 UTC+8,對應內文的 UTC 窗口。)
這一輪對被觀測程式做了什麼:main.go 加了一行 blank import 把 SDK 帶進二進位檔,並用 -gcflags="all=-N -l -dwarflocationlists=true" 編譯。業務邏輯一個字沒動,沒有加任何 log 或計數器(程式每個相位結束時印的筆數是 demo 本來就有的對帳來源)。五個觀測點全部是行程跑起來之後才掛上去的:leveldb.(*DB).Put:372、putRec:334、writeJournal:19、unlockWrite:141(抓 merged、overflow),以及 main.writeOne:54–58 的計時。延遲比較來自另一個行程的對照輪(07:16:41Z 起,只掛計時);另外兩輪對照只掛不收堆疊的計數點,一輪不掛任何點、在 strace --seccomp-bpf -e trace=write 底下跑。五輪的程式、參數與流量完全相同(-rate 24 -a 4m -b 4m -workers 8)。