先決定要站在哪裡看
(*processor).Execute 是 GORM 所有語句的收斂點——新增、查詢、更新、計數、刪除,最後都經過它。收斂點的好處是一個位置就涵蓋全部;壞處是它把來源抹平了,光看它你不知道是誰叫的。
所以這一輪的設計是:收斂點上掛滿三種訊號——計數(82 行)、計時(135 → 158 這個區間)、逐字內容(139 行抓 stmt.SQL.buf)——上游五個呼叫端各只掛一個計數。
想驗證的是一件很基本的事:三種訊號掛在同一個函式上,它們會不會對同一批事件說話。
三個數字
窗口結束後,同一個函式上的三個點是這樣的:
計數(Execute:82) 1,888
逐字內容(Execute:139) 1,888
計時(Execute:135 → 158) 1,652
計數與逐字內容一分不差:8 × 236 = 1,888——八種語句、每種 236 次,跟命中數對得起來。
計時少了 236。
我第一個念頭是掉事件。SDK 那一側的預設限流是每秒 1,000 筆,而這支 demo 每三秒才跑一輪——差得遠。而且真要掉,掉的應該是三個點一起掉,不會只掉計時那一個。
236 這個數字前面出現過
同一張圖上,查第一筆 → GORM 執行一次 那條邊的倍率是 ×1.5。472 次呼叫、708 次執行,多出來的正是 236。
而堆疊把它畫了出來。這一輪收斂點收到六條框鏈,五條長這樣:
goexit · main · main · Create · Execute 472
goexit · main · main · First · Execute 472
goexit · main · main · Update · Execute 236
goexit · main · main · Count · Execute 236
goexit · main · main · Delete · Execute 236
第六條長這樣:
goexit · main · main · First · Execute · Preload · preloadEntryPoint · preload · Find · Execute 236
Execute 在同一條鏈上出現了兩次。 一次 Preload 的展開,是在外層那次 Execute 還沒返回的時候發生的——內層那次被包在外層的區間裡面。
計時點量的是一個區間關閉了幾次。而那 236 次巢狀執行,一次都沒有讓區間關起來:1888 − 1652 = 236,跟第六條鏈的次數一模一樣。
計數數的是「進去幾次」,計時數的是「關起來幾次」。平常這兩件事一樣,遇到自己呼叫自己就不一樣了。
那個 p99 是八種語句疊在一起的樣子
計時那一側給的是這個:
p50 5.232ms
p95 18.406ms
p99 67.321ms
max 80.272ms
p99 是 p50 的十三倍。而這個分佈不分語句種類——INSERT、count(*)、Preload 的子查詢、那句軟刪除的 UPDATE,全部疊在同一條線上。
逐字內容那個點把問題回答掉一半:慢的候選有八個,形狀都在。但要知道哪一種慢,得往上游各掛一個計時點——這正是收斂點的代價。一個位置涵蓋全部,代價是它對「全部」只有一個答案。
誠實說
為什麼巢狀那一次沒有讓區間關起來,我沒有再往下量。 我量到的是差額,以及差額正好等於第六條鏈的次數。機制我有一個猜測,但這一輪沒有掛點去驗它,所以它不進文章。
「不是掉事件」這句話我證不到底。 這支 demo 建在一個回報不了掉事件的 SDK 版本上(證據包自己會說:sampling.supported: false)。我能證明的是「差額正好等於巢狀次數」這個巧合太整齊了,不是能證明「絕對一筆都沒掉」。
這五格堆疊短得不像真的服務。 呼叫端就寫在倒數第二格,因為這支 demo 的 CRUD 直接寫在 main 裡。換一支有 handler、有 service 層的服務,同一個位置會拿到長得多的鏈——短鏈是這支 demo 的性質,不是這個方法的性質。
收斂點以下是空的。 GORM 執行一次 → 送出 SQL 那條邊零層未觀測,因為兩個點在同一個函式裡。callback 鏈、連線池、驅動,這張圖上完全沒有。
結果
三種訊號掛在同一行上,最有用的一刻不是它們互相印證的時候,是它們對不起來的時候。
計數與計時差了 236,而那 236 不是誤差、不是取樣、也不是我掛錯位置——它是這個函式自己呼叫自己留下的痕跡,而唯一看得見它的地方是堆疊。三個點各自都給了一個對的數字;是它們之間的差,指出了那個沒有人寫下來的事實。
這一輪對被觀測服務做了什麼:main.go 加了一行 blank import 把 SDK 帶進二進位檔,並用 -gcflags="all=-dwarflocationlists=true -N -l" 編譯。業務邏輯一個字沒動,沒有加任何 log 或計數器。八個觀測點掛在五個函式上,全部是行程跑起來之後才掛上去的。